Boot is extremely slow/hangs

After disabling the video, audio and wireless overlays in my uEnv.txt the boot starts to get extremely slow.

The serial console output looks as follows:

`

[11:41:14:515] ␍␊

[11:41:14:519] U-Boot SPL 2017.07-00002-g61c3ee0fb5 (Jul 19 2017 - 17:02:08)␍␊

[11:41:14:576] Trying to boot from MMC2␍␊

[11:41:14:678] ␍␊

[11:41:14:681] ␍␊

[11:41:14:681] U-Boot 2017.07-00002-g61c3ee0fb5 (Jul 19 2017 - 17:02:08 -0500), Build: jenkins-github_Bootloader-Builder-591␍␊

[11:41:14:690] ␍␊

[11:41:14:690] CPU : AM335X-GP rev 2.1␍␊

[11:41:14:692] I2C: ready␍␊

[11:41:14:744] DRAM: 512 MiB␍␊

[11:41:14:793] No match for driver 'omap_hsmmc’␍␊

[11:41:14:798] No match for driver 'omap_hsmmc’␍␊

[11:41:14:801] Some drivers were not found␍␊

[11:41:14:803] Reset Source: Power-on reset has occurred.␍␊

[11:41:14:808] MMC: OMAP SD/MMC: 0, OMAP SD/MMC: 1␍␊

[11:41:14:812] Using default environment␍␊

[11:41:14:812] ␍␊

[11:41:14:874] Board: BeagleBone Black␍␊

[11:41:14:878] not set. Validating first E-fuse MAC␍␊

[11:41:14:934] BeagleBone Black:␍␊

[11:41:14:938] BeagleBone: cape eeprom: i2c_probe: 0x54:␍␊

[11:41:14:943] BeagleBone: cape eeprom: i2c_probe: 0x55:␍␊

[11:41:14:947] BeagleBone: cape eeprom: i2c_probe: 0x56:␍␊

[11:41:14:952] BeagleBone: cape eeprom: i2c_probe: 0x57:␍␊

[11:41:14:955] Net: eth0: MII MODE␍␊

[11:41:14:961] cpsw␍␊

[11:41:14:964] Press SPACE to abort autoboot in 2 seconds␍␊

[11:41:16:964] board_name=[A335BNLT] …␍␊

[11:41:16:970] board_rev=[00C0] …␍␊

[11:41:17:309] switch to partitions #0, OK␍␊

[11:41:17:309] mmc0 is current device␍␊

[11:41:17:385] SD/MMC found on device 0␍␊

[11:41:17:385] ** Bad device 0:2 0x82000000 **␍␊

[11:41:17:385] ** Bad device 0:2 0x82000000 **␍␊

[11:41:17:454] switch to partitions #0, OK␍␊

[11:41:17:457] mmc0 is current device␍␊

[11:41:17:548] Scanning mmc 0:1…␍␊

[11:41:17:960] gpio: pin 56 (gpio 56) value is 0␍␊

[11:41:17:965] gpio: pin 55 (gpio 55) value is 0␍␊

[11:41:17:966] gpio: pin 54 (gpio 54) value is 0␍␊

[11:41:17:971] gpio: pin 53 (gpio 53) value is 1␍␊

[11:41:18:042] switch to partitions #0, OK␍␊

[11:41:18:046] mmc0 is current device␍␊

[11:41:18:115] gpio: pin 54 (gpio 54) value is 1␍␊

[11:41:18:333] Checking for: /uEnv.txt …␍␊

[11:41:18:369] Checking for: /boot.scr …␍␊

[11:41:18:404] Checking for: /boot/boot.scr …␍␊

[11:41:18:464] Checking for: /boot/uEnv.txt …␍␊

[11:41:18:520] gpio: pin 55 (gpio 55) value is 1␍␊

[11:41:18:576] 2141 bytes read in 49 ms (42 KiB/s)␍␊

[11:41:18:581] Loaded environment from /boot/uEnv.txt␍␊

[11:41:18:586] Checking if uname_r is set in /boot/uEnv.txt…␍␊

[11:41:18:590] gpio: pin 56 (gpio 56) value is 1␍␊

[11:41:18:594] Running uname_boot …␍␊

[11:41:18:653] loading /boot/vmlinuz-4.4.87-ti-rt-r121 …␍␊

[11:41:19:263] 8725520 bytes read in 602 ms (13.8 MiB/s)␍␊

[11:41:19:269] uboot_overlays: [uboot_base_dtb=am335x-boneblack-uboot.dtb] …␍␊

[11:41:19:360] uboot_overlays: Switching too: dtb=am335x-boneblack-uboot.dtb …␍␊

[11:41:19:451] loading /boot/dtbs/4.4.87-ti-rt-r121/am335x-boneblack-uboot.dtb …␍␊

[11:41:19:547] 53128 bytes read in 86 ms (602.5 KiB/s)␍␊

[11:41:19:553] uboot_overlays: [fdt_buffer=0x60000] …␍␊

[11:41:19:800] uboot_overlays: loading /lib/firmware/AM335X-20-00A0.dtbo …␍␊

[11:41:20:048] 378 bytes read in 238 ms (1000 Bytes/s)␍␊

[11:41:20:289] uboot_overlays: loading /lib/firmware/BB-BONE-eMMC1-01-00A0.dtbo …␍␊

[11:41:20:525] 1105 bytes read in 226 ms (3.9 KiB/s)␍␊

[11:41:20:536] uboot_overlays: uboot loading of [/lib/firmware/BB-HDMI-TDA998x-00A0.dtbo] disabled by /boot/uEnv.txt [disable_uboot_overlay_video=1]…␍␊

[11:41:20:611] uboot_overlays: loading /lib/firmware/BB-ADC-00A0.dtbo …␍␊

[11:41:20:679] 695 bytes read in 58 ms (10.7 KiB/s)␍␊

[11:41:20:962] uboot_overlays: loading /lib/firmware/AM335X-PRU-UIO-00A0.dtbo …␍␊

[11:41:21:241] 853 bytes read in 269 ms (2.9 KiB/s)␍␊

[11:41:21:294] uboot_overlays: loading /lib/firmware/univ-bbb-Exx-00A0.dtbo …␍␊

[11:41:21:347] 92817 bytes read in 43 ms (2.1 MiB/s)␍␊

[11:41:22:542] loading /boot/initrd.img-4.4.87-ti-rt-r121 …␍␊

[11:41:22:977] 5921265 bytes read in 426 ms (13.3 MiB/s)␍␊

[11:41:22:985] debug: [console=ttyO0,115200n8 bone_capemgr.uboot_capemgr_enabled=1 root=/dev/mmcblk0p1 ro rootfstype=ext4 rootwait coherent_pool=1M net.ifnames=0 quiet init=/lib/systemd/systemd cape_universal=enable] …␍␊

[11:41:23:004] debug: [bootz 0x82000000 0x88080000:5a59f1 88000000] …␍␊

[11:41:23:011] ## Flattened Device Tree blob at 88000000␍␊

[11:41:23:015] Booting using the fdt blob at 0x88000000␍␊

[11:41:23:018] Loading Ramdisk to 8fa5a000, end 8ffff9f1 … OK␍␊

[11:41:23:085] reserving fdt memory region: addr=88000000 size=7a000␍␊

[11:41:23:089] Loading Device Tree to 8f9dd000, end 8fa59fff … OK␍␊

[11:41:23:105] ␍␊

[11:41:23:107] Starting kernel …␍␊

[11:41:23:107] ␍␊

[11:41:26:070] [ 0.002366] clocksource_probe: no matching clocksources found␍␊

[11:41:26:077] [ 2.520273] wkup_m3_ipc 44e11324.wkup_m3_ipc: could not get rproc handle␍␊

[11:41:26:347] [ 2.807393] omap_voltage_late_init: Voltage driver support not added␍␊

[11:41:26:362] [ 2.822380] PM: Cannot get wkup_m3_ipc handle␍␊

[11:43:14:563] rootfs: recovering journal␍␊

[11:43:15:897] rootfs: clean, 44356/217728 files, 416930/869376 blocks␍␊

[11:43:44:465] [<0x1b>[0m<0x1b>[0;31m* <0x1b>[0m] (1 of 3) A start job is running for dev-ttyS0.device (27s / 1min 30s)␍<0x1b>[K[<0x1b>[0;32m OK <0x1b>[0m] Found device /dev/ttyS0.␍␊

[11:43:49:102] [<0x1b>[0;32m OK <0x1b>[0m] Started Serial Getty on ttyS0.␍␊

[11:43:50:297] ␍␍␊

`

