* Boott ime delays and issues on Dell Latitude 5430 Chromebook
@ 2023-10-02 6:32 Paul Menzel
0 siblings, 0 replies; only message in thread
From: Paul Menzel @ 2023-10-02 6:32 UTC (permalink / raw
To: Steven Rostedt; +Cc: Brian Norris, LKML
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/coreboot@coreboot.org/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/168778151245.3634408.4606396781291833683.tglx@vps.praguecc.cz/
^ permalink raw reply [flat|nested] only message in thread
only message in thread, other threads:[~2023-10-02 6:33 UTC | newest]
Thread overview: (only message) (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2023-10-02 6:32 Boott ime delays and issues on Dell Latitude 5430 Chromebook Paul Menzel
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.