Striped down kernel take long time to load on Raspberry Pi 4

0

I'm just trying to customize the kernel configuration for Raspberry Pi 4B, to achieve a compact system image and quick startup, but as we can see in the logs there's approximate ~4.0s to start executing my 4.2MB kernel.

  • Logs:
23:20:06.198 -> 
23:20:06.198 -> PM_RSTS: 0x00001000
23:20:06.198 -> RPi: BOOTLOADER release VERSION:f626c772 Sep 10 2019 10:41:52 BOOTMODE: 0x00000006 part: 0 BUILD_TIMESTAMP=1568112110
23:20:06.231 -> uSD voltage 3.3V
23:20:06.430 -> SD HOST: 200000000 CTL0: 0x00000000 BUS: 100000 Hz div: 2000 status: 0x1fff0000 delay-ticks: 1080
23:20:06.463 -> SD HOST: 200000000 CTL0: 0x00000f00 BUS: 100000 Hz div: 2000 status: 0x1fff0000 delay-ticks: 1080
23:20:06.463 -> CID: 00035344534331364780411a41a20123
23:20:06.463 -> CSD: 400e00325b59000076b27f800a404000
23:20:06.496 -> CSD: VER: 1 logical blocks: 30386 mult: 1024 rd(len: 512 partial: 0 misalign: 0) sectors: 31116288
23:20:06.496 -> SD: bus-width: 4 spec: 2 SCR: 0x02358443 0x00000000
23:20:06.496 -> SWITCH_FUNC: 0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000010000038001c00180018001800180c800
23:20:06.529 -> SD HOST: 200000000 CTL0: 0x00000f04 BUS: 40000000 Hz div: 6 status: 0x1fff0000 delay-ticks: 2
23:20:06.529 -> MBR: 0x00000001,   32768 type: 0x0c
23:20:06.529 -> MBR: 0x00008001,   20376 type: 0x83
23:20:06.529 -> MBR: 0x0000cf99,  131072 type: 0x83
23:20:06.529 -> MBR: 0x00000000,       0 type: 0x00
23:20:06.529 -> part-offset: 1 oem:  mkfs.fat volume:   V       ^ 
23:20:06.529 -> rsc: 4 sectors-per-fat: 32 clusters: 8167 cluster-size: 4 root-dir: 1 root-sectors: 32
23:20:06.562 -> WEL: 0x00000045 0x00008000
23:20:06.562 -> PM_RSTS: 0x00001000
23:20:06.562 -> Partition: 0
23:20:06.562 -> part-offset: 1 oem:  mkfs.fat volume:   V       ^ 
23:20:06.562 -> rsc: 4 sectors-per-fat: 32 clusters: 8167 cluster-size: 4 root-dir: 1 root-sectors: 32
23:20:06.562 -> Loading config.txt hnd: 0x00000017
23:20:06.562 -> Initialising SDRAM 'Samsung' 8Gb x1 total-size: 8 Gbit 3200
23:20:07.258 -> Loading recovery.elf hnd: 0x00000000
23:20:07.258 -> Failed to read recovery.elf error: 6
23:20:07.291 -> Loading start4.elf hnd: 0x0000001b
23:20:07.655 -> Loading fixup4.dat hnd: 0x00000018
23:20:07.655 -> MEM GPU: 96 ARM: 928 TOTAL: 1024
23:20:07.655 -> FIXUP src: 128 256 dst: 928 1024
23:20:07.821 -> Starting start4.elf @ 0xfec00200
23:20:07.821 -> 
23:20:11.859 -> Booting Linux on physical CPU 0x0
23:20:11.859 -> Linux version 4.19.66-v7l (iman@MSI-7758) (gcc version 8.3.0 (Buildroot 2019.11.1-dirty)) #12 SMP PREEMPT Tue Feb 18 23:17:21 +0330 2020
23:20:11.859 -> CPU: ARMv7 Processor [410fd083] revision 3 (ARMv7), cr=50c5383d
23:20:11.859 -> CPU: div instructions available: patching division code
23:20:11.859 -> CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
23:20:11.893 -> OF: fdt: Machine model: Raspberry Pi 4 Model B Rev 1.1
23:20:11.893 -> Memory policy: Data cache writealloc
23:20:11.893 -> Ignoring RAM at 0x30000000-0x3a000000
23:20:11.893 -> Consider using a HIGHMEM enabled kernel.
23:20:11.893 -> cma: Reserved 64 MiB at 0x2ac00000
23:20:11.893 -> random: get_random_bytes called from start_kernel+0x63/0x2e4 with crng_init=0
23:20:11.893 -> percpu: Embedded 16 pages/cpu s34828 r8192 d22516 u65536
23:20:11.893 -> Built 1 zonelists, mobility grouping on.  Total pages: 194880
23:20:11.926 -> Kernel command line: coherent_pool=1M 8250.nr_uarts=1 cma=64M bcm2708_fb.fbwidth=0 bcm2708_fb.fbheight=0 bcm2708_fb.fbswap=1 smsc95xx.macaddr=DC:A6:32:4C:50:2A vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  root=/dev/mmcblk0p2 rootwait console=tty1 console=ttyAMA0,115200
23:20:11.926 -> Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
23:20:12.010 -> Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
23:20:12.010 -> Memory: 704556K/786432K available (4096K kernel code, 404K rwdata, 1748K rodata, 1024K init, 509K bss, 16340K reserved, 65536K cma-reserved)
23:20:12.010 -> Virtual kernel memory layout:
23:20:12.010 ->     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
23:20:12.010 ->     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
23:20:12.010 ->     vmalloc : 0xf0800000 - 0xff800000   ( 240 MB)
23:20:12.010 ->     lowmem  : 0xc0000000 - 0xf0000000   ( 768 MB)
23:20:12.010 ->     modules : 0xbf800000 - 0xc0000000   (   8 MB)
23:20:12.010 ->       .text : 0x(ptrval) - 0x(ptrval)   (5088 kB)
23:20:12.010 ->       .init : 0x(ptrval) - 0x(ptrval)   (1024 kB)
23:20:12.010 ->       .data : 0x(ptrval) - 0x(ptrval)   ( 405 kB)
23:20:12.010 ->        .bss : 0x(ptrval) - 0x(ptrval)   ( 510 kB)
23:20:12.010 -> ftrace: allocating 21664 entries in 43 pages
23:20:12.010 -> rcu: Preemptible hierarchical RCU implementation.
23:20:12.010 ->     Tasks RCU enabled.
23:20:12.010 -> NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
23:20:12.010 -> GIC: Using split EOI/Deactivate mode
23:20:12.010 -> arch_timer: cp15 timer(s) running at 54.00MHz (phys).
23:20:12.010 -> clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
23:20:12.032 -> sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
23:20:12.032 -> Switching to timer-based delay loop, resolution 18ns
23:20:12.032 -> Console: colour dummy device 80x30
23:20:12.058 -> console [tty1] enabled
23:20:12.058 -> Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=540000)
23:20:12.058 -> pid_max: default: 32768 minimum: 301
23:20:12.058 -> Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
23:20:12.058 -> Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
23:20:12.091 -> CPU: Testing write buffer coherency: ok
23:20:12.091 -> CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
23:20:12.091 -> Setting up static identity map for 0x100000 - 0x100038
23:20:12.091 -> rcu: Hierarchical SRCU implementation.
23:20:12.091 -> smp: Bringing up secondary CPUs ...
23:20:12.091 -> CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
23:20:12.091 -> CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
23:20:12.091 -> CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
23:20:12.124 -> smp: Brought up 1 node, 4 CPUs
23:20:12.124 -> SMP: Total of 4 processors activated (432.00 BogoMIPS).
23:20:12.124 -> CPU: All CPU(s) started in HYP mode.
23:20:12.124 -> CPU: Virtualization extensions available.
23:20:12.124 -> devtmpfs: initialized
23:20:12.124 -> VFP support v0.3: implementor 41 architecture 3 part 40 variant 8 rev 0
23:20:12.124 -> clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
23:20:12.158 -> futex hash table entries: 1024 (order: 4, 65536 bytes)
23:20:12.158 -> pinctrl core: initialized pinctrl subsystem
23:20:12.158 -> NET: Registered protocol family 16
23:20:12.158 -> DMA: preallocated 1024 KiB pool for atomic coherent allocations
23:20:12.158 -> hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
23:20:12.158 -> hw-breakpoint: maximum watchpoint size is 8 bytes.
23:20:12.158 -> Serial: AMBA PL011 UART driver
23:20:12.158 -> bcm2835-mbox fe00b880.mailbox: mailbox enabled
23:20:12.190 -> bcm2835-dma fe007000.dma: DMA legacy API manager at (ptrval), dmachans=0x1
23:20:12.190 -> usbcore: registered new interface driver usbfs
23:20:12.190 -> usbcore: registered new interface driver hub
23:20:12.190 -> usbcore: registered new device driver usb
23:20:12.190 -> raspberrypi-firmware soc:firmware: Attached to firmware from 2019-08-15 12:03, variant start
23:20:12.190 -> raspberrypi-firmware soc:firmware: Firmware hash is 9f8431fb7839c7f00f52b81f5822ddab2b31d0db
23:20:12.224 -> clocksource: Switched to clocksource arch_sys_counter
23:20:12.224 -> VFS: Disk quotas dquot_6.6.0
23:20:12.224 -> VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
23:20:12.224 -> FS-Cache: Loaded
23:20:12.224 -> CacheFiles: Loaded
23:20:12.224 -> NET: Registered protocol family 2
23:20:12.224 -> tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes)
23:20:12.224 -> TCP established hash table entries: 8192 (order: 3, 32768 bytes)
23:20:12.257 -> TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
23:20:12.257 -> TCP: Hash tables configured (established 8192 bind 8192)
23:20:12.257 -> UDP hash table entries: 512 (order: 2, 16384 bytes)
23:20:12.257 -> UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
23:20:12.257 -> NET: Registered protocol family 1
23:20:12.257 -> Initialise system trusted keyrings
23:20:12.257 -> workingset: timestamp_bits=14 max_order=18 bucket_order=4
23:20:12.290 -> squashfs: version 4.0 (2009/01/31) Phillip Lougher
23:20:12.290 -> Key type asymmetric registered
23:20:12.290 -> Asymmetric key parser 'x509' registered
23:20:12.290 -> Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250)
23:20:12.290 -> io scheduler noop registered
23:20:12.290 -> io scheduler deadline registered
23:20:12.290 -> io scheduler cfq registered (default)
23:20:12.290 -> io scheduler mq-deadline registered
23:20:12.290 -> io scheduler kyber registered
23:20:12.290 -> bcm2708_fb soc:fb: Unable to determine number of FB's. Assuming 1
23:20:12.323 -> bcm2708_fb soc:fb: FB found 1 display(s)
23:20:12.323 -> raspberrypi-firmware soc:firmware: Request 0x00048003 returned status 0x80000001
23:20:12.323 -> bcm2708_fb soc:fb: Failed to allocate GPU framebuffer (-22)
23:20:12.323 -> bcm2708_fb soc:fb: probe failed, err -22
23:20:12.323 -> bcm2708_fb: probe of soc:fb failed with error -22
23:20:12.323 -> Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
23:20:12.356 -> iproc-rng200 fe104000.rng: hwrng registered
23:20:12.356 -> vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
23:20:12.356 -> vc-sm: Videocore shared memory driver
23:20:12.356 -> gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000
23:20:12.356 -> brd: module loaded
23:20:12.356 -> loop: module loaded
23:20:12.356 -> libphy: Fixed MDIO Bus: probed
23:20:12.356 -> bcmgenet fd580000.genet: failed to get enet clock
23:20:12.356 -> bcmgenet fd580000.genet: GENET 5.0 EPHY: 0x0000
23:20:12.389 -> bcmgenet fd580000.genet: failed to get enet-wol clock
23:20:12.389 -> bcmgenet fd580000.genet: failed to get enet-eee clock
23:20:12.389 -> bcmgenet: Skipping UMAC reset
23:20:12.389 -> unimac-mdio unimac-mdio.-19: DMA mask not set
23:20:12.389 -> libphy: bcmgenet MII bus: probed
23:20:12.389 -> unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus at 0x(ptrval)
23:20:12.389 -> dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
23:20:12.389 -> dwc_otg fe980000.usb: base=(ptrval)
23:20:12.422 -> Core Release: 2.80a
23:20:12.422 -> Setting default values for core params
23:20:12.422 -> Finished setting default values for core params
23:20:12.422 -> WARN::dwc_otg_core_reset:5114: dwc_otg_core_reset() HANG! Soft Reset GRSTCTL=80000001
23:20:12.422 -> 
23:20:12.422 -> WARN::dwc_otg_core_reset:5114: dwc_otg_core_reset() HANG! Soft Reset GRSTCTL=80000001
23:20:12.422 -> 
23:20:12.422 -> Using Buffer DMA mode
23:20:12.422 -> Periodic Transfer Interrupt Enhancement - disabled
23:20:12.455 -> Multiprocessor Interrupt Enhancement - disabled
23:20:12.455 -> OTG VER PARAM: 0, OTG VER FLAG: 0
23:20:12.455 -> Dedicated Tx FIFOs mode
23:20:12.455 -> WARN::dwc_otg_hcd_init:1045: FIQ DMA bounce buffers: virt = ead04000 dma = 0xead04000 len=9024
23:20:12.455 -> FIQ FSM acceleration enabled for :
23:20:12.455 -> Non-periodic Split Transactions
23:20:12.455 -> Periodic Split Transactions
23:20:12.455 -> High-Speed Isochronous Endpoints
23:20:12.455 -> Interrupt/Control Split Transaction hack enabled
23:20:12.489 -> WARN::hcd_init_fiq:457: FIQ on core 1
23:20:12.489 -> WARN::hcd_init_fiq:458: FIQ ASM at c038a680 length 26
23:20:12.489 -> WARN::hcd_init_fiq:497: MPHI regs_base at f0810200
23:20:12.489 -> dwc_otg fe980000.usb: DWC OTG Controller
23:20:12.489 -> dwc_otg fe980000.usb: new USB bus registered, assigned bus number 1
23:20:12.489 -> dwc_otg fe980000.usb: irq 38, io mem 0x00000000
23:20:12.489 -> Init: Port Power? op_state=1
23:20:12.489 -> Init: Power Port (0)
23:20:12.522 -> usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
23:20:12.522 -> usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
23:20:12.522 -> usb usb1: Product: DWC OTG Controller
23:20:12.522 -> usb usb1: Manufacturer: Linux 4.19.66-v7l dwc_otg_hcd
23:20:12.522 -> usb usb1: SerialNumber: fe980000.usb
23:20:12.522 -> hub 1-0:1.0: USB hub found
23:20:12.522 -> hub 1-0:1.0: 1 port detected
23:20:12.522 -> mousedev: PS/2 mouse device common for all mice
23:20:12.555 -> bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
23:20:12.555 -> sdhci: Secure Digital Host Controller Interface driver
23:20:12.555 -> sdhci: Copyright(c) Pierre Ossman
23:20:12.555 -> mmc-bcm2835 fe300000.mmcnr: could not get clk, deferring probe
23:20:12.555 -> sdhci-pltfm: SDHCI platform and OF driver helper
23:20:12.555 -> ledtrig-cpu: registered to indicate activity on CPUs
23:20:12.555 -> hidraw: raw HID events driver (C) Jiri Kosina
23:20:12.588 -> usbcore: registered new interface driver usbhid
23:20:12.588 -> usbhid: USB HID core driver
23:20:12.588 -> vchiq: vchiq_init_state: slot_zero = (ptrval), is_master = 0
23:20:12.588 -> [vc_sm_connected_init]: start
23:20:12.588 -> [vc_sm_connected_init]: end - returning 0
23:20:12.588 -> Initializing XFRM netlink socket
23:20:12.588 -> NET: Registered protocol family 17
23:20:12.588 -> Key type dns_resolver registered
23:20:12.588 -> Registering SWP/SWPB emulation handler
23:20:12.588 -> registered taskstats version 1
23:20:12.621 -> Loading compiled-in X.509 certificates
23:20:12.621 -> uart-pl011 fe201000.serial: cts_event_workaround enabled
23:20:12.621 -> fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 34, base_baud = 0) is a PL011 rev2
23:20:12.621 -> console [ttyAMA0] enabled
23:20:12.621 -> fe215040.serial: ttyS0 at MMIO 0x0 (irq = 36, base_baud = 62500000) is a 16550
23:20:12.654 -> bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
23:20:12.654 -> brcmstb_thermal fd5d2200.thermal: registered AVS TMON of-sensor driver
23:20:12.654 -> mmc-bcm2835 fe300000.mmcnr: mmc_debug:0 mmc_debug2:0
23:20:12.654 -> mmc-bcm2835 fe300000.mmcnr: DMA channel allocated
23:20:12.687 -> sdhci-iproc fe340000.emmc2: Linked as a consumer to regulator.1
23:20:12.720 -> mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
23:20:12.720 -> mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
23:20:12.720 -> mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
23:20:12.754 -> mmc0: SDHCI controller on fe340000.emmc2 [fe340000.emmc2] using ADMA
23:20:12.754 -> of_cfs_init
23:20:12.754 -> of_cfs_init: OK
23:20:12.754 -> mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
23:20:12.754 -> uart-pl011 fe201000.serial: no DMA platform data
23:20:12.754 -> mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
23:20:12.754 -> Waiting for root device /dev/mmcblk0p2...
23:20:12.820 -> random: fast init done
23:20:12.820 -> mmc1: new high speed SDIO card at address 0001
23:20:12.886 -> mmc0: new ultra high speed DDR50 SDHC card at address aaaa
23:20:12.886 -> mmcblk0: mmc0:aaaa SC16G 14.8 GiB
23:20:12.886 ->  mmcblk0: p1 p2 p3
23:20:12.919 -> VFS: Mounted root (squashfs filesystem) readonly on device 179:2.
23:20:12.952 -> devtmpfs: mounted
23:20:12.985 -> Freeing unused kernel memory: 1024K
23:20:12.985 -> Run /sbin/init as init process
23:20:13.184 -> rcS: applet not found
23:20:13.283 -> 

