Take the 2-minute tour ×
Unix & Linux Stack Exchange is a question and answer site for users of Linux, FreeBSD and other Un*x-like operating systems.. It's 100% free, no registration required.

Log message from ARM Cortex A9 based board. Running linux.

[Sat Apr 12 19:33:50.207 2014] 
[Sat Apr 12 19:33:50.207 2014] 
[Sat Apr 12 19:33:50.207 2014] U-Boot 2013.07 (Apr 09 2014 - 12:31:52)
[Sat Apr 12 19:33:50.207 2014] 
[Sat Apr 12 19:33:50.207 2014] Memory: ECC disabled
[Sat Apr 12 19:33:50.207 2014] DRAM:  1 GiB
[Sat Apr 12 19:33:50.224 2014] MMC:   zynq_sdhci: 0
[Sat Apr 12 19:33:50.224 2014] SF: Detected N25Q128A with page size 64 KiB, total 16 MiB
[Sat Apr 12 19:33:50.245 2014] In:    serial
[Sat Apr 12 19:33:50.245 2014] Out:   serial
[Sat Apr 12 19:33:50.245 2014] Err:   serial
[Sat Apr 12 19:33:50.245 2014] 
[Sat Apr 12 19:33:50.245 2014] boot Petalinux
[Sat Apr 12 19:33:50.303 2014] Device: zynq_sdhci
[Sat Apr 12 19:33:50.303 2014] Manufacturer ID: 2
[Sat Apr 12 19:33:50.303 2014] OEM: 544d
[Sat Apr 12 19:33:50.303 2014] Name: SA04G 
[Sat Apr 12 19:33:50.303 2014] Tran Speed: 50000000
[Sat Apr 12 19:33:50.303 2014] Rd Block Len: 512
[Sat Apr 12 19:33:50.303 2014] SD version 3.0
[Sat Apr 12 19:33:50.303 2014] High Capacity: Yes
[Sat Apr 12 19:33:50.303 2014] Capacity: 3.7 GiB
[Sat Apr 12 19:33:50.303 2014] Bus Width: 4-bit
[Sat Apr 12 19:33:50.303 2014] reading image.ub
[Sat Apr 12 19:33:50.520 2014] 1395836 bytes read in 166 ms (8 MiB/s)
[Sat Apr 12 19:33:50.520 2014] ## Loading kernel from FIT Image at 01000000 ...
[Sat Apr 12 19:33:50.520 2014]    Using 'conf@1' configuration
[Sat Apr 12 19:33:50.520 2014]    Trying 'kernel@1' kernel subimage
[Sat Apr 12 19:33:50.520 2014]      Description:  PetaLinux Kernel
[Sat Apr 12 19:33:50.520 2014]      Type:         Kernel Image
[Sat Apr 12 19:33:50.520 2014]      Compression:  gzip compressed
[Sat Apr 12 19:33:50.520 2014]      Data Start:   0x010000f0
[Sat Apr 12 19:33:50.520 2014]      Data Size:    1383397 Bytes = 1.3 MiB
[Sat Apr 12 19:33:50.520 2014]      Architecture: ARM
[Sat Apr 12 19:33:50.520 2014]      OS:           Linux
[Sat Apr 12 19:33:50.520 2014]      Load Address: 0x00008000
[Sat Apr 12 19:33:50.520 2014]      Entry Point:  0x00008000
[Sat Apr 12 19:33:50.520 2014]      Hash algo:    crc32
[Sat Apr 12 19:33:50.520 2014]      Hash value:   c02e0858
[Sat Apr 12 19:33:50.520 2014]    Verifying Hash Integrity ... crc32+ OK
[Sat Apr 12 19:33:50.579 2014] ## Loading fdt from FIT Image at 01000000 ...
[Sat Apr 12 19:33:50.579 2014]    Using 'conf@1' configuration
[Sat Apr 12 19:33:50.579 2014]    Trying 'fdt@1' fdt subimage
[Sat Apr 12 19:33:50.579 2014]      Description:  Flattened Device Tree blob
[Sat Apr 12 19:33:50.579 2014]      Type:         Flat Device Tree
[Sat Apr 12 19:33:50.579 2014]      Compression:  uncompressed
[Sat Apr 12 19:33:50.579 2014]      Data Start:   0x01151dbc
[Sat Apr 12 19:33:50.579 2014]      Data Size:    11101 Bytes = 10.8 KiB
[Sat Apr 12 19:33:50.579 2014]      Architecture: ARM
[Sat Apr 12 19:33:50.579 2014]      Hash algo:    crc32
[Sat Apr 12 19:33:50.579 2014]      Hash value:   5e16707d
[Sat Apr 12 19:33:50.579 2014]      Hash algo:    sha1
[Sat Apr 12 19:33:50.579 2014]      Hash value:   0af07559d7f0578246fb91abe17c7987dcee216a
[Sat Apr 12 19:33:50.579 2014]    Verifying Hash Integrity ... crc32+ sha1+ OK
[Sat Apr 12 19:33:50.596 2014]    Booting using the fdt blob at 0x1151dbc
[Sat Apr 12 19:33:50.596 2014]    Uncompressing Kernel Image ... OK
[Sat Apr 12 19:33:50.692 2014]    Loading Device Tree to 07ffa000, end 07fffb5c ... OK
[Sat Apr 12 19:33:50.692 2014] 
[Sat Apr 12 19:33:50.692 2014] Starting kernel ...
[Sat Apr 12 19:33:50.692 2014] 
[Sat Apr 12 19:33:51.298 2014] Booting Linux on physical CPU 0x0
[Sat Apr 12 19:33:51.298 2014] Linux version 3.8.11 (root@xilinx) (gcc version 4.7.3 (Sourcery CodeBench Lite 2013.05-40) ) #2 SMP PREEMPT Sat Apr 12 19:11:59 IST 2014
[Sat Apr 12 19:33:51.298 2014] CPU: ARMv7 Processor [413fc090] revision 0 (ARMv7), cr=18c53c7d
[Sat Apr 12 19:33:51.298 2014] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[Sat Apr 12 19:33:51.298 2014] Machine: Xilinx Zynq Platform, model: Xilinx-ZC702-14.7
[Sat Apr 12 19:33:51.298 2014] Memory policy: ECC disabled, Data cache writealloc
[Sat Apr 12 19:33:51.298 2014] PERCPU: Embedded 7 pages/cpu @c0af2000 s5568 r8192 d14912 u32768
[Sat Apr 12 19:33:51.298 2014] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 260096
[Sat Apr 12 19:33:51.342 2014] Kernel command line: console=ttyPS0,115200
[Sat Apr 12 19:33:51.342 2014] PID hash table entries: 4096 (order: 2, 16384 bytes)
[Sat Apr 12 19:33:51.342 2014] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[Sat Apr 12 19:33:51.342 2014] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[Sat Apr 12 19:33:51.343 2014] __ex_table already sorted, skipping sort
[Sat Apr 12 19:33:51.343 2014] Memory: 1024MB = 1024MB total
[Sat Apr 12 19:33:51.343 2014] Memory: 1036484k/1036484k available, 12092k reserved, 270336K highmem
[Sat Apr 12 19:33:51.343 2014] Virtual kernel memory layout:
[Sat Apr 12 19:33:51.343 2014]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[Sat Apr 12 19:33:51.343 2014]     fixmap  : 0xfff00000 - 0xfffe0000   ( 896 kB)
[Sat Apr 12 19:33:51.387 2014]     vmalloc : 0xf0000000 - 0xff000000   ( 240 MB)
[Sat Apr 12 19:33:51.387 2014]     lowmem  : 0xc0000000 - 0xef800000   ( 760 MB)
[Sat Apr 12 19:33:51.387 2014]     pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
[Sat Apr 12 19:33:51.387 2014]     modules : 0xbf000000 - 0xbfe00000   (  14 MB)
[Sat Apr 12 19:33:51.387 2014]       .text : 0xc0008000 - 0xc0208d94   (2052 kB)
[Sat Apr 12 19:33:51.387 2014]       .init : 0xc0209000 - 0xc02b55c0   ( 690 kB)
[Sat Apr 12 19:33:51.387 2014]       .data : 0xc02b6000 - 0xc02d3ea0   ( 120 kB)
[Sat Apr 12 19:33:51.387 2014]        .bss : 0xc02d3ea0 - 0xc02e6898   (  75 kB)
[Sat Apr 12 19:33:51.387 2014] Preemptible hierarchical RCU implementation.
[Sat Apr 12 19:33:51.387 2014]  RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2.
[Sat Apr 12 19:33:51.435 2014] NR_IRQS:16 nr_irqs:16 16
[Sat Apr 12 19:33:51.435 2014] MIO pin 47 not assigned(00001220)
[Sat Apr 12 19:33:51.435 2014] xslcr mapped to f0002000
[Sat Apr 12 19:33:51.435 2014] Zynq clock init
[Sat Apr 12 19:33:51.435 2014] sched_clock: 16 bits at 54kHz, resolution 18432ns, wraps every 1207ms
[Sat Apr 12 19:33:51.435 2014] ps7-ttc #0 at f0004000, irq=43
[Sat Apr 12 19:33:51.435 2014] Console: colour dummy device 80x30
[Sat Apr 12 19:33:51.435 2014] Calibrating delay loop... 1332.01 BogoMIPS (lpj=6660096)
[Sat Apr 12 19:33:51.435 2014] pid_max: default: 4096 minimum: 301
[Sat Apr 12 19:33:51.435 2014] Mount-cache hash table entries: 512
[Sat Apr 12 19:33:51.435 2014] CPU: Testing write buffer coherency: ok
[Sat Apr 12 19:33:51.435 2014] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[Sat Apr 12 19:33:51.435 2014] Setting up static identity map for 0x1b6990 - 0x1b69c4
[Sat Apr 12 19:33:51.476 2014] L310 cache controller enabled
[Sat Apr 12 19:33:51.476 2014] l2x0: 8 ways, CACHE_ID 0x000000c0, AUX_CTRL 0x72360000, Cache size: 524288 B
[Sat Apr 12 19:33:51.476 2014] CPU1: Booted secondary processor
[Sat Apr 12 19:33:51.476 2014] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[Sat Apr 12 19:33:51.476 2014] Brought up 2 CPUs
[Sat Apr 12 19:33:51.476 2014] SMP: Total of 2 processors activated (2664.03 BogoMIPS).
[Sat Apr 12 19:33:51.476 2014] devtmpfs: initialized
[Sat Apr 12 19:33:51.476 2014] NET: Registered protocol family 16
[Sat Apr 12 19:33:51.476 2014] I reach build/linux/kernel/xlnx-3.8/source/net/socket.c:
[Sat Apr 12 19:33:51.476 2014] DMA: preallocated 256 KiB pool for atomic coherent allocations
[Sat Apr 12 19:33:51.476 2014] xgpiops e000a000.ps7-gpio: gpio at 0xe000a000 mapped to 0xf004e000
[Sat Apr 12 19:33:51.518 2014] GPIO IRQ not connected
[Sat Apr 12 19:33:51.518 2014] XGpio: /amba@0/gpio@41220000: registered, base is 255
[Sat Apr 12 19:33:51.518 2014] GPIO IRQ not connected
[Sat Apr 12 19:33:51.518 2014] XGpio: /amba@0/gpio@41200000: registered, base is 251
[Sat Apr 12 19:33:51.518 2014] usbcore: registered new interface driver usbfs
[Sat Apr 12 19:33:51.518 2014] usbcore: registered new interface driver hub
[Sat Apr 12 19:33:51.518 2014] usbcore: registered new device driver usb
[Sat Apr 12 19:33:51.518 2014] Switching to clocksource xttcps_clocksource
[Sat Apr 12 19:33:51.518 2014] e0001000.serial: ttyPS0 at MMIO 0xe0001000 (irq = 82) is a xuartps
[Sat Apr 12 19:33:51.518 2014] console [ttyPS0] enabled
[Sat Apr 12 19:33:51.534 2014] xdevcfg f8007000.ps7-dev-cfg: ioremap f8007000 to f0052000 with size 100
[Sat Apr 12 19:33:51.548 2014] xqspips e000d000.ps7-qspi: master is unqueued, this is deprecated
[Sat Apr 12 19:33:51.566 2014] m25p80 spi32766.0: found n25q128, expected n25q128
[Sat Apr 12 19:33:51.566 2014] m25p80 spi32766.0: n25q128 (16384 Kbytes)
[Sat Apr 12 19:33:51.566 2014] 4 ofpart partitions found on MTD device spi32766.0
[Sat Apr 12 19:33:51.566 2014] Creating 4 MTD partitions on "spi32766.0":
[Sat Apr 12 19:33:51.566 2014] 0x000000000000-0x000000500000 : "boot"
[Sat Apr 12 19:33:51.566 2014] 0x000000500000-0x000000520000 : "bootenv"
[Sat Apr 12 19:33:51.580 2014] 0x000000520000-0x0000006416c0 : "image"
[Sat Apr 12 19:33:51.580 2014] mtd: partition "image" doesn't end on an erase block -- force read-only
[Sat Apr 12 19:33:51.580 2014] 0x0000006416c0-0x000000a416c0 : "jffs2"
[Sat Apr 12 19:33:51.580 2014] mtd: partition "jffs2" doesn't start on an erase block boundary -- force read-only
[Sat Apr 12 19:33:51.598 2014] xqspips e000d000.ps7-qspi: at 0xE000D000 mapped to 0xF0054000, irq=51
[Sat Apr 12 19:33:51.598 2014] libphy: XEMACPS mii bus: probed
[Sat Apr 12 19:33:51.613 2014] xemacps e000b000.ps7-ethernet: invalid address, use assigned
[Sat Apr 12 19:33:51.613 2014] xemacps e000b000.ps7-ethernet: MAC updated ce:5e:a9:56:ee:44
[Sat Apr 12 19:33:51.613 2014] xemacps e000b000.ps7-ethernet: pdev->id -1, baseaddr 0xe000b000, irq 54
[Sat Apr 12 19:33:51.630 2014] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[Sat Apr 12 19:33:51.630 2014] ULPI transceiver vendor/product ID 0x0424/0x0007
[Sat Apr 12 19:33:51.630 2014] Found SMSC USB3320 ULPI transceiver.
[Sat Apr 12 19:33:51.630 2014] ULPI integrity check: passed.
[Sat Apr 12 19:33:51.646 2014] xusbps-ehci xusbps-ehci.0: Xilinx PS USB EHCI Host Controller
[Sat Apr 12 19:33:51.646 2014] xusbps-ehci xusbps-ehci.0: new USB bus registered, assigned bus number 1
[Sat Apr 12 19:33:51.660 2014] xusbps-ehci xusbps-ehci.0: irq 53, io mem 0x00000000
[Sat Apr 12 19:33:51.677 2014] xusbps-ehci xusbps-ehci.0: USB 2.0 started, EHCI 1.00
[Sat Apr 12 19:33:51.696 2014] hub 1-0:1.0: USB hub found
[Sat Apr 12 19:33:51.696 2014] hub 1-0:1.0: 1 port detected
[Sat Apr 12 19:33:51.696 2014] xi2cps e0004000.ps7-i2c: 400 kHz mmio e0004000 irq 57
[Sat Apr 12 19:33:51.696 2014] xadcps f8007100.ps7-xadc: enabled:   yes reference:  external
[Sat Apr 12 19:33:51.716 2014] xwdtps f8005000.ps7-wdt: Xilinx Watchdog Timer at f0074000 with timeout 10s
[Sat Apr 12 19:33:51.716 2014] sdhci: Secure Digital Host Controller Interface driver
[Sat Apr 12 19:33:51.716 2014] sdhci: Copyright(c) Pierre Ossman
[Sat Apr 12 19:33:51.716 2014] sdhci-pltfm: SDHCI platform and OF driver helper
[Sat Apr 12 19:33:51.736 2014] usbcore: registered new interface driver usbhid
[Sat Apr 12 19:33:51.736 2014] usbhid: USB HID core driver
[Sat Apr 12 19:33:51.736 2014]  I am at build/linux/kernel/xlnx-3.8/source/drivers/hid/usbhid/hid-core.c
[Sat Apr 12 19:33:51.736 2014] VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 4
[Sat Apr 12 19:33:51.746 2014] Freeing init memory: 688K
[Sat Apr 12 19:33:51.759 2014] 
[Sat Apr 12 19:33:51.759 2014] Hello world from myinit.c!