Any ideas what’s happening between these two lines?

Thanks,
Alexander

That seems logical, but the same problem still happens after a correct sudo poweroff.

I also updated the /etc/fstab to skip the file system tests but without success.

I figured out that is caused by the RT_PREEMPT kernel. However, I still have no clue why this happens.

The boot hangs at a different position when I enable eMMC flashing:

[17:19:14:140] [ 4.730493] wkup_m3_ipc 44e11324.wkup_m3_ipc: CM3 Firmware Version = 0x192␍␊

[17:19:14:197] Loading, please wait…␍␊

[17:19:14:301] starting version 232␍␊

[17:19:14:309] [ 4.908472] random: systemd-udevd: uninitialized urandom read (16 bytes read, 3 bits of entropy available)␍␊

[17:19:14:337] [ 4.932103] random: systemd-udevd: uninitialized urandom read (16 bytes read, 3 bits of entropy available)␍␊

[17:19:14:358] [ 4.937269] random: udevadm: uninitialized urandom read (16 bytes read, 3 bits of entropy available)␍␊

[17:19:14:373] [ 4.937739] random: udevadm: uninitialized urandom read (16 bytes read, 3 bits of entropy available)␍␊

[17:19:14:392] [ 4.942139] random: udevadm: uninitialized urandom read (16 bytes read, 3 bits of entropy available)␍␊

