Boot to Python

I’m attending Sketching in Hardware this weekend and there was a fair bit of discussion regarding how long it takes to boot Linux and barriers it makes to understanding a system. My assertion was that booting Linux on a computer, like PocketBeagle, doesn’t take very long at all and that it generally only gets in the way when you want it.

Here’s what I hacked up in about 10 minutes to show off how we can get a whole lot of distribution code out-of-the-way.

In /boot/uEnv.txt, I edited the cmdline:

cmdline=coherent_pool=1M net.ifnames=0 rng_core.default_quality=100 quiet **modules-load=g_serial**

The point of this is that our boot script that configures the USB gadget won’t be loaded anymore. This causes the Linux kernel to emulate a serial port, providing a way to get to the Python REPL.

In /etc/passwd, I edited the shell for the ‘debian’ user:

debian:x:1000:1000:Demo User:/home/debian:**/usr/bin/python3**

This makes python3 the default shell for the ‘debian’ user, so whenever a user logs in as ‘debian’, they get a python3 REPL.

In /lib/systemd/system/serial-getty@.service, I enabled a bypass for the user login password request:

ExecStart=-/sbin/agetty --keep-baud 115200,38400,9600 %I $TERM **-a debian**

This totally insecure, but on PocketBeagle without any augmentation, this just gives access over the USB port. Seems pretty reasonable to me.

I executed the following commands to reduce the applications running at startup and enable the terminal on the virtual serial port:

sudo systemctl set-default rescue.target
sudo ln -s /lib/systemd/system/serial-getty@.service /etc/systemd/system/default.target.wants/serial-getty@ttyGS0.service

When you do the above, a reboot will no longer bring up things like the Cloud9 IDE, so be sure to run both commands before rebooting. Use ‘sudo shutdown -r now’ to reboot.

Seems like there’s still a fair amount of optimization that can be done, but here’s the behavior I saw when pulling and re-inserting the USB cable after making these changes:

jkridner@tupper:~$ **journalctl -f**
Sep 28 13:55:52 tupper kernel: usb 1-4: USB disconnect, device number 26
 Sep 28 13:55:52 tupper upowerd[2124]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:14.0/usb1/1-4/1-4:2.1
 Sep 28 13:55:52 tupper upowerd[2124]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:14.0/usb1/1-4/1-4:2.0
 Sep 28 13:55:52 tupper upowerd[2124]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:14.0/usb1/1-4
 Sep 28 13:56:08 tupper kernel: usb 1-4: new high-speed USB device number 27 using xhci_hcd
 Sep 28 13:56:08 tupper kernel: usb 1-4: New USB device found, idVendor=0525, idProduct=a4a7
 Sep 28 13:56:08 tupper kernel: usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
 Sep 28 13:56:08 tupper kernel: usb 1-4: Product: Gadget Serial v2.4
 Sep 28 13:56:08 tupper kernel: usb 1-4: Manufacturer: Linux 4.14.108-ti-r113 with musb-hdrc
 Sep 28 13:56:08 tupper kernel: cdc_acm 1-4:2.0: ttyACM0: USB ACM device

So, without any other tweaking, it seems to still be taking about 16 seconds. I’m not very happy with this, so I’ll be hooking up a serial cable and figuring out where the time goes soon.

jkridner@tupper:~$ **tio /dev/ttyACM0**
[tio 14:02:10] tio v1.29
[tio 14:02:10] Press ctrl-t q to quit
[tio 14:02:10] Connected

  File "", line 0
    
    ^
SyntaxError: 'utf-8' codec can't decode byte 0xf0 in position 2: invalid continuation byte
>>> quit()

Debian GNU/Linux 9 beaglebone ttyGS0

BeagleBoard.org Debian Image 2019-08-03

