Por que a inicialização do kernel está começando tarde demais?

Question

Mensagem de log da placa baseada no ARM Cortex A9. Correndo 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!

O problema está aqui:

[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

A inicialização está começando após cerca de 0,6 segundos. Como posso fazer isso mais rápido? Eu quero que a inicialização deve começar após 0,1 segundo do Starting kernel ...

Qual deve ser meu foco para melhorar isso?

Atualizar

Estou de volta com o mesmo problema novamente.

Gostaria de saber quais funções são chamadas depois de " Iniciando o kernel ... ". Eu coloquei várias instruções printf e printk nos arquivos a seguir, mas não consegui nada útil a partir de agora:

1- bootm.c

2- setup.c

3- main.c

Ainda estou tendo estas mensagens:

    [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 

Não consigo encontrar a divisão do tempo entre essas duas mensagens. Mesmo se eu pudesse conhecer o software cointrol entre essas duas linhas, isso me ajudaria a alcançar a causa raiz.

Em particular, quero saber qual linha de código está sendo executada entre essas duas mensagens.

Eu sei que alguma iniciação pode estar acontecendo entre essas linhas, mas onde está o código para o mesmo?

O problema é que não há nenhuma função main (), por isso não consigo encontrar a sequência das chamadas funnction no arquivo acima.

    

Answer 1

Durante esses 0,6 segundos, o material acontece. Todas as mensagens até “Starting kernel” são impressas por U-Boot Todas as mensagens de “Booting Linux” em diante são impressas pelo kernel do Linux. O kernel precisa inicializar suas próprias estruturas de dados e vários periféricos (o suficiente para imprimir um rastreamento). Isso leva tempo.

Você pode ver o que o kernel está fazendo lendo o main . A mensagem “Boot Linux” vem da chamada para smp_setup_processor_id .

Você pode rastrear o código em um depurador para ver onde está gastando tempo. É possível que haja algum hardware desnecessário sendo inicializado, por exemplo. Mas é improvável que haja algo a ganhar neste momento.

    

Answer 2

Eu acho que isso tem muito a ver com a maneira como o carregador de inicialização e o kernel são colados . A Seção 5.1.3 (Bootstrap Loader) no Embedded Linux Primer da Hallinan tem o seguinte a dizer sobre isso:

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

Se você vir a imagem com ela, observará que, antes da execução real do kernel, as rotinas% assembly head.s e head-<arch>.s são executadas. Algumas outras tarefas, como a descompactação do kernel para a memória, precisam ser feitas, pois o kernel não está na forma kernel ( vmlinux ), mas compactado e colado a essas rotinas como piggy.gz image.

Embora isso seja específico do arco, mas eu acho que isso pode explicar o tempo extra entre a mudança do Uboot para o kernel.

    

Answer 3

Você começa com a função do_bootm_linux em bootm.c e segue seu caminho até o código. Você também pode tentar adicionar o parâmetro debug ou loglevel=7 ao iniciar o kernel para obter mais informações.