[17:19:14:414] [ 4.943209] random: udevadm: uninitialized urandom read (16 bytes read, 3 bits of entropy available)␍␊

[17:19:14:425] [ 4.943971] random: udevadm: uninitialized urandom read (16 bytes read, 3 bits of entropy available)␍␊

[17:19:14:442] [ 4.944667] random: udevadm: uninitialized urandom read (16 bytes read, 3 bits of entropy available)␍␊

[17:19:14:464] [ 4.945336] random: udevadm: uninitialized urandom read (16 bytes read, 3 bits of entropy available)␍␊

[17:19:14:484] [ 4.950296] random: udevadm: uninitialized urandom read (16 bytes read, 3 bits of entropy available)␍␊

[17:21:07:358] Begin: Loading essential drivers … done.␍␊

[17:21:07:364] Begin: Running /scripts/init-premount … done.␍␊

[17:21:07:367] Begin: Mounting root file system … Begin: Running /scripts/local-top … done.␍␊

[17:21:07:390] Begin: Running /scripts/local-premount … done.␍␊

[17:21:07:462] Begin: Will now check root file system … fsck from util-linux 2.29.2␍␊

[17:21:07:566] [/sbin/fsck.ext4 (1) – /dev/mmcblk0p1] fsck.ext4 -a -C0 /dev/mmcblk0p1 ␍␊

[17:21:07:589] rootfs: recovering journal␍␊

[17:21:07:909] rootfs: clean, 59570/217728 files, 479942/869376 blocks␍␊

[17:21:07:927] done.␍␊

[17:21:07:955] [ 118.559094] EXT4-fs (mmcblk0p1): mounted filesystem with ordered data mode. Opts: (null)␍␊

I’m still unsure whats causing the problems.