Problem is here:

[Sat Apr 12 19:33:50.692 2014] Starting kernel ...
[Sat Apr 12 19:33:50.692 2014] 
[Sat Apr 12 19:33:51.298 2014] Booting Linux on physical CPU 0x0

Booting is starting after close to 0.6 seconds. How can I make it faster? I want that the booting should start after 0.1 second of the Starting kernel ...

What should be my focus for improving this ?

Update

I am back with the same issue again.

I would like to know what functions are called after " Starting kernel...". I have put several printf and printk statements in following files, but did not get any thing useful as of now:

1- bootm.c

2- setup.c

3- main.c

Still I am having these messages:

    [Sat Apr 12 19:33:50.692 2014] Starting kernel ...
    [Sat Apr 12 19:33:50.692 2014]   
    [Sat Apr 12 19:33:51.298 2014] Booting Linux on physical CPU 0x0 

I am not able to find the breakup of the time between these two messages. Even if I could know software cointrol between these two lines, it will help me in reaching the root cause.

In particular I want to know what line of code(s) are being executed between these two messages.

I know some initilization might be happening between these lines, but where is the code for the same?

The problem is there is no main() function so I am unable to find the sequnce of the funnction calls in the above file.

share|improve this question
    
Your flash device is not formatted correctly. You need to align the virtual partitions and the mtd erase blocks. Working around that will slow everything down. Pad the filesystem with zeros if necessary. mtd: partition "image" doesn't end on an erase block -- force read-only –  mikeserv Jun 24 at 0:50
1  
You may want to try investigating the Linux Kernel instructions using QEMU. Here is how you can set it up on Ubuntu/Debian machine. Also note how to debug using GDB. hellion.org.uk/blog/posts/grub-on-uboot-on-qemu Specifically, you nave to setup QEMU with U-Boot, and your version of Linux Kernel running on emulated Cortex-A9 processor (qemu-system-arm -M vexpress-a9). –  tuxdna Jun 26 at 15:47
add comment