Support/FAQ: [http://elinux.org/Beagleboard:BeagleBoneBlack_Debian](http://elinux.org/Beagleboard:BeagleBoneBlack_Debian)

default username:password is [debian:temppwd]

beaglebone login: debian (automatic login)

Last login: Sun Aug  4 02:10:35 UTC 2019 on ttyGS0

The programs included with the Debian GNU/Linux system are free software;
the exact distribution terms for each program are described in the
individual files in /usr/share/doc/*/copyright.

Debian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent
permitted by applicable law.
Python 3.5.3 (default, Sep 27 2018, 17:25:39) 
[GCC 6.3.0 20170516] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> **import os**
>>> **os.system("bash")**
debian@beaglebone:~$ 

I chose to use ‘tio’, but ‘screen’ and other serial utilities would work fine.

I don’t actually know that the cause of the stray characters is. Someone can probably enlighten me.

I’ll release this as a blog post once I figure out why the boot time is this slow, but I thought this was interesting enough to post here. Enjoy.

Very interesting concept.

Thanks for sharing your proof of concept.

Tell everyone at sketching hello!
Drew

A quick grabserial log:

[0.000001 0.000001] 
[0.000084 0.000083] U-Boot SPL 2019.04-00002-gbb4af0f50f (Jul 08 2019 - 11:44:39 -0500)
[0.048198 0.048114] Trying to boot from MMC1
[0.128443 0.080245] Loading Environment from EXT4... ** File not found /boot/uboot.env **
[0.176759 0.048316] 
[0.176803 0.000044] ** Unable to read "/boot/uboot.env" from mmc0:1 **
[0.257320 0.080517] 
[0.257422 0.000102] 
[0.257473 0.000051] U-Boot 2019.04-00002-gbb4af0f50f (Jul 08 2019 - 11:44:39 -0500), Build: jenkins-github_Bootloader-Builder-128
[0.261285 0.003812] 
[0.261331 0.000046] CPU  : AM335X-GP rev 2.1
[0.262184 0.000853] I2C:   ready
[0.305677 0.043493] DRAM:  512 MiB
[0.353349 0.047672] No match for driver 'omap_hsmmc'
[0.354567 0.001218] No match for driver 'omap_hsmmc'
[0.392303 0.037736] Some drivers were not found
[0.393526 0.001223] Reset Source: Global external warm reset has occurred.
[0.396006 0.002480] Reset Source: Power-on reset has occurred.
[0.398008 0.002002] RTC 32KCLK Source: Internal.
[0.399596 0.001588] MMC:   OMAP SD/MMC: 0, OMAP SD/MMC: 1
[0.401448 0.001852] Loading Environment from EXT4... ** File not found /boot/uboot.env **
[0.500941 0.099493] 
[0.500992 0.000051] ** Unable to read "/boot/uboot.env" from mmc0:1 **
[0.574400 0.073408] Model: BeagleBoard.org PocketBeagle
[0.575353 0.000953] <ethaddr> not set. Validating first E-fuse MAC
[0.576464 0.001111] Net:   usb_ether
[0.576935 0.000471] Press SPACE to abort autoboot in 2 seconds
[2.559828 1.982893] board_name=[A335PBGL] ...

Only a 1/2s of waste up to here. The 2s delay is intentional. I'm tempted to set the boot environment and BOOTDELAY to clear this one.
[2.656112 0.096284] switch to partitions #0, OK
[2.657331 0.001219] mmc0 is current device
[2.736225 0.078894] SD/MMC found on device 0
[2.762987 0.026762] gpio: pin 56 (gpio 56) value is 0
[2.764810 0.001823] gpio: pin 55 (gpio 55) value is 0
[2.766536 0.001726] gpio: pin 54 (gpio 54) value is 0
[2.768192 0.001656] gpio: pin 53 (gpio 53) value is 1
[2.770000 0.001808] starting USB...
[2.770900 0.000900] USB0:   Port not available.
[3.755765 0.984865] gpio: pin 54 (gpio 54) value is 1

hmmm.... that's quite a delay. This also seems like a good candidate for elimination with configuring the boot environment.
[3.771881 0.016116] Checking for: /boot/uEnv.txt ...
[3.877247 0.105366] switch to partitions #0, OK
[3.878375 0.001128] mmc0 is current device
[3.879302 0.000927] gpio: pin 56 (gpio 56) value is 0
[3.880383 0.001081] gpio: pin 55 (gpio 55) value is 0
[3.881447 0.001064] gpio: pin 54 (gpio 54) value is 0
[3.882650 0.001203] gpio: pin 53 (gpio 53) value is 1
[3.957024 0.074374] switch to partitions #0, OK
[3.958922 0.001898] mmc0 is current device
[4.036965 0.078043] gpio: pin 54 (gpio 54) value is 1
[4.117177 0.080212] Checking for: /uEnv.txt ...
[4.149090 0.031913] Checking for: /boot.scr ...
[4.165031 0.015941] Checking for: /boot/boot.scr ...
[4.180923 0.015892] Checking for: /boot/uEnv.txt ...
[4.213085 0.032162] gpio: pin 55 (gpio 55) value is 1
[4.245069 0.031984] 2340 bytes read in 34 ms (66.4 KiB/s)
[4.246042 0.000973] Loaded environment from /boot/uEnv.txt
[4.278298 0.032256] debug: [dtb=am335x-pocketbeagle.dtb] ...
[4.280809 0.002511] Using: dtb=am335x-pocketbeagle.dtb ...
[4.283421 0.002612] Checking if uname_r is set in /boot/uEnv.txt...
[4.286133 0.002712] gpio: pin 56 (gpio 56) value is 1
[4.288118 0.001985] Running uname_boot ...
[4.293022 0.004904] loading /boot/vmlinuz-4.14.108-ti-r113 ...
[4.949998 0.656976] 9929216 bytes read in 657 ms (14.4 MiB/s)

Pretty big kernel, but not too bad to spend 1/2s here. Almost 10M. A trimmed kernel would still be about 2M. A possible place to optimize, but one with big trade-offs.
[4.966652 0.016654] debug: [enable_uboot_overlays=] ...
[5.002822 0.036170] loading /boot/dtbs/4.14.108-ti-r113/am335x-pocketbeagle.dtb ...
[5.064918 0.062096] 124423 bytes read in 54 ms (2.2 MiB/s)
[5.066676 0.001758] uboot_overlays: add [enable_uboot_overlays=1] to /boot/uEnv.txt to enable...
[5.080701 0.014025] loading /boot/initrd.img-4.14.108-ti-r113 ...
[5.455137 0.374436] 4696515 bytes read in 326 ms (13.7 MiB/s)

If we aren't really running from this initrd, why spend the time to load it?
[5.457428 0.002291] debug: [console=ttyO0,115200n8 root=/dev/mmcblk0p1 ro rootfstype=ext4 rootwait coherent_pool=1M net.ifnames=0 rng_core.default_quality=100 quiet modules-load=g_serial] ...
[5.464145 0.006717] debug: [bootz 0x82000000 0x88080000:47a9c3 0x88000000] ...
[5.466492 0.002347] ## Flattened Device Tree blob at 88000000
[5.467819 0.001327]    Booting using the fdt blob at 0x88000000
[5.469190 0.001371]    Loading Ramdisk to 8fb85000, end 8ffff9c3 ... OK
[5.487277 0.018087]    Loading Device Tree to 8fb63000, end 8fb84606 ... OK
[5.503357 0.016080] 
[5.503431 0.000074] Starting kernel ...
[5.504097 0.000666] 
[7.040070 1.535973] [    0.001542] timer_probe: no matching timers found

1.5s to before the kernel starts printing messages? Is this mostly due to decompression? Certainly something to pay attention to here.
[7.062996 0.022926] [    0.936616] wkup_m3_ipc 44e11324.wkup_m3_ipc: could not get rproc handle
[7.237535 0.174539] [    1.137073] omap_voltage_late_init: Voltage driver support not added
[7.260652 0.023117] [    1.144372] PM: Cannot get wkup_m3_ipc handle
[7.307415 0.046763] [    1.208281] PM: Cannot get wkup_m3_ipc handle
[7.769046 0.461631] [    1.651529] musb-hdrc musb-hdrc.1: VBUS_ERROR in a_wait_vrise (80, <SessEnd), retry #3, port1 0008010c

Hmmm.... would this go away if I had something connected?
[12.556108 4.787062] rootfs: recovering journal

Ugh. Now this is serious. Should I have the file system mounted read-only and only have Python scripts switch it to writable as-needed? I cannot expect people will perform consistent graceful shutdowns.
[12.636161 0.080053] rootfs: clean, 83681/230144 files, 589372/920576 blocks
[18.112197 5.476036] You are in rescue mode. After logging in, type "journalctl -xb" Give root password for maintenance 

Hmmm. What am I missing about what is going on here? Is this more file system work or something else in the system. I probably need to overlay a systemd report here...

[18.304912 0.192715] (or press Control-D to continue):

root@beaglebone:~# systemd-analyze
Startup finished in 7.153s (kernel) + 4.770s (userspace) = 11.924s

root@beaglebone:~# systemd-analyze blame
10.874s dev-mmcblk0p1.device
2.791s systemd-udev-trigger.service
2.124s keyboard-setup.service
1.175s systemd-journald.service
704ms systemd-modules-load.service
682ms systemd-tmpfiles-setup-dev.service
565ms sys-kernel-debug.mount
548ms systemd-random-seed.service
545ms systemd-timesyncd.service
414ms systemd-sysctl.service
382ms kmod-static-nodes.service
381ms systemd-udevd.service
323ms systemd-remount-fs.service
255ms dev-mqueue.mount
241ms sys-kernel-config.mount
238ms systemd-update-utmp.service
227ms sys-fs-fuse-connections.mount
223ms systemd-tmpfiles-setup.service
207ms systemd-journal-flush.service
174ms systemd-update-utmp-runlevel.service

OK then. Booting from microSD on an unclean filesystem is rough. Thoughts?

A quick grabserial log:

[0.000001 0.000001]
[0.000084 0.000083] U-Boot SPL 2019.04-00002-gbb4af0f50f (Jul 08 2019 - 11:44:39 -0500)
[0.048198 0.048114] Trying to boot from MMC1
[0.128443 0.080245] Loading Environment from EXT4... ** File not found /boot/uboot.env **
[0.176759 0.048316]
[0.176803 0.000044] ** Unable to read "/boot/uboot.env" from mmc0:1 **
[0.257320 0.080517]
[0.257422 0.000102]
[0.257473 0.000051] U-Boot 2019.04-00002-gbb4af0f50f (Jul 08 2019 - 11:44:39 -0500), Build: jenkins-github_Bootloader-Builder-128
[0.261285 0.003812]
[0.261331 0.000046] CPU : AM335X-GP rev 2.1
[0.262184 0.000853] I2C: ready
[0.305677 0.043493] DRAM: 512 MiB
[0.353349 0.047672] No match for driver 'omap_hsmmc'
[0.354567 0.001218] No match for driver 'omap_hsmmc'
[0.392303 0.037736] Some drivers were not found
[0.393526 0.001223] Reset Source: Global external warm reset has occurred.
[0.396006 0.002480] Reset Source: Power-on reset has occurred.
[0.398008 0.002002] RTC 32KCLK Source: Internal.
[0.399596 0.001588] MMC: OMAP SD/MMC: 0, OMAP SD/MMC: 1
[0.401448 0.001852] Loading Environment from EXT4... ** File not found /boot/uboot.env **
[0.500941 0.099493]
[0.500992 0.000051] ** Unable to read "/boot/uboot.env" from mmc0:1 **
[0.574400 0.073408] Model: BeagleBoard.org PocketBeagle
[0.575353 0.000953] <ethaddr> not set. Validating first E-fuse MAC
[0.576464 0.001111] Net: usb_ether
[0.576935 0.000471] Press SPACE to abort autoboot in 2 seconds
[2.559828 1.982893] board_name=[A335PBGL] ...

Only a 1/2s of waste up to here. The 2s delay is intentional. I'm tempted to set the boot environment and BOOTDELAY to clear this one.

I believe this is a waste too, i'd like to nuke the whole 2s delay,
the space bar can still abort it, but most users never buy a serial
cable...

[2.656112 0.096284] switch to partitions #0, OK
[2.657331 0.001219] mmc0 is current device
[2.736225 0.078894] SD/MMC found on device 0
[2.762987 0.026762] gpio: pin 56 (gpio 56) value is 0
[2.764810 0.001823] gpio: pin 55 (gpio 55) value is 0
[2.766536 0.001726] gpio: pin 54 (gpio 54) value is 0
[2.768192 0.001656] gpio: pin 53 (gpio 53) value is 1
[2.770000 0.001808] starting USB...
[2.770900 0.000900] USB0: Port not available.
[3.755765 0.984865] gpio: pin 54 (gpio 54) value is 1

hmmm.... that's quite a delay. This also seems like a good candidate for elimination with configuring the boot environment.

I nuked the USB0 path yesterday, as the resolve isn't going to ship...

[3.771881 0.016116] Checking for: /boot/uEnv.txt ...
[3.877247 0.105366] switch to partitions #0, OK
[3.878375 0.001128] mmc0 is current device
[3.879302 0.000927] gpio: pin 56 (gpio 56) value is 0
[3.880383 0.001081] gpio: pin 55 (gpio 55) value is 0
[3.881447 0.001064] gpio: pin 54 (gpio 54) value is 0
[3.882650 0.001203] gpio: pin 53 (gpio 53) value is 1
[3.957024 0.074374] switch to partitions #0, OK
[3.958922 0.001898] mmc0 is current device
[4.036965 0.078043] gpio: pin 54 (gpio 54) value is 1
[4.117177 0.080212] Checking for: /uEnv.txt ...
[4.149090 0.031913] Checking for: /boot.scr ...
[4.165031 0.015941] Checking for: /boot/boot.scr ...
[4.180923 0.015892] Checking for: /boot/uEnv.txt ...
[4.213085 0.032162] gpio: pin 55 (gpio 55) value is 1
[4.245069 0.031984] 2340 bytes read in 34 ms (66.4 KiB/s)
[4.246042 0.000973] Loaded environment from /boot/uEnv.txt
[4.278298 0.032256] debug: [dtb=am335x-pocketbeagle.dtb] ...
[4.280809 0.002511] Using: dtb=am335x-pocketbeagle.dtb ...
[4.283421 0.002612] Checking if uname_r is set in /boot/uEnv.txt...
[4.286133 0.002712] gpio: pin 56 (gpio 56) value is 1
[4.288118 0.001985] Running uname_boot ...
[4.293022 0.004904] loading /boot/vmlinuz-4.14.108-ti-r113 ...
[4.949998 0.656976] 9929216 bytes read in 657 ms (14.4 MiB/s)

Pretty big kernel, but not too bad to spend 1/2s here. Almost 10M. A trimmed kernel would still be about 2M. A possible place to optimize, but one with big trade-offs.

[4.966652 0.016654] debug: [enable_uboot_overlays=] ...
[5.002822 0.036170] loading /boot/dtbs/4.14.108-ti-r113/am335x-pocketbeagle.dtb ...
[5.064918 0.062096] 124423 bytes read in 54 ms (2.2 MiB/s)
[5.066676 0.001758] uboot_overlays: add [enable_uboot_overlays=1] to /boot/uEnv.txt to enable...
[5.080701 0.014025] loading /boot/initrd.img-4.14.108-ti-r113 ...
[5.455137 0.374436] 4696515 bytes read in 326 ms (13.7 MiB/s)

If we aren't really running from this initrd, why spend the time to load it?

remove the "/boot/initrd.img-4.14.108-ti-r113" file and u-boot will
skip loading it..

[5.457428 0.002291] debug: [console=ttyO0,115200n8 root=/dev/mmcblk0p1 ro rootfstype=ext4 rootwait coherent_pool=1M net.ifnames=0 rng_core.default_quality=100 quiet modules-load=g_serial] ...
[5.464145 0.006717] debug: [bootz 0x82000000 0x88080000:47a9c3 0x88000000] ...
[5.466492 0.002347] ## Flattened Device Tree blob at 88000000
[5.467819 0.001327] Booting using the fdt blob at 0x88000000
[5.469190 0.001371] Loading Ramdisk to 8fb85000, end 8ffff9c3 ... OK
[5.487277 0.018087] Loading Device Tree to 8fb63000, end 8fb84606 ... OK
[5.503357 0.016080]
[5.503431 0.000074] Starting kernel ...
[5.504097 0.000666]
[7.040070 1.535973] [ 0.001542] timer_probe: no matching timers found

1.5s to before the kernel starts printing messages? Is this mostly due to decompression? Certainly something to pay attention to here.

So we use LZO, maybe it's time to switch to LZ4:

  │ LZ4 is an LZ77-type compressor with a fixed, byte-oriented
encoding.
                                      │
  │ A preliminary version of LZ4 de/compression tool is available at

                              │
  │ <GitHub - lz4/lz4: Extremely Fast Compression algorithm.

                              │
  │

                              │
  │ Its compression ratio is worse than LZO. The size of the kernel

                              │
  │ is about 8% bigger than LZO. But the decompression speed is

                              │
  │ faster than LZO.

As of Debian Buster, LZ4 is now pretty stable:

https://packages.debian.org/source/buster/lz4

> 1.5s to before the kernel starts printing messages? Is this mostly due to decompression? Certainly something to pay attention to here.

So we use LZO, maybe it's time to switch to LZ4:

  │ LZ4 is an LZ77-type compressor with a fixed, byte-oriented

As of Debian Buster, LZ4 is now pretty stable:

Debian -- Details of source package lz4 in buster

Nope, while lz4 is "faster" at decompression, it's not faster then
lzo, due to the vmlinuz size:

lz4:

[0.029385 0.029385] loading /boot/vmlinuz-5.4.0-rc2-bone0.1 ...
[0.724044 0.694659] 9044480 bytes read in 652 ms (13.2 MiB/s)
[0.724719 0.000675] debug: [enable_uboot_overlays=1] ...

[0.002140 0.002140] debug: [bootz 0x82000000 - 88000000] ...
[0.002576 0.000436] ## Flattened Device Tree blob at 88000000
[0.003020 0.000444] Booting using the fdt blob at 0x88000000
[0.003481 0.000461] Loading Device Tree to 8ff68000, end 8fffffff ... OK
[0.015984 0.012503]
[0.016097 0.000113] Starting kernel ...
[0.016451 0.000354]
[1.852331 1.835880] [ 0.000000] Booting Linux on physical CPU 0x0

Total: 2.57705

lzo:

[0.027253 0.027253] loading /boot/vmlinuz-5.4.0-rc2-bone0.1 ...
[0.693089 0.665836] 8581632 bytes read in 623 ms (13.1 MiB/s)
[0.694399 0.001310] debug: [enable_uboot_overlays=1] ...

[0.004443 0.004443] debug: [bootz 0x82000000 - 88000000] ...
[0.005406 0.000963] ## Flattened Device Tree blob at 88000000
[0.006403 0.000997] Booting using the fdt blob at 0x88000000
[0.007432 0.001029] Loading Device Tree to 8ff68000, end 8fffffff ... OK
[0.015855 0.008423]
[0.015896 0.000041] Starting kernel ...
[0.016128 0.000232]
[1.874360 1.858232] [ 0.000000] Booting Linux on physical CPU 0x0

Total: 2.568759

lzo - lz4 = -0.008291

So in our case lzo is 8.3ms faster.. (and 0.5 MB smaller..)

Regards,

A couple of tips for faster booting:
Disable any device probing that isn’t critical. Probing for USB and SD cards that aren’t there isn’t helpful. Maybe the DTB helps. It’ll be faster to load additional modules once the kernel is initialized.
Disable networking helps as I think you saw.

You can eliminate fsck (filesystem) checks by putting the system files on a read only partition, and the user code on a read write. Using a overlay or union file system if needed, to get around third party softwares that don’t conform to the LSB (Linux standards base for file system layout).

You can delay the fsck of the user file system to after the system is booted. And file system checks can be parallelized and backgrounded.

Using a file system journal will speed up checks.
There are flash specific file system that can offer better performance.

One discovery of mine was that when writing compact flash and SD cards it was faster to decompress the file on the fly than work with the uncompressed file system image. This appeared to be due to a couple of effects, i.e. fast cpus with L2 caches (Intel atom) can decompress faster than data can be transferred from ram. So this may or may not be a benefit. (This appeared to hold true with our TI OMAP firewall, but I didn’t spend as much time testing it).

I think I have my freebsd beagle bones booting in about 6 seconds… Linux should do a lot better.