23:20:13.283 -> Welcome to RPI4
23:20:13.283 -> root login: 
  • config.txt:
# Please note that this is only a sample, we recommend you to change it to fit
# your needs.
# You should override this file using a post-build script.
# See http://buildroot.org/manual.html#rootfs-custom
# and http://elinux.org/RPiconfig for a description of config.txt syntax

kernel=zImage

start_file=start4.elf
fixup_file=fixup4.dat

# Disable overscan assuming the display supports displaying the full resolution
# If the text shown on the screen disappears off the edge, comment this out
disable_overscan=1

# fixes rpi3 ttyAMA0 serial console
dtoverlay=pi3-miniuart-bt

# Uncomment some or all of these to enable the optional hardware interfaces
dtparam=i2c_arm=off
dtparam=i2s=off
dtparam=spi=off

# Disable audio (loads snd_bcm2835)
dtparam=audio=off

# Disable DPI interface
enable_dpi_lcd=0

# Disable LCD on I2C bus
ignore_lcd=1

# Disable camera module
start_x=0

# Disable rainbow splash
disable_splash=1

# Remove possible bootloader delay
boot_delay_ms=0
bootcode_delay=0
boot_delay=0

# Set VideoCore memory
gpu_mem=96
  • cmdline.txt:
root=/dev/mmcblk0p2 rootfstype=squashfs rootwait console=tty1 console=ttyAMA0,115200

Is this supposed to be normal?

linux-kernel
buildroot
raspberry-pi4
asked on Stack Overflow Feb 18, 2020 by IMAN4K • edited Feb 18, 2020 by IMAN4K

0 Answers

Nobody has answered this question yet.


User contributions licensed under CC BY-SA 3.0