I found a workaround for the problem.

The problems seems to be related to the images I built with the
setup_sdcard script. I used the Debian Stretch console image builder 9.2
with the following command:

./setup_sdcard.sh --dtb beaglebone --enable-cape-universal
–enable-uboot-cape-overlays --boot_label SandyBox --enable-systemd
–hostname sandybox --img-4gb test.img

With the prebuilt image, everything works as expected. For me this
solution is okay.

My best guess is that it has to do with the boot_label, but I have no clue why it should only cause trouble with the RT kernels.

Hi Alexander,

I found a workaround for the problem.

The problems seems to be related to the images I built with the
setup_sdcard script. I used the Debian Stretch console image builder 9.2
with the following command:

./setup_sdcard.sh --dtb beaglebone --enable-cape-universal
--enable-uboot-cape-overlays --boot_label SandyBox --enable-systemd
--hostname sandybox --img-4gb test.img

With the prebuilt image, everything works as expected. For me this
solution is okay.

My best guess is that it has to do with the boot_label, but I have no clue
why it should only cause trouble with the RT kernels.

It also could be the "--enable-systemd" that was only for the old
"wheezy", since jessie systemd has been the default and the flag my
change something else..

if [ "x${enable_systemd}" = "xenabled" ] ; then
       cmdline="${cmdline} init=/lib/systemd/systemd"
fi

i'll test that locally too...

Regards,

Nope, that didn't make a difference:

debian@sandybox:~$ uname -r
4.9.56-bone-rt-r7

debian@sandybox:~$ cat /proc/cmdline
console=ttyO0,115200n8 bone_capemgr.uboot_capemgr_enabled=1
root=/dev/mmcblk0p1 ro rootfstype=ext4 rootwait coherent_pool=1M
net.ifnames=0 quiet init=/lib/systemd/systemd cape_universal=enable

[ 4.573940] ALSA device list:
[ 4.573948] #0: TI BeagleBone Black
[ 4.575942] Freeing unused kernel memory: 1024K
[ 37.414498] EXT4-fs (mmcblk0p1): mounted filesystem with ordered
data mode. Opts: (null)
[ 37.991016] ip_tables: (C) 2000-2006 Netfilter Core Team

debian@sandybox:~$ cat /proc/cmdline
console=ttyO0,115200n8 bone_capemgr.uboot_capemgr_enabled=1
root=/dev/mmcblk0p1 ro rootfstype=ext4 rootwait coherent_pool=1M
net.ifnames=0 quiet cape_universal=enable

[ 4.573685] ALSA device list:
[ 4.573870] #0: TI BeagleBone Black
[ 4.575851] Freeing unused kernel memory: 1024K
[ 34.504317] EXT4-fs (mmcblk0p1): mounted filesystem with ordered
data mode. Opts: (null)
[ 35.085202] ip_tables: (C) 2000-2006 Netfilter Core Team

Regards,

Bingo, it's the initrd.img.. This is only really needed for 3.8.13,
"kernel overlays" (which are now, not recommended)..

[ 4.133706] PM: Hibernation image not present or could not be loaded.
[ 4.133987] ALSA device list:
[ 4.133997] #0: TI BeagleBone Black
[ 4.147398] EXT4-fs (mmcblk0p1): mounted filesystem with ordered
data mode. Opts: (null)
[ 4.147467] VFS: Mounted root (ext4 filesystem) readonly on device 179:1.

So double check:

cat /proc/cmdline

that's using, root=/dev/mmcblk*

and that /etc/fstab

has "/dev/mmcblk*"

(aka no UUID)

Then your safe to do:

sudo rm /boot/initrd.img-4.*

I'll keep testing, as something in the initrd is blocking the RT kernel..

Regards,

Really appreciate you answer… my beaglebone now boots 1:30 faster. Did you figure out the course in the initrd?

`

[11:43:14:563] rootfs: recovering journal␍␊

perhaps your system was shut down without unmounting the file system?

`