Very slow boot time from SD Card (kernel and initrd load)

I’ve created a custom Debian build for a Xavier NX, after I create the rootfs I use the L4T tools to create an SD card image. The card does boot and I can login to the newly created system. What I am seeing is a very long boot time, specifically loading of the kernel and initrd. The following boot log is using a kernel provided by Allied Vision but I have seen the same issue using the stock Nvidia kernel as well.

I have speed tested the SD card once the system is running and I can write at 76MB/s so I don’t think the card is the issue.

Looking at the log times you can see where the issue is. What would cause this to happen.

[0001.164] I>  3) Base:0xf1200000 Size:0x00200000
[0001.169] I>  4) Base:0xf1000000 Size:0x00100000
[0001.173] I>  5) Base:0xf0f00000 Size:0x00100000
[0001.178] I>  6) Base:0xf3800000 Size:0x00400000
[0001.182] I>  7) Base:0xf1c00000 Size:0x00400000
[0001.187] I>  8) Base:0xf0e00000 Size:0x00100000
[0001.191] I>  9) Base:0xf0d00000 Size:0x00100000
[0001.196] I> 10) Base:0xf3000000 Size:0x00800000
[0001.200] I> 11) Base:0x40000000 Size:0x00040000
[0001.205] I> 12) Base:0xf0c00000 Size:0x00100000
[0001.209] I> 13) Base:0x40046000 Size:0x00002000
[0001.213] I> 14) Base:0x40048000 Size:0x00002000
[0001.218] I> 15) Base:0xac000000 Size:0x00004000
[0001.222] I> 16) Base:0x4004a000 Size:0x00002000
[0001.227] I> 17) Base:0xf0b00000 Size:0x00100000
[0001.231] I> 18) Base:0x4004c000 Size:0x00002000
[0001.236] I> 19) Base:0xf2200000 Size:0x00600000
[0001.240] I> 20) Base:0x4004e000 Size:0x00002000
[0001.245] I> 21) Base:0xf0ad0000 Size:0x0000c000
[0001.249] I> 22) Base:0x00000000 Size:0x00000000
[0001.254] I> 23) Base:0xf0ae0000 Size:0x00020000
[0001.258] I> 24) Base:0xf6000000 Size:0x02000000
[0001.263] I> 25) Base:0x40050000 Size:0x00002000
[0001.267] I> 26) Base:0x40040000 Size:0x00006000
[0001.271] I> 27) Base:0xf1800000 Size:0x00400000
[0001.276] I> 28) Base:0xf4c00000 Size:0x01400000
[0001.280] I> 29) Base:0xf1400000 Size:0x00400000
[0001.285] I> 30) Base:0x00000000 Size:0x00000000
[0001.289] I> 31) Base:0x00000000 Size:0x00000000
[0001.294] I> 32) Base:0xf8000000 Size:0x08000000
[0001.298] I> 33) Base:0x00000000 Size:0x00000000
[0001.303] I> 34) Base:0xf3c00000 Size:0x01000000
[0001.307] I> 35) Base:0xab000000 Size:0x01000000
[0001.312] I> 36) Base:0xa0000000 Size:0x0b000000
[0001.316] I> 37) Base:0xf2800000 Size:0x00800000
[0001.321] I> 38) Base:0x80000000 Size:0x20000000
[0001.325] I> 39) Base:0xb0000000 Size:0x08000000
[0001.329] I> 40) Base:0x00000000 Size:0x00000000
[0001.334] I> 41) Base:0x00000000 Size:0x00000000
[0001.338] I> 42) Base:0x00000000 Size:0x00000000
[0001.343] I> 43) Base:0x00000000 Size:0x00000000
[0001.347] I> 44) Base:0x00000000 Size:0x00000000
[0001.352] I> 45) Base:0x00000000 Size:0x00000000
[0001.356] GIC-SPI Target CPU: 0
[0001.359] Interrupts Init done
[0001.362] calling constructors
[0001.365] initializing heap
[0001.368] I> Heap: [0xa06945e8 ... 0xab000000]
[0001.372] initializing threads
[0001.375] initializing timers
[0001.378] creating bootstrap completion thread
[0001.382] top of bootstrap2()
[0001.385] CPU: MIDR: 0x4E0F0040, MPIDR: 0x80000000
[0001.389] initializing platform
[0001.392] E> DEVICE_PROD: Invalid value data = 0, size = 0.
[0001.398] W> device prod register failed
[0001.401] I> Bl_dtb @0xaaf00000
[0001.407] W> "plugin-manager" doesn't exist, creating
[0001.409] W> "ids" doesn't exist, creating
[0001.414] W> "connection" doesn't exist, creating
[0001.418] W> "configs" doesn't exist, creating
[0001.429] I> Find /i2c@3160000's alias i2c0
[0001.429] I> Reading eeprom i2c=0 address=0x50
[0001.456] I> Device at /i2c@3160000:0x50
[0001.456] I> Reading eeprom i2c=0 address=0x57
[0001.481] I> Device at /i2c@3160000:0x57
[0001.482] I> Find /i2c@c240000's alias i2c1
[0001.482] I> Reading eeprom i2c=1 address=0x50
[0001.484] E> I2C: slave not found in slaves.
[0001.484] E> I2C: Could not write 0 bytes to slave: 0x00a0 with repeat start true.
[0001.485] E> I2C_DEV: Failed to send register address 0x00000000.
[0001.486] E> I2C_DEV: Could not read 256 registers of size 1 from slave 0xa0 at 0x00000000 via instance 1.
[0001.495] E> eeprom: Retry to read I2C slave device.
[0001.500] E> I2C: slave not found in slaves.
[0001.504] E> I2C: Could not write 0 bytes to slave: 0x00a0 with repeat start true.
[0001.511] E> I2C_DEV: Failed to send register address 0x00000000.
[0001.517] E> I2C_DEV: Could not read 256 registers of size 1 from slave 0xa0 at 0x00000000 via instance 1.
[0001.526] E> eeprom: Failed to read I2C slave device
[0001.531] I> Eeprom read failed 0x3526070d
[0001.535] I> create_pm_ids: id: 3668-0000-200-H, len: 15
[0001.540] I> config: mem-type:00,power-config:00,misc-config:00,modem-config:00,touch-config:00,display-config:00,, len: 93
[0001.551] I> create_pm_ids: id: 3509-0000-100-F, len: 15
[0001.557] I> config: mem-type:00,power-config:00,misc-config:00,modem-config:00,touch-config:00,display-config:00,, len: 93
[0001.568] I> Adding plugin-manager/ids/3668-0000-200=/i2c@3160000:module@0x50
[0001.575] W> "i2c@3160000" doesn't exist, creating
[0001.579] W> "module@0x50" doesn't exist, creating
[0001.584] I> Adding plugin-manager/ids/3509-0000-100=/i2c@3160000:module@0x57
[0001.591] W> "module@0x57" doesn't exist, creating
[0001.597] I> Adding plugin-manager/cvm
[0001.599] W> "chip-id" doesn't exist, creating
[0001.603] I> Adding plugin-manager/chip-id/A02P
[0001.608] I> Plugin-manager override starting
[0001.613] I> node /plugin-manager/fragment-pcie-c5-rp matches
[0001.622] I> node /plugin-manager/fragement-tegra-wdt-en matches
[0001.627] I> node /plugin-manager/fragement-tegra-sdhci-emmc-dis matches
[0001.633] I> Disable plugin-manager status in FDT
[0001.635] I> Plugin-manager override finished successfully
[0001.640] I> gpio framework initialized
[0001.644] I> tegrabl_gpio_driver_register: register 'nvidia,tegra194-gpio' driver
[0001.652] I> tegrabl_gpio_driver_register: register 'nvidia,tegra194-gpio-aon' driver
[0001.659] I> tegrabl_tca9539_init: i2c bus: 1, slave addr: 0x46
[0001.665] W> fetch_driver_phandle_from_dt: failed to get node with compatible ti,tca9539
[0001.673] W> fetch_driver_phandle_from_dt: failed to get node with compatible nxp,tca9539
[0001.680] W> tegrabl_tca9539_init: failed to fetch phandle from dt
[0001.686] I> tegrabl_tca9539_init: i2c bus: 1, slave addr: 0x44
[0001.693] W> fetch_driver_phandle_from_dt: failed to get node with compatible ti,tca9539
[0001.701] W> fetch_driver_phandle_from_dt: failed to get node with compatible nxp,tca9539
[0001.708] W> tegrabl_tca9539_init: failed to fetch phandle from dt
[0001.715] I> fixed regulator driver initialized
[0001.722] I> register 'maxim' power off handle
[0001.723] I> virtual i2c enabled
[0001.726] I> registered 'maxim,max20024' pmic
[0001.730] I> tegrabl_gpio_driver_register: register 'max20024-gpio' driver
[0001.737] I> Boot-device: QSPI
[0001.740] I> Boot_device: QSPI_FLASH instance: 0
[0001.745] I> QSPI source rate = 204000 Khz
[0001.748] I> Requested rate for QSPI clock = 34000 Khz
[0001.753] I> BPMP-set rate for QSPI clk = 34000 Khz
[0001.758] I> QSPI Flash Size = 32 MB
[0001.766] I> Qspi initialized successfully
[0001.766] I> qspi flash-0 params source = boot args
[0001.770] I> create_pm_ids: id: 3668-0000-200-H, len: 15
[0001.775] I> config: mem-type:00,power-config:00,misc-config:00,modem-config:00,touch-config:00,display-config:00,, len: 93
[0001.786] I> create_pm_ids: id: 3509-0000-100-F, len: 15
[0001.791] I> config: mem-type:00,power-config:00,misc-config:00,modem-config:00,touch-config:00,display-config:00,, len: 93
[0001.803] I> Found sdcard
[0001.807] I> enabling 'vdd-sdmmc1-sw' regulator
[0001.813] I> regulator 'vdd-sdmmc1-sw' already enabled
[0001.967] I> -0 params source = 
[0001.969] I> Found 47 partitions in QSPI_FLASH (instance 0)
[0002.063] I> Found 11 partitions in SDCARD (instance 0)
[0002.070] I> regulator 'vdd-hdmi-5v0' already enabled
[0002.074] I> regulator 'vdd-hdmi-5v0' already enabled
[0002.074] E> tegrabl_display_init_regulator: hdmi cable is not connected
[0002.075] E> tegrabl_display_get_pdata, failed to parse dtb settings
[0002.078] E> invalid display type
[0002.079] E> cannot find any other nvdisp nodes
[0002.079] E> no valid display unit config found in dtb
[0002.082] W> display init failed
[0002.084] I> Load in CBoot Boot Options partition and parse it
[0002.090] E> Error -9 when finding node with path /boot-configuration
[0002.096] E> tegrabl_cbo_parse_info: "boot-configuration" not found in CBO file.
[0002.103] I> Using default boot order
[0002.106] I> boot-dev-order :-
[0002.109] I> 1.sd
[0002.111] I> 2.usb
[0002.113] I> 3.nvme
[0002.115] I> 4.emmc
[0002.117] I> 5.net
[0002.119] I> Hit any key to stop autoboot:	4	3	2	1
[0004.126] initializing target
[0004.126] calling apps_init()
[0004.127] starting app kernel_boot_app
[0004.133] I> found decompressor handler: lz4-legacy
[0004.133] I> decompressing BMP blob ...
[0004.137] I> Kernel type = Normal
[0004.137] I> Loading kernel-bootctrl from partition
[0004.137] I> Loading partition kernel-bootctrl at 0xa42c0000 from device(0x6)
[0005.512] W> tegrabl_get_kernel_bootctrl: magic number(0x00000000) is invalid
[0005.513] W> tegrabl_get_kernel_bootctrl: use default dummy boot control data
[0005.513] I> ########## SD (0) boot ##########
[0005.514] I> Found sdcard
[0005.515] I> regulator 'vdd-sdmmc1-sw' already enabled
[0005.519] I> regulator 'vdd-sdmmc1-sw' already enabled
[0005.560] I> -0 params source = 
[0005.560] I> Already published: 00060000
[0005.561] I> Look for boot partition
[0005.561] I> Fallback: assuming 0th partition is boot partition
[0005.561] I> Detect filesystem
[0005.688] I> Loading extlinux.conf ...
[0005.688] I> rootfs path: /sd/boot/extlinux/extlinux.conf
[0005.858] I> L4T boot options
[0005.858] I> [1]: "primary kernel"
[0005.859] I> Enter choice: 
[0008.860] I> Continuing with default option: 1
[0008.860] I> Loading kernel sig file from rootfs ...
[0008.860] I> rootfs path: /sd/boot/Image.sig
[0008.933] I> Loading kernel binary from rootfs ...
[0008.934] I> rootfs path: /sd/boot/Image
[0188.285] I> Validate kernel ...
[0188.286] I> T19x: Authenticate kernel (bin_type: 37), max size 0x5000000
[0188.600] E> digest on binary did not match!!
[0188.600] C> OEM authentication of kernel payload failed!
[0188.601] W> Failed to validate kernel binary (err=1077936152, fail=0)
[0188.601] W> Security fuse not burned, ignore validation failure
[0188.613] I> No kernel-dtb binary path
[0188.613] I> A/B: bin_type (38) slot 0
[0188.614] I> Loading kernel-dtb from partition
[0188.614] I> Loading partition kernel-dtb at 0x91000000 from device(0x6)
[0191.018] I> Validate kernel-dtb ...
[0191.018] I> T19x: Authenticate kernel-dtb (bin_type: 38), max size 0x400000
[0191.021] I> Encryption fuse is not ON
[0191.022] I> Loading ramdisk from rootfs ...
[0191.022] I> Loading initrd sig file from rootfs ...
[0191.022] I> rootfs path: /sd/boot/initrd.sig
[0191.095] I> Loading initrd binary from rootfs ...
[0191.096] I> rootfs path: /sd/boot/initrd
[0229.025] I> overload load_size to 7238344 (from 7238352)
[0229.028] I> Validate initrd ...
[0229.028] I> T19x: Authenticate initrd (bin_type: 49), max size 0x4000000
[0229.094] I> Encryption fuse is not ON
[0229.108] I> Kernel hdr @0xa42c0000
[0229.108] I> Kernel dtb @0x90000000
[0229.108] I> decompressor handler not found
[0229.109] I> Copying kernel image (34271240 bytes) from 0xa42c0000 to 0x80080000 ... [0229.119] I> Done
[0229.120] I> Updated bpmp info to DTB
[0229.121] I> Ramdisk: Base: 0x92000000; Size: 0x6e72c8
[0229.121] I> Updated initrd info to DTB
[0229.122] W> WARN: Fail to override "console=none" in commandline
[0229.122] I> Active rootfs suffix: 
[0229.124] E> tegrabl_linuxboot_add_disp_param, du 0 failed to get display params
[0229.131] E> tegrabl_linuxboot_add_disp_param, du 0 failed to get display params
[0229.139] E> tegrabl_linuxboot_add_disp_param, du 0 failed to get display params
[0229.146] I> Active slot suffix: 
[0229.149] I> add_boot_slot_suffix: slot_suffix = 
[0229.154] I> Linux Cmdline: console=ttyTCU0,115200 video=tegrafb no_console_suspend=1 earlycon=tegra_comb_uart,mmio32,0x0c168000 gpt rootfs.slot_suffix= usbcore.old_scheme_first=1 tegraid=19.1.2.0.0 maxcpus=6 boot.slot_suffix= boot.ratchetvalues=0.4.2 vpr_resize sdhci_tegra.en_boot_part_access=1 
[0229.180] I> Updated bootarg info to DTB
[0229.184] W> MAC addr invalid!
[0229.186] E> Failed to get WIFI MAC address
[0229.190] W> MAC addr invalid!
[0229.193] E> Failed to get Bluetooth MAC address
[0229.198] I> eeprom_get_mac_addr: MAC (type: 2): 48:b0:2d:07:88:0d
[0229.204] W> "plugin-manager" doesn't exist, creating
[0229.209] I> Adding /chosen/plugin-manager/cvm
[0229.213] W> "chip-id" doesn't exist, creating
[0229.217] I> Adding /chosen/plugin-manager/chip-id
[0229.222] W> "configs" doesn't exist, creating
[0229.226] I> Adding /chosen/plugin-manager/configs
[0229.231] W> "ids" doesn't exist, creating
[0229.235] I> Adding /chosen/plugin-manager/ids
[0229.239] W> "odm-data" doesn't exist, creating
[0229.244] I> Adding /chosen/plugin-manager/odm-data
[0229.251] W> "memory" doesn't exist, creating
[0229.253] I> [0] START: 0x80000000, END: 0xac000000
[0229.257] I> [1] START: 0xac004000, END: 0xf0ad0000
[0229.262] I> [2] START: 0xf0adc000, END: 0xf0ae0000
[0229.267] I> dram_block larger than 80000000
[0229.271] I> [3] START: 0x100000000, END: 0x280000000
[0229.276] I> added [base:0x80000000, size:0x2c000000] to /memory
[0229.281] I> added [base:0xac200000, size:0x44800000] to /memory
[0229.287] I> added [base:0x100000000, size:0x180000000] to /memory
[0229.294] I> Updated memory info to DTB
[0229.297] E> add_disp_param: failed to get display params for du=0
[0229.303] W> "reset" doesn't exist, creating
[0229.308] I> Adding ecid(00000001645df4441800000015ff8200) to DT
[0229.313] I> NVG: Logical CPU: 0; MPIDR: 0x80000000
[0229.318] I> NVG: Logical CPU: 1; MPIDR: 0x80000001
[0229.322] I> NVG: Logical CPU: 2; MPIDR: 0x80000100
[0229.327] I> NVG: Logical CPU: 3; MPIDR: 0x80000101
[0229.332] I> NVG: Logical CPU: 4; MPIDR: 0x80000200
[0229.337] I> NVG: Logical CPU: 5; MPIDR: 0x80000201
[0229.341] I> Deleted cpu@6 node in DT
[0229.345] I> Deleted cpu@7 node in DT
[0229.349] I> Deleted cluster3 node in FDT
[0229.352] I> Update arm-pmu in FDT
[0229.355] I> - update property: interrupts
[0229.359] I> - update property: interrupt-affinity
[0229.365] W> "misc-data" doesn't exist, creating
[0229.369] I> Boot-device: QSPI
[0229.371] W> Unknown boot device
[0229.374] I> Add storage-qspi to plugin-manager/misc-data
[0229.380] W> Unknown storage device
[0229.383] I> Add serial number:1421520055788 as DT property
[0229.389] I> Plugin-manager override starting
[0229.393] I> node /plugin-manager/fragment-pcie-c5-rp matches
[0229.400] I> node /plugin-manager/fragement-tegra-wdt-en matches
[0229.406] I> node /plugin-manager/fragement-tegra-sdhci-emmc-dis matches
[0229.413] I> Disable plugin-manager status in FDT
[0229.415] I> Plugin-manager override finished successfully
[0229.421] I> tegrabl_load_kernel_and_dtb: Done

