Why is kernel boot too late?

2020-03-31 08:21发布

问题:

I have zynq-microzed board and my log messages are following...

[Mon Jun 09 19:28:38.231 2014] SF: Detected S25FL129P_64K/S25FL128S_64K with page size 64 KiB, total 16 MiB
[Mon Jun 09 19:28:38.446 2014] SF: 1245184 bytes @ 0x520000 Read: OK
[Mon Jun 09 19:28:38.446 2014] ## Loading kernel from FIT Image at 01000000 ...
[Mon Jun 09 19:28:38.446 2014]    Using 'conf@1' configuration
[Mon Jun 09 19:28:38.446 2014]    Trying 'kernel@1' kernel subimage
[Mon Jun 09 19:28:38.446 2014]      Description:  PetaLinux Kernel
[Mon Jun 09 19:28:38.446 2014]      Type:         Kernel Image
[Mon Jun 09 19:28:38.446 2014]      Compression:  gzip compressed
[Mon Jun 09 19:28:38.446 2014]      Data Start:   0x010000f0
[Mon Jun 09 19:28:38.446 2014]      Data Size:    1215908 Bytes = 1.2 MiB
[Mon Jun 09 19:28:38.446 2014]      Architecture: ARM
[Mon Jun 09 19:28:38.446 2014]      OS:           Linux
[Mon Jun 09 19:28:38.446 2014]      Load Address: 0x00008000
[Mon Jun 09 19:28:38.446 2014]      Entry Point:  0x00008000
[Mon Jun 09 19:28:38.446 2014]    Verifying Hash Integrity ... OK
[Mon Jun 09 19:28:38.446 2014] ## Loading fdt from FIT Image at 01000000 ...
[Mon Jun 09 19:28:38.490 2014]    Using 'conf@1' configuration
[Mon Jun 09 19:28:38.490 2014]    Trying 'fdt@1' fdt subimage
[Mon Jun 09 19:28:38.490 2014]      Description:  Flattened Device Tree blob
[Mon Jun 09 19:28:38.490 2014]      Type:         Flat Device Tree
[Mon Jun 09 19:28:38.490 2014]      Compression:  uncompressed
[Mon Jun 09 19:28:38.490 2014]      Data Start:   0x01128f44
[Mon Jun 09 19:28:38.490 2014]      Data Size:    9766 Bytes = 9.5 KiB
[Mon Jun 09 19:28:38.490 2014]      Architecture: ARM
[Mon Jun 09 19:28:38.490 2014]      Hash algo:    crc32
[Mon Jun 09 19:28:38.490 2014]      Hash value:   fad9c7a8
[Mon Jun 09 19:28:38.490 2014]      Hash algo:    sha1
[Mon Jun 09 19:28:38.490 2014]      Hash value:   4ffcd311a61838768c94b2cb0c2e3d5312861fb4
[Mon Jun 09 19:28:38.490 2014]    Verifying Hash Integrity ... crc32+ sha1+ OK
[Mon Jun 09 19:28:38.490 2014]    Booting using the fdt blob at 0x1128f44
[Mon Jun 09 19:28:38.492 2014]    Uncompressing Kernel Image ... OK
[Mon Jun 09 19:28:38.595 2014]    Loading Device Tree to 07ffa000, end 07fff625 ... OK
[Mon Jun 09 19:28:38.595 2014] 
[Mon Jun 09 19:28:38.595 2014] Starting kernel ...
[Mon Jun 09 19:28:38.595 2014] 
[Mon Jun 09 19:28:39.137 2014] Booting Linux on physical CPU 0x0
[Mon Jun 09 19:28:39.137 2014] Linux version 3.8.11 (root@xilinx) (gcc version 4.7.3 (Sourcery CodeBench Lite 2013.05-40) ) #33 SMP PREEMPT Mon Jun 9 19:23:59 IST 2014
[Mon Jun 09 19:28:39.137 2014] CPU: ARMv7 Processor [413fc090] revision 0 (ARMv7), cr=18c53c7d
[Mon Jun 09 19:28:39.137 2014] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[Mon Jun 09 19:28:39.137 2014] Machine: Xilinx Zynq Platform, model: suheb_24
[Mon Jun 09 19:28:39.137 2014] Memory policy: ECC disabled, Data cache writealloc
[Mon Jun 09 19:28:39.137 2014] PERCPU: Embedded 7 pages/cpu @c0aa3000 s5568 r8192 d14912 u32768
[Mon Jun 09 19:28:39.137 2014] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 260096
[Mon Jun 09 19:28:39.181 2014] Kernel command line: console=ttyPS0,115200
[Mon Jun 09 19:28:39.181 2014] PID hash table entries: 4096 (order: 2, 16384 bytes)
[Mon Jun 09 19:28:39.181 2014] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[Mon Jun 09 19:28:39.181 2014] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[Mon Jun 09 19:28:39.181 2014] __ex_table already sorted, skipping sort
[Mon Jun 09 19:28:39.181 2014] Memory: 1024MB = 1024MB total
[Mon Jun 09 19:28:39.181 2014] Memory: 1036800k/1036800k available, 11776k reserved, 270336K highmem
[Mon Jun 09 19:28:39.181 2014] Virtual kernel memory layout:
[Mon Jun 09 19:28:39.181 2014]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[Mon Jun 09 19:28:39.181 2014]     fixmap  : 0xfff00000 - 0xfffe0000   ( 896 kB)
[Mon Jun 09 19:28:39.226 2014]     vmalloc : 0xf0000000 - 0xff000000   ( 240 MB)
[Mon Jun 09 19:28:39.226 2014]     lowmem  : 0xc0000000 - 0xef800000   ( 760 MB)
[Mon Jun 09 19:28:39.226 2014]     pkmap   : 0xbfe00000 - 0xc0000000   (   2 MB)
[Mon Jun 09 19:28:39.226 2014]     modules : 0xbf000000 - 0xbfe00000   (  14 MB)
[Mon Jun 09 19:28:39.226 2014]       .text : 0xc0008000 - 0xc01b8c4c   (1732 kB)
[Mon Jun 09 19:28:39.226 2014]       .init : 0xc01b9000 - 0xc02785c0   ( 766 kB)
[Mon Jun 09 19:28:39.226 2014]       .data : 0xc027a000 - 0xc0289980   (  63 kB)
[Mon Jun 09 19:28:39.226 2014]        .bss : 0xc0289980 - 0xc0298798   (  60 kB)
[Mon Jun 09 19:28:39.226 2014] Preemptible hierarchical RCU implementation.
[Mon Jun 09 19:28:39.226 2014]  RCU restricting CPUs from NR_CPUS=4 to nr_cpu_ids=2.
[Mon Jun 09 19:28:39.267 2014] NR_IRQS:16 nr_irqs:16 16
[Mon Jun 09 19:28:39.267 2014] xslcr mapped to f0002000
[Mon Jun 09 19:28:39.267 2014] Zynq clock init
[Mon Jun 09 19:28:39.267 2014] sched_clock: 16 bits at 54kHz, resolution 18432ns, wraps every 1207ms
[Mon Jun 09 19:28:39.267 2014] ps7-ttc #0 at f0004000, irq=43

