Dear Steven,
I saw your great talk *The Resurrection of Ureadahead and Speeding up
the Boot Process and Preloading Applications* [1], and wanted to share
my findings with the Dell Latitude 5430 Chromebook
(google/brya/var/crota) running ChromeOS. The login screen is visible
after around six seconds, which is great compared to other GNU/Linux
laptop/desktop devices, and probably similar to Microsoft Windows and
Apple devices. (One second boot time would still be very nice – 0.5 s
firmware plus 0.5 s Linux/userspace. Systems (CPUs, SSDs) get faster and
faster, but power-on to graphical login does not.)
### Firmware (unrelated to Linux)
coreboot based firmware takes 1.1 seconds until loading the Linux kernel.¹
```
990:CSME ROM started execution 0
944:CSE sent 'Boot Stall Done' to PMC 71,000
945:CSE started to handle ICC configuration 71,000 (0)
946:CSE sent 'Host BIOS Prep Done' to PMC 73,000 (2,000)
947:CSE received 'CPU Reset Done Ack sent' from PMC 191,000 (118,000)
0:1st timestamp 226,794 (35,794)
[…]
1101:jumping to kernel 1,142,626 (17,740)
Total Time: 1,142,591
```
Cf *google/brya/var/crota: selfboot jump reached after 1.2 s* [2] with a
different longer run with more details.
### Linux kernel
I created bug #217962 in the Linux Kernel Bugzilla [3] and attached the
logs there.
This is:
[ 0.000000] Linux version 5.15.124-20278-ga3eed51cfa07
(chrome-bot@chromeos-release-builder-us-central1-b-x32-14-mesv)
(Chromium OS 17.0_pre496208_p20230501-r16 clang version 17.0.0
(/mnt/host/source/src/third_party/llvm-project
98f5a340975bc00197c57e39eb4ca26e2da0e8a2), LLD 17.0.0) #1 SMP PREEMPT
Wed Sep 27 18:36:41 PDT 2023
I am listing delays of several tens milliseconds.
All CPUs are brought up after 136 ms. No idea, if Thomas’ work on
parallel CPU bringup, added to Linux 6.5-rc1 [4], has a positive effect
on a 12 thread system.
```
[ 0.035501] smpboot: Allowing 12 CPUs, 0 hotplug CPUs
[…]
[ 0.042149] mem auto-init: stack:all(zero), heap alloc:on, heap free:off
[ 0.085764] Memory: 16159744K/16617488K available (16396K kernel
code, 2407K rwdata, 7444K rodata, 1904K init, 912K bss, 457484K
reserved, 0K cma-reserved)
[ 0.086049] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=12, Nodes=1
[ 0.086063] ftrace: allocating 53568 entries in 210 pages
[ 0.098541] ftrace: allocated 210 pages with 4 groups
[…]
[ 0.117600] x86: Booting SMP configuration:
[ 0.117600] .... node #0, CPUs: #1 #2 #3 #4
[…]
[ 0.125757] #5 #6 #7 #8 #9 #10 #11
[ 0.136741] smp: Brought up 1 node, 12 CPUs
```
Linux points out a problem with MTRR settings:
```
[ 0.138790] PCI: Using configuration type 1 for base access
[ 0.138909] mtrr: your CPUs had inconsistent variable MTRR settings
[ 0.138909] mtrr: probably your BIOS does not setup all CPUs.
[ 0.138909] mtrr: corrected configuration.
[ 0.140504] kprobes: kprobe jump-optimization is enabled. All kprobes
are optimized if possible.
```
Linux mentions an ACPI error:
```
[ 0.141312] ACPI BIOS Error (bug): Failure creating named object
[\_SB.MPTS], AE_ALREADY_EXISTS (20210730/dswload2-327)
[ 0.141317] ACPI Error: AE_ALREADY_EXISTS, During name lookup/catalog
(20210730/psobject-220)
[ 0.141319] ACPI: Skipping parse of AML opcode: OpcodeName
unavailable (0x0014)
```
There is a 160 ms delay in ACPI PR00/PR01 power resource logs:
```
[ 0.144968] ACPI: PM: Power Resource [RTD3]
[ 0.145246] ACPI: PM: Power Resource [PR00]
[ 0.308776] ACPI: PM: Power Resource [PR01]
[ 0.313974] ACPI: PM: Power Resource [TBT0]
[ 0.313981] ACPI: PM: Power Resource [TBT1]
[ 0.313989] ACPI: PM: Power Resource [D3C]
[ 0.339780] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
```
Another 68 ms delay:
```
[ 0.352921] PCI: Using ACPI for IRQ routing
[ 0.410211] PCI: pci_cache_line_size set to 64 bytes
```
Another 52 ms jump between Thunderbolt and RAPL PMU message:
```
[ 0.432117] DMAR: Intel(R) Virtualization Technology for Directed I/O
[ 0.432118] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[ 0.432119] software IO TLB: mapped [mem
0x000000006e865000-0x0000000076865000] (128MB)
[ 0.432129] ACPI: bus type thunderbolt registered
[ 0.432140] pci 0000:00:0d.2: attach allowed to drvr thunderbolt
[internal device]
[ 0.483161] pci 0000:00:0d.3: attach allowed to drvr thunderbolt
[internal device]
[ 0.535970] RAPL PMU: API unit is 2^-32 Joules, 4 fixed counters,
655360 ms ovfl timer
[ 0.535972] RAPL PMU: hw unit of domain pp0-core 2^-14 Joules
[ 0.535972] RAPL PMU: hw unit of domain package 2^-14 Joules
[ 0.535973] RAPL PMU: hw unit of domain pp1-gpu 2^-14 Joules
[ 0.535973] RAPL PMU: hw unit of domain psys 2^-14 Joules
[ 0.539576] kvm: already loaded the other module
[ 0.539578] clocksource: tsc: mask: 0xffffffffffffffff max_cycles:
0x23fa772cf26, max_idle_ns: 440795269835 ns
[ 0.539591] clocksource: Switched to clocksource tsc
```
A 100 ms delay between the cr50_i2c message and intel-lpss message:
```
[ 0.570925] i2c_designware i2c_designware.1: using ACPI for GPIO lookup
[ 0.570925] acpi device:17: GPIO: looking up scl-gpios
[ 0.570926] acpi device:17: GPIO: looking up scl-gpio
[ 0.570926] i2c_designware i2c_designware.1: using lookup tables for
GPIO lookup
[ 0.570927] i2c_designware i2c_designware.1: No GPIO consumer scl found
[ 0.574609] cr50_i2c i2c-GOOG0005:00: cr50 TPM 2.0 (i2c 0x50 irq 77
id 0x28)
[ 0.682100] pci 0000:00:15.2: attach allowed to drvr intel-lpss
[internal device]
[ 0.693828] intel-lpss 0000:00:15.2: enabling device (0000 -> 0002)
[ 0.697641] pci 0000:00:19.0: attach allowed to drvr intel-lpss
[internal device]
[ 0.709862] intel-lpss 0000:00:19.0: enabling device (0000 -> 0002)
[ 0.713679] pci 0000:00:1e.3: attach allowed to drvr intel-lpss
[internal device]
[ 0.726207] idma64 idma64.7: Found Intel integrated DMA 64-bit
[ 0.729180] pci 0000:01:00.0: attach allowed to drvr nvme [internal
device]
```
A 60 ms delay before the elan_i2c log message:
```
[ 0.790747] device-mapper: init: waiting for all devices to be
available before creating mapped devices
[ 0.792551] cros-ec-spi spi-PRP0001:00: Chrome EC device registered
[ 0.859111] elan_i2c i2c-ELAN0000:00: Elan Touchpad: Module ID:
0x0136, Firmware: 0x0002, Sample: 0x0004, IAP: 0x0003
[ 0.859466] input: Elan Touchpad as
/devices/pci0000:00/0000:00:19.1/i2c_designware.5/i2c-14/i2c-ELAN0000:00/input/input4
```
HuC firmware authentication seems to take 16 ms:
```
[ 0.868703] i915 0000:00:02.0: [drm] HuC firmware
i915/tgl_huc_7.9.3.bin version 7.9.3
[ 0.884332] i915 0000:00:02.0: [drm] HuC authenticated
```
A warning, and init is run after 917 ms. The audit message is shown
after a delay of 26 ms:
```
[ 0.893505] Warning: unable to open an initial console.
[ 0.896843] EXT4-fs (dm-0): mounting ext2 file system using the ext4
subsystem
[ 0.897851] EXT4-fs (dm-0): mounted filesystem without journal. Opts:
(null). Quota mode: none.
[ 0.897877] VFS: Mounted root (ext2 filesystem) readonly on device 254:0.
[ 0.898928] devtmpfs: mounted
[ 0.912316] Freeing unused kernel image (initmem) memory: 1904K
[…]
[ 0.917145] Run /sbin/init as init process
[…]
[ 0.917151] xdomain=0
[ 0.943534] audit: type=1404 audit(1696062844.825:2): enforcing=1
old_enforcing=0 auid=4294967295 ses=4294967295 enabled=1 old-enabled=1
lsm=selinux res=1
```
100 ms pass in the part below:
```
[ 0.974761] usb 3-6: new high-speed USB device number 2 using xhci_hcd
[ 0.993260] audit: type=1403 audit(1696062844.875:3): auid=4294967295
ses=4294967295 lsm=selinux res=1
[ 1.033591] SELinux: Context u:object_r:cros_run_pvm_opt:s0 is not
valid (left unmapped).
[ 1.033629] SELinux: Context u:object_r:cros_run_pvm_opt_pita:s0 is
not valid (left unmapped).
[ 1.034703] audit: type=1400 audit(1696062844.916:4): avc: granted {
execute } for pid=242 comm="sh" name="crash_reporter" dev="dm-0"
ino=18252 scontext=u:r:cros_init_scripts:s0
tcontext=u:object_r:cros_crash_reporter_exec:s0 tclass=file
[ 1.064252] loop0: detected capacity change from 0 to 1184
[ 1.076327] udevd[258]: starting version 225
```
30 ms pass before the USB Webcam device is found, and 60 ms before
frecon prints a message:
```
[ 1.077015] LoadPin: security-policy pinned
obj="/opt/google/dlc/_trusted_verity_digests" pid=252
cmdline="chromeos_startup"
[ 1.079053] NMI watchdog: Enabled. Permanently consumes one hw-PMU
counter.
[ 1.112522] usb 3-6: New USB device found, idVendor=0c45,
idProduct=6a1b, bcdDevice=15.11
[ 1.112530] usb 3-6: New USB device strings: Mfr=2, Product=1,
SerialNumber=0
[ 1.112533] usb 3-6: Product: Integrated_Webcam_FHD
[ 1.112535] usb 3-6: Manufacturer: CKFLF10T0954203AE620
[ 1.175154] frecon[536]: Frecon using drm driver i915, version 1.6,
date(20201103), desc(Intel Graphics) using atomic
[ 1.182147] i915 0000:00:02.0: [drm] Finished loading DMC firmware
i915/adlp_dmc_ver2_16.bin (v2.16)
```
The USB Bluetooth device and Bluetooth stack also takes some time:
```
[ 1.233804] usb 3-10: new full-speed USB device number 3 using xhci_hcd
[ 1.361528] usb 3-10: New USB device found, idVendor=8087,
idProduct=0033, bcdDevice= 0.00
[ 1.361542] usb 3-10: New USB device strings: Mfr=0, Product=0,
SerialNumber=0
[ 1.379121] EXT4-fs (dm-5): mounted filesystem with ordered data
mode. Opts: commit=600,discard. Quota mode: journalled.
[ 1.379567] EXT4-fs (nvme0n1p8): mounted filesystem without journal.
Opts: . Quota mode: none.
[ 1.382850] usb 3-6: GPIO lookup for consumer privacy
[ 1.382853] usb 3-6: using ACPI for GPIO lookup
[ 1.382855] acpi device:2f: GPIO: looking up privacy-gpios
[ 1.382857] acpi device:2f: GPIO: looking up privacy-gpio
[ 1.382858] usb 3-6: using lookup tables for GPIO lookup
[ 1.382859] usb 3-6: No GPIO consumer privacy found
[ 1.382860] usb 3-6: Found UVC 1.00 device Integrated_Webcam_FHD
(0c45:6a1b)
[ 1.391519] usbcore: registered new interface driver uvcvideo
[ 1.406142] EXT4-fs (dm-5): re-mounted. Opts: . Quota mode: journalled.
[ 1.434031] Bluetooth: bt_init() Core ver 2.22
```
ext4 shows a warning, and the audit system logs something 60 ms after
that. Then init kills process 711, and cros-ec-sensorhup also logs a
warning(?):
```
[ 1.443140] Bluetooth: btintel_prepare_fw_download_tlv() hci0: Found
device firmware: intel/ibt-0040-0041.sfi
[ 1.532713] frecon[536]: Frecon using drm driver i915, version 1.6,
date(20201103), desc(Intel Graphics) using atomic
[ 1.674258] EXT4-fs (dm-7): mounted filesystem with ordered data
mode. Opts: discard,commit=600. Quota mode: none.
[ 1.675920] EXT4-fs warning (device dm-7): ext4_resize_fs:1975: can't
read last block, resize aborted
[ 1.740241] audit: type=1400 audit(1696062845.622:5): avc: granted {
execute } for pid=702 comm="chromeos_startu" name="crash_reporter"
dev="dm-0" ino=18252 scontext=u:r:chromeos_startup:s0
tcontext=u:object_r:cros_crash_reporter_exec:s0 tclass=file
[ 1.758349] SELinux: Context u:object_r:cros_modemfwd_file:s0 is not
valid (left unmapped).
[ 1.894270] init: console-ttyS0 main process (711) killed by TERM signal
[ 1.955529] usbcore: registered new interface driver r8152
[ 1.957885] cros-ec-sensorhub cros-ec-sensorhub.2.auto: no info for
EC sensor 0 : -22/3
[ 2.055032] Intel(R) Wireless WiFi driver for Linux
```
Is that something, Chromium OS cares about and going to look into? My
gut feeling would say, it’d be a good idea, to move to a newer Linux
kernel, like 6.1 or 6.6-rc4 first to not analyze already fixed issues.
Can newer Linux kernels be tested?
What would be your preference, on how to proceed? I bought the Dell
Chromebook with Chrome OS enterprise to also financially support the
project.
Kind regards,
Paul
¹ This makes the one second goal moot already.
[1]: https://www.youtube.com/watch?v=HwdWKMxM83E
[2]:
https://mail.coreboot.org/hyperkitty/list/[email protected]/thread/PVXOCXACTUS5EE3O75QRAH6GIG4MK6I5/
"google/brya/var/crota: selfboot jump reached after 1.2 s"
[3]: https://bugzilla.kernel.org/show_bug.cgi?id=217962
[4]:
https://lore.kernel.org/all/[email protected]/