3 Answers 3

During these 0.6 seconds, stuff happens. All the messages up to “Starting kernel” are printed by U-Boot All the messages from “Booting Linux” onwards are printed by the Linux kernel. The kernel needs to initialize its own data structures and a number of peripherals (enough to be able to print a trace). This takes time.

You can see what the kernel is doing by reading the main. The “Booting Linux” message comes from the call to smp_setup_processor_id.

You can trace the code in a debugger to see where it's spending time. It's possible that there is some unnecessary hardware that's being initialized, for example. But it's unlikely that there's anything to gain at this point.

share|improve this answer
    
Kindly explain Why did you "it's unlikely that there's anything to gain at this point." ? –  user2799508 Apr 23 at 13:22
add comment

I would guess that this has much to do with the way bootloader and kernel are glued. Section 5.1.3 (Bootstrap Loader) in Hallinan's Embedded Linux Primer has the following to say on this :

Some bootstrap loaders perform checksum verification of the kernel image, and most decompress and relocate the kernel image. The difference between a bootloader and a bootstrap loader in this context is simple: The bootloader controls the board upon power-up and does not rely on the Linux kernel in any way. In contrast, the bootstrap loader’s primary purpose is to act as the glue between a bare metal bootloader and the Linux kernel. It is the bootstrap loader’s responsibility to provide a proper context for the kernel to run in, as well as perform the necessary steps to decompress and relocate the kernel binary image

If you see the image with it, you will observe that before kernel's actual execution, head.s and head-<arch>.s assembly routines are executed. Some other tasks like kernel decompression to memory has to be done as kernel is not in the kernel proper form (vmlinux) but compressed and glued to these routines as a piggy.gz image.

Though this is arch specific but I think it may explain the extra time between the switch from Uboot to kernel.

share|improve this answer
add comment

You start with the function do_bootm_linux in bootm.c and work your way to the code. You could also try adding the parameter debug or loglevel=7 when starting the kernel to get more information.

share|improve this answer
    
your first line helped me in tracing to bottle neck. Thanks –  user2799508 Jun 25 at 12:43
add comment

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.