it takes 0.542 seconds between...

[Mon Jun 09 19:28:38.595 2014] Starting kernel ...
[Mon Jun 09 19:28:38.595 2014] 
[Mon Jun 09 19:28:39.137 2014] Booting Linux on physical CPU 0x0

Now i want to reduce this time as possible.. But i dont know how to reduce this time (0.542 sec) And i want to know that, what does it do at that time.

Can you please tell me how can i achieve this?

回答1:

Your method of calculating elapsed time is using flawed data.
What you think is a 0.5 sec "delay" is actually U-Boot outputting "Starting kernel ..." in real time, while the kernel buffers and postpones outputting its "Booting Linux..." until the system and console are initialized. That's comparing apples to oranges.
At the very least you have to get the kernel to output in realtime (just like U-Boot). Then your timestamps will better indicate actual elapsed time.

While the kernel is performing the early initialization, interrupts are disabled and any output to the console (including that "Booting Linux on..." message) is held in a buffer until console_init() is performed at line 572 in Linux/init/main.c. Note that the salient "Booting Linux on..." text was "output" at the beginning of this start_kernel() procedure from the routine smp_setup_processor_id(), line 478. Most of the "delay" that you notice before the "Booting Linux on..." text appears as the kernel starts up is caused by this buffering of the console output.

You can overcome this apparent delay due to buffering by enabling the kernel debugging feature early printk.
Two steps are required:

  1. Enable this feature in configuration:

    make menuconfig
    Kernel hacking
    Kernel low-level debugging functions
    Early printk

  2. Add the parameter "earlyprintk" to the kernel command line, which is usually stored in the U-Boot environment variable bootargs or in the Device Tree.

The kernel boot log should indicate that this feature is enabled:

Booting Linux on physical CPU 0x0
Linux version 3.10...
CPU: ARMv7 Processor [410fc051] revision 1 (ARMv7), cr=10c53c7d
CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Machine: Atmel SAMA5 (Device Tree), model: Atmel SAMA5D36-EK
bootconsole [earlycon0] enabled
Memory policy: ECC disabled, Data cache writeback
...
Kernel command line: console=ttyS0,115200 earlyprintk rootfstype=ubifs ...