Can you help rely

  1. Is this a custom board or devkit?

  2. Will you see such behavior with the sdcard image provided by NV?

I’m using the dev board for this test.

I do not see this behaviour with the supplied Nvidia SD card image even with the Allied Vision kernel.

I am using the jetson-disk-image-creator.sh script from the latest L4T release. Same thing happens with both kernels I’ve tried.

Anything else I should try to help diagnose the problem?

Can you describe the whole step you are running here? I would like to reproduce this issue on our side.

The steps are as follows using Jetson_Linux_R32.6.1_aarch64.tbz2

  1. Creating a custom Debian 10 rootfs using qemu-debootstrap, it shouldn’t matter at this point what this looks like as the issue occurs before we get to this loading
  2. Copy the rootfs to Linux_for_Tegra/rootfs
  3. Run Linux_for_Tegra/apply_binaries.sh (more to create the extlinux.conf file then anything else)
  4. Run sudo ./tools/jetson-disk-image-creator.sh -o …/sdcard.img -b jetson-xavier-nx-devkit
  5. Run sudo dd if=sdcard.img of=/dev/mmcblk0 bs=1M oflab=direct
  6. Resize the rootfs to take up the rest of the sdcard
  7. Put the card in the NX and boot, I have a USB-TTL serial cable attached to the debug port

