¿Por qué el arranque del kernel comienza demasiado tarde?

Mensaje de logging de la placa ARM Cortex A9. Ejecutando 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: Registenetworking 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: registenetworking, 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: registenetworking, base is 251 [Sat Apr 12 19:33:51.518 2014] usbcore: registenetworking new interface driver usbfs [Sat Apr 12 19:33:51.518 2014] usbcore: registenetworking new interface driver hub [Sat Apr 12 19:33:51.518 2014] usbcore: registenetworking 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 registenetworking, 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: registenetworking 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! 

El problema está aquí:

 [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 

El arranque comienza después de cerca de 0.6 segundos. ¿Cómo puedo hacerlo más rápido? Quiero que el arranque comience después de 0.1 segundo del Starting kernel ...

¿Cuál debería ser mi enfoque para mejorar esto?

Actualizar

He vuelto con el mismo problema otra vez.

Me gustaría saber qué funciones se llaman después de " Iniciar kernel … ". He puesto varias declaraciones printf y printk en los siguientes files, pero no obtuve ninguna utilidad a partir de ahora:

1- bootm.c

2- setup.c

3- main.c

Todavía estoy teniendo estos posts:

  [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 

No puedo encontrar la ruptura del time entre estos dos posts. Incluso si pudiera conocer el software cointrol entre estas dos líneas, me ayudará a llegar a la causa raíz.

En particular, quiero saber qué línea de código se está ejecutando entre estos dos posts.

Sé que podría estar ocurriendo alguna iniciación entre estas líneas, pero ¿dónde está el código para el mismo?

El problema es que no hay function main (), así que no puedo encontrar la secuencia de las llamadas de function en el file anterior.

Durante estos 0.6 segundos, pasan cosas. Todos los posts hasta "Iniciar kernel" se imprimen mediante U-Boot. Todos los posts de "Booting Linux" en adelante son impresos por el kernel de Linux. El kernel necesita inicializar sus propias estructuras de datos y una cantidad de periféricos (suficiente para poder imprimir una traza). Esto lleva time.

Puedes ver lo que está haciendo el núcleo leyendo el main . El post "Booting Linux" proviene de la llamada a smp_setup_processor_id .

Puede rastrear el código en un depurador para ver dónde está gastando time. Es posible que haya algo de hardware innecesario que se está inicializando, por ejemplo. Pero es poco probable que haya algo que ganar en este punto.

Supongo que esto tiene mucho que ver con la forma en que se pegan el cargador de arranque y el kernel. La Sección 5.1.3 (Bootstrap Loader) en Embedded Linux Primer de Hallinan tiene lo siguiente que decir al respecto:

Algunos cargadores de arranque realizan verificaciones de sum de verificación de la image del kernel, y la mayoría descomprime y reubica la image del kernel. La diferencia entre un gestor de arranque y un cargador de arranque en este context es simple: el gestor de arranque controla la placa al encenderse y no depende del kernel de Linux de ninguna manera. Por el contrario, el propósito principal del cargador de bootstrap es actuar como el pegamento entre un gestor de arranque de metal puro y el kernel de Linux. Es responsabilidad del cargador de bootstrap proporcionar un context adecuado para que el kernel se ejecute, así como realizar los pasos necesarios para descomprimir y reubicar la image binaria del kernel

Si ve la image con ella, observará que antes de la ejecución real del núcleo, se ejecutan las rutinas de ensamblaje head.s y head-<arch>.s . Algunas otras tareas, como la descompression del kernel a la memory, tienen que hacerse porque Kernel no está en la forma correcta del kernel ( vmlinux ), sino que está comprimida y pegada a estas rutinas como una image piggy.gz .

Aunque esto es específico del arco, creo que puede explicar el time extra entre el cambio de Uboot a kernel.

Empiezas con la function do_bootm_linux en bootm.c y te bootm.c al código. También puede intentar agregar el parámetro debug o loglevel=7 al iniciar el kernel para get más información.