What I discovered that is slightly annoying is the supplied deb files are compressed with zst which is not supported by dpkg in Debian. NOt that I can use many of the packages but tools and oem-config could be handy. I recompressed all the debs to use the standard xz compression. Can’t install directly as they depend on core which is for Ubuntu only. Had to extract and copy.

Once it does finally boot the Debian rootfs behaves fine. Ubuntu is a bit bloated for my application and we like the stability of Debian.

Any luck reproducing this issue?

Hi,

We cannot reproduce your issue with the official rootfs.

Which means we didn’t do this step

  1. Creating a custom Debian 10 rootfs using qemu-debootstrap, it shouldn’t matter at this point what this looks like as the issue occurs before we get to this loading

Please try if original rootfs can also reproduce this issue on your side.

I have the exact same delay issue with the supplied rootfs. Is it possible it is the sdcard? Although it is fine once it boots. The SD card in use is a Class 10 Lexar card. Should be able to do 10MB/s.

I have another card that is a Class 3 Sandisk card, it loads the kernel in 3 seconds.

Is there a minimum card class?

We don’t have ‘minimum card class’ limitation to users’ cards. But sometimes such issue happens to some cards from some brand.

Turns out SD card brand makes a difference. Case U3 Sandisk card works fine, Class U1 Lexar does not