OpenBMC Boot time improvements
Ed Tanous
edtanous at google.com
Tue Sep 13 06:32:19 AEST 2022
Is anyone interested in boot time improvements? I recently looked at my
system just to get a baseline, and it seems like there's some low hanging
fruit to be gained that could give us some significant speedups on the boot
process. Is anyone looking at this kind of thing already?
My quick analysis from timing the serial log is below. Total time to a
login is 95 seconds, which it seems like we could improve quite a bit.
First serial line printed to u-boot "hit any key" startup init is 3 seconds
3 seconds of countdown for "hit any key to stop autoboot". I'm sure u-boot
has a way to disable that, so there's 3 seconds right there.
Decompressing the dtb, initramfs, and kernel images is seconds 5-14. If
there's a way to optimize that better that u-bmc has implemented ahead of
us, that seems like an area for improvement that we could pull in.
Kernel starts at ~20 seconds, then 3.5 seconds of dead air... not sure
what's going on there.
A big 17 second pause between these two lines. Not sure what that's about.
[25.443908 0.001845] [ 2.294952] Driver for 1-wire Dallas network
protocol.
[42.321590 16.877682] [ 19.191143] SPI driver bmp280 has no spi_device_id
for bosch,bmp085
6. Init script runs at 46 seconds, so we're getting into the realm of
"systemd problems" at ~50% of our boot time.
7. 71 seconds in, all the user-facing sockets are up, and the NIC comes up;
So far as a user is concerned, the bmc is "up" (kinda), given that the
user facing services are socket activated.
8. 71-95, launching all the various backend system services.
9. 95 seconds in, services have finished launching, and a login prompt is
presented.
```
~/grabserial master ❯ sudo python3 grabserial -v -d /dev/ttyUSB3 -b 115200
-f -w 8 -p N -s 1 -e 150 -t -m "DRAM Init-V12-DDR4"
Opening serial port /dev/ttyUSB3
115200:8N1:xonxoff=0:rtscts=0:rts=1:dtr=1
Program set to end in 150 seconds
Printing timing information for each line
Using pattern 'DRAM Init-V12-DDR4' to set base time
Use Control-C to stop...
[0.000001 0.000001]
[0.000531 0.000530] DRAM Init-V12-DDR4
[0.016045 0.016045] 0abc1-4Gb-Done
[0.271901 0.255857] Read margin-DL:0.3647/DH:0.3745 CK (min:0.30)
[1.971260 1.699359]
[1.971447 0.000186]
[1.971544 0.000097] U-Boot 2016.07 (Jun 10 2020 - 10:12:49 +0000)
[1.973912 0.002369]
[1.973960 0.000047] Watchdog enabled
[1.974791 0.000832] DRAM: 496 MiB
[2.850693 0.875902] Flash: 128 MiB
[2.962520 0.111827] In: serial
[3.000751 0.038230] Out: serial
[3.001596 0.000845] Err: serial
[3.002095 0.000499] Net: MAC0 : RMII/NCSI
[3.002880 0.000785] MAC1 : RGMII
[3.003157 0.000277] FTGMAC100#0
[3.003447 0.000290] Error: FTGMAC100#0 address not set.
[3.004289 0.000842] , FTGMAC100#1
[3.004628 0.000339] Error: FTGMAC100#1 address not set.
[3.005417 0.000789]
[3.005442 0.000025] Hit any key to stop autoboot: 0
[5.037966 2.032524] ## Loading kernel from FIT Image at 20080000 ...
[5.039975 0.002010] Using 'conf-aspeed-bmc-tyan-s7106.dtb' configuration
[5.041790 0.001814] Trying 'kernel-1' kernel subimage
[5.042722 0.000932] Description: Linux kernel
[5.043504 0.000782] Type: Kernel Image
[5.044270 0.000766] Compression: uncompressed
[5.045040 0.000770] Data Start: 0x20080128
[5.045763 0.000723] Data Size: 3168888 Bytes = 3 MiB
[5.046716 0.000954] Architecture: ARM
[5.047274 0.000558] OS: Linux
[5.047869 0.000595] Load Address: 0x80001000
[5.048530 0.000660] Entry Point: 0x80001000
[5.049099 0.000569] Hash algo: sha256
[5.049564 0.000465] Hash value:
fed4aab9de8bc0c04cb8a180da7a817b4c0e7db8c9608e1f59a0c7385eccd7a6
[5.059791 0.010227] Verifying Hash Integrity ... sha256+ OK
[11.582735 6.522943] ## Loading ramdisk from FIT Image at 20080000 ...
[11.633128 0.050394] Using 'conf-aspeed-bmc-tyan-s7106.dtb' configuration
[11.634600 0.001472] Trying 'ramdisk-1' ramdisk subimage
[11.635495 0.000895] Description: obmc-phosphor-initramfs
[11.636475 0.000980] Type: RAMDisk Image
[11.637248 0.000773] Compression: uncompressed
[11.637960 0.000712] Data Start: 0x2038d038
[11.638650 0.000690] Data Size: 1096840 Bytes = 1 MiB
[11.639495 0.000845] Architecture: ARM
[11.639993 0.000498] OS: Linux
[11.640573 0.000579] Load Address: unavailable
[11.641293 0.000721] Entry Point: unavailable
[11.642033 0.000740] Hash algo: sha256
[11.642632 0.000599] Hash value:
98744c2598168b3a123ef8760636a8c5e005948e67191646c017e877e7f86e51
[11.654930 0.012298] Verifying Hash Integrity ... sha256+ OK
[13.909357 2.254427] ## Loading fdt from FIT Image at 20080000 ...
[13.967636 0.058279] Using 'conf-aspeed-bmc-tyan-s7106.dtb' configuration
[13.969544 0.001907] Trying 'fdt-aspeed-bmc-tyan-s7106.dtb' fdt subimage
[13.970586 0.001042] Description: Flattened Device Tree blob
[13.971422 0.000836] Type: Flat Device Tree
[13.972072 0.000650] Compression: uncompressed
[13.972657 0.000585] Data Start: 0x20385cb8
[13.973207 0.000550] Data Size: 29362 Bytes = 28.7 KiB
[13.973970 0.000763] Architecture: ARM
[13.974391 0.000420] Hash algo: sha256
[13.974972 0.000582] Hash value:
66368a4557754ea3287198f0d2b75f98bf6a6e17a32c2a9bcc8a574b2dbe5a06
[13.976801 0.001829] Verifying Hash Integrity ... sha256+ OK
[14.045789 0.068988] Booting using the fdt blob at 0x20385cb8
[14.047312 0.001523] Loading Kernel Image ... OK
[18.347361 4.300049] Loading Ramdisk to 9ea90000, end 9eb9bc88 ... OK
[19.834330 1.486969] Loading Device Tree to 9ea85000, end 9ea8f2b1 ... OK
[19.914132 0.079802]
[19.914196 0.000063] Starting kernel ...
[19.930654 0.016458]
[23.488077 3.557423] [ 0.000000] Booting Linux on physical CPU 0x0
[23.490190 0.002112] [ 0.000000] Linux version 5.15.59-51fd11b
(oe-user at oe-host) (arm-openbmc-linux-gnueabi-gcc (GCC) 12.1.0, GNU ld (GNU
Binutils) 2.38.20220623) #1 Thu Aug 4 03:28:18 UTC 2022
[23.515911 0.025721] [ 0.000000] CPU: ARMv6-compatible processor
[410fb767] revision 7 (ARMv7), cr=00c5387d
[23.522071 0.006160] [ 0.000000] CPU: PIPT / VIPT nonaliasing data
cache, VIPT nonaliasing instruction cache
[23.550850 0.028779] [ 0.000000] OF: fdt: Machine model: Tyan S7106 BMC
[23.552944 0.002095] [ 0.000000] Memory policy: Data cache writeback
[23.554374 0.001430] [ 0.000000] Reserved memory: created CMA memory
pool at 0x9d000000, size 16 MiB
[23.604916 0.050542] [ 0.000000] OF: reserved mem: initialized node
framebuffer, compatible id shared-dma-pool
[23.608081 0.003165] [ 0.000000] cma: Reserved 16 MiB at 0x9c000000
[23.609227 0.001147] [ 0.000000] Zone ranges:
[23.609886 0.000659] [ 0.000000] Normal [mem
0x0000000080000000-0x000000009effffff]
[23.611526 0.001640] [ 0.000000] Movable zone start for each node
[23.675950 0.064424] [ 0.000000] Early memory node ranges
[23.677739 0.001789] [ 0.000000] node 0: [mem
0x0000000080000000-0x00000000987effff]
[23.680125 0.002386] [ 0.000000] node 0: [mem
0x00000000987f0000-0x00000000987fffff]
[23.681552 0.001427] [ 0.000000] node 0: [mem
0x0000000098800000-0x000000009effffff]
[23.682810 0.001258] [ 0.000000] Initmem setup node 0 [mem
0x0000000080000000-0x000000009effffff]
[23.684468 0.001658] [ 0.000000] Built 1 zonelists, mobility grouping
on. Total pages: 125984
[23.706800 0.022331] [ 0.000000] Kernel command line:
console=ttyS4,115200n8 root=/dev/ram rw
[23.709396 0.002597] [ 0.000000] Dentry cache hash table entries: 65536
(order: 6, 262144 bytes, linear)
[23.735743 0.026347] [ 0.000000] Inode-cache hash table entries: 32768
(order: 5, 131072 bytes, linear)
[23.738499 0.002756] [ 0.000000] mem auto-init: stack:all(zero), heap
alloc:off, heap free:off
[23.765738 0.027239] [ 0.000000] Memory: 457284K/507904K available
(8192K kernel code, 666K rwdata, 1560K rodata, 1024K init, 156K bss, 17852K
reserved, 32768K cma-reserved)
[23.819745 0.054007] [ 0.000000] SLUB: HWalign=32, Order=0-3,
MinObjects=0, CPUs=1, Nodes=1
[23.822114 0.002369] [ 0.000000] ftrace: allocating 23856 entries in 47
pages
[23.823525 0.001412] [ 0.000000] ftrace: allocated 47 pages with 5 groups
[23.824556 0.001031] [ 0.000000] trace event string verifier disabled
[23.825776 0.001220] [ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated
irqs: 16
[23.845754 0.019979] [ 0.000000] i2c controller registered, irq 17
[23.847347 0.001592] [ 0.000000] clocksource: FTTMR010-TIMER2: mask:
0xffffffff max_cycles: 0xffffffff, max_idle_ns: 77222644334 ns
[23.875768 0.028421] [ 0.000004] sched_clock: 32 bits at 24MHz,
resolution 40ns, wraps every 86767015915ns
[23.878921 0.003153] [ 0.000097] Switching to timer-based delay loop,
resolution 40ns
[23.944690 0.065770] [ 0.000886] Calibrating delay loop (skipped), value
calculated using timer frequency.. 49.50 BogoMIPS (lpj=247500)
[23.948623 0.003933] [ 0.000967] pid_max: default: 32768 minimum: 301
[23.949579 0.000956] [ 0.003104] Mount-cache hash table entries: 1024
(order: 0, 4096 bytes, linear)
[23.950998 0.001419] [ 0.003192] Mountpoint-cache hash table entries:
1024 (order: 0, 4096 bytes, linear)
[23.952525 0.001527] [ 0.006434] CPU: Testing write buffer coherency: ok
[23.995660 0.043134] [ 0.009700] Setting up static identity map for
0x80100000 - 0x80100038
[23.998464 0.002805] [ 0.011248] ASPEED AST2500 rev A2 (04030303)
[23.999575 0.001111] [ 0.012611] devtmpfs: initialized
[24.000401 0.000826] [ 0.035630] clocksource: jiffies: mask: 0xffffffff
max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[24.044628 0.044227] [ 0.035733] futex hash table entries: 256 (order:
-1, 3072 bytes, linear)
[24.047093 0.002465] [ 0.041939] pinctrl core: initialized pinctrl
subsystem
[24.048455 0.001362] [ 0.045095] NET: Registered PF_NETLINK/PF_ROUTE
protocol family
[24.049654 0.001199] [ 0.047578] DMA: preallocated 256 KiB pool for
atomic coherent allocations
[24.115643 0.065989] [ 0.050560] hw-breakpoint: found 6 breakpoint and 1
watchpoint registers.
[24.118448 0.002805] [ 0.050632] hw-breakpoint: maximum watchpoint size
is 4 bytes.
[24.119609 0.001161] [ 0.127577] mc: Linux media interface: v0.10
[24.120438 0.000829] [ 0.127769] videodev: Linux video capture
interface: v2.00
[24.121494 0.001056] [ 0.128051] pps_core: LinuxPPS API ver. 1 registered
[24.122430 0.000937] [ 0.128105] pps_core: Software ver. 5.3.6 -
Copyright 2005-2007 Rodolfo Giometti <giometti at linux.it>
[24.140529 0.018099] [ 0.128212] PTP clock support registered
[24.142585 0.002055] [ 0.132611] clocksource: Switched to clocksource
FTTMR010-TIMER2
[24.146256 0.003671] [ 0.224804] NET: Registered PF_INET protocol family
[24.167846 0.021590] [ 0.225299] IP idents hash table entries: 8192
(order: 4, 65536 bytes, linear)
[24.196360 0.028513] [ 0.226947] tcp_listen_portaddr_hash hash table
entries: 512 (order: 0, 4096 bytes, linear)
[24.199464 0.003104] [ 0.227069] Table-perturb hash table entries: 65536
(order: 6, 262144 bytes, linear)
[24.226350 0.026886] [ 0.227152] TCP established hash table entries:
4096 (order: 2, 16384 bytes, linear)
[24.228337 0.001987] [ 0.227259] TCP bind hash table entries: 4096
(order: 2, 16384 bytes, linear)
[24.274405 0.046068] [ 0.227349] TCP: Hash tables configured
(established 4096 bind 4096)
[24.277254 0.002849] [ 0.227642] UDP hash table entries: 256 (order: 0,
4096 bytes, linear)
[24.279681 0.002427] [ 0.227756] UDP-Lite hash table entries: 256
(order: 0, 4096 bytes, linear)
[24.281286 0.001605] [ 0.228521] NET: Registered PF_UNIX/PF_LOCAL
protocol family
[24.300313 0.019027] [ 0.232052] Unpacking initramfs...
[24.301608 0.001295] [ 0.242800] workingset: timestamp_bits=30
max_order=17 bucket_order=0
[24.303753 0.002145] [ 0.257235] squashfs: version 4.0 (2009/01/31)
Phillip Lougher
[24.368598 0.064845] [ 0.257303] jffs2: version 2.2. (SUMMARY)
2001-2006 Red Hat, Inc.
[24.370530 0.001932] [ 0.275423] NET: Registered PF_ALG protocol family
[24.371767 0.001237] [ 0.279878] ipmi-bt-host 1e789140.ibt: Found bt bmc
device
[24.373178 0.001411] [ 0.280829] ipmi-bt-host 1e789140.ibt: Using IRQ 34
[24.374452 0.001274] [ 0.282479] ast-kcs-bmc 1e789024.kcs: Initialised
raw client for channel 1
[24.419349 0.044897] [ 0.283020] ast-kcs-bmc 1e789024.kcs: Initialised
IPMI client for channel 1
[24.422025 0.002676] [ 0.283089] ast-kcs-bmc 1e789024.kcs: Initialised
channel 1 at 0xca8
[24.423269 0.001244] [ 0.294041] ast-kcs-bmc 1e78902c.kcs: Initialised
raw client for channel 3
[24.424783 0.001514] [ 0.294499] ast-kcs-bmc 1e78902c.kcs: Initialised
IPMI client for channel 3
[24.446348 0.021565] [ 0.294569] ast-kcs-bmc 1e78902c.kcs: Initialised
channel 3 at 0xca2
[24.449583 0.003235] [ 0.300129] aspeed-uart-routing
1e78909c.uart-routing: module loaded
[24.476207 0.026623] [ 0.303416] Serial: 8250/16550 driver, 6 ports, IRQ
sharing enabled
[24.478619 0.002412] [ 0.317481] 1e787000.serial: ttyS5 at MMIO
0x1e787000 (irq = 34, base_baud = 1546875) is a ASPEED VUART
[24.511201 0.032583] [ 0.319809] 1e783000.serial: ttyS0 at MMIO
0x1e783000 (irq = 32, base_baud = 1500000) is a 16550A
[24.514808 0.003607] [ 0.321423] 1e784000.serial: ttyS4 at MMIO
0x1e784000 (irq = 33, base_baud = 1500000) is a 16550A
[24.527183 0.012376] [ 1.393553] printk: console [ttyS4] enabled
[24.528688 0.001505] [ 1.399759] 1e78d000.serial: ttyS1 at MMIO
0x1e78d000 (irq = 35, base_baud = 1500000) is a 16550A
[24.571180 0.042492] [ 1.424074] 1e78e000.serial: ttyS2 at MMIO
0x1e78e000 (irq = 36, base_baud = 1500000) is a 16550A
[24.592127 0.020947] [ 1.444561] 1e78f000.serial: ttyS3 at MMIO
0x1e78f000 (irq = 37, base_baud = 1500000) is a 16550A
[24.620174 0.028047] [ 1.465512] timeriomem_rng 1e6e2078.hwrng: 32bits
from 0x(ptrval) @ 1us
[24.622947 0.002773] [ 1.473446] aspeed_gfx 1e6e6000.display: assigned
reserved memory node framebuffer
[24.636189 0.013241] [ 1.503570] random: crng init done
[24.652126 0.015937] [ 1.524490] [drm] Initialized aspeed-gfx-drm 1.0.0
20180319 for 1e6e6000.display on minor 0
[24.701060 0.048934] [ 1.553274] aspeed_gfx 1e6e6000.display: [drm] fb0:
aspeed-gfx-drmd frame buffer device
[24.733143 0.032083] [ 1.595158] loop: module loaded
[24.797137 0.063995] [ 1.659126] spi-nor spi0.0: mx66l1g45g (131072
Kbytes)
[24.939029 0.141891] [ 1.791345] spi-aspeed-smc 1e620000.spi: CE0 read
buswidth:2 [0x203c0641]
[25.098046 0.159017] [ 1.945137] 5 fixed-partitions partitions found on
MTD device bmc
[25.101257 0.003211] [ 1.951289] Creating 5 MTD partitions on "bmc":
[25.102476 0.001219] [ 1.955967] 0x000000000000-0x000000060000 : "u-boot"
[25.113789 0.011313] [ 1.984254] 0x000000060000-0x000000080000 :
"u-boot-env"
[25.138113 0.024324] [ 1.992205] 0x000000080000-0x0000004c0000 : "kernel"
[25.164872 0.026759] [ 2.015047] 0x0000004c0000-0x000001c00000 : "rofs"
[25.168555 0.003682] [ 2.022386] 0x000001c00000-0x000002000000 : "rwfs"
[25.234758 0.066204] [ 2.047580] spi-nor spi1.0: unrecognized JEDEC id
bytes: ff ff ff ff ff ff
[25.237092 0.002333] [ 2.054602] spi-nor: probe of spi1.0 failed with
error -2
[25.237974 0.000883] [ 2.065146] ftgmac100 1e660000.ethernet: Generated
random MAC address ee:f3:83:36:82:59
[25.238928 0.000954] [ 2.073315] ftgmac100 1e660000.ethernet: Using NCSI
interface
[25.239958 0.001030] [ 2.080277] ftgmac100 1e660000.ethernet eth0: irq
20, mapped at fbb6b239
[25.241289 0.001331] [ 2.087826] ftgmac100 1e680000.ethernet: Generated
random MAC address 2e:e3:14:ec:62:ff
[25.243061 0.001772] [ 2.105583] RTL8211E Gigabit Ethernet
1e680000.ethernet--1:00: attached PHY driver
(mii_bus:phy_addr=1e680000.ethernet--1:00, irq=POLL)
[25.271468 0.028407] [ 2.119043] ftgmac100 1e680000.ethernet eth1: irq
21, mapped at dd746f2b
[25.283708 0.012240] [ 2.154169] Freeing initrd memory: 1072K
[25.334315 0.050606] [ 2.159954] aspeed_vhub 1e6a0000.usb-vhub:
Initialized virtual hub in USB2 mode
[25.337081 0.002767] [ 2.167969] Mass Storage Function, version:
2009/09/11
[25.338294 0.001213] [ 2.173247] LUN: removable file: (no medium)
[25.339165 0.000871] [ 2.177613] no file given for LUN0
[25.339808 0.000643] [ 2.181098] udc 1e6a0000.usb-vhub:p1: failed to
start g_mass_storage: -22
[25.341107 0.001299] [ 2.188670] i2c_dev: i2c /dev entries driver
[25.341952 0.000845] [ 2.194845] aspeed-i2c-bus 1e78a040.i2c-bus: i2c
bus 0 registered, irq 38
[25.343256 0.001304] [ 2.203024] aspeed-i2c-bus 1e78a080.i2c-bus: i2c
bus 1 registered, irq 39
[25.390362 0.047106] [ 2.212682] at24 2-0050: 32768 byte 24c256 EEPROM,
writable, 1 bytes/write
[25.392269 0.001907] [ 2.219811] aspeed-i2c-bus 1e78a0c0.i2c-bus: i2c
bus 2 registered, irq 40
[25.394077 0.001808] [ 2.229401] at24 3-0050: 256 byte 24c02 EEPROM,
writable, 1 bytes/write
[25.395848 0.001771] [ 2.237783] at24 3-0051: 256 byte 24c02 EEPROM,
writable, 1 bytes/write
[25.397618 0.001771] [ 2.245540] aspeed-i2c-bus 1e78a100.i2c-bus: i2c
bus 3 registered, irq 41
[25.399389 0.001770] [ 2.253818] aspeed-i2c-bus 1e78a140.i2c-bus: i2c
bus 4 registered, irq 42
[25.401156 0.001767] [ 2.261963] aspeed-i2c-bus 1e78a180.i2c-bus: i2c
bus 5 registered, irq 43
[25.438266 0.037110] [ 2.270210] aspeed-i2c-bus 1e78a1c0.i2c-bus: i2c
bus 6 registered, irq 44
[25.440232 0.001966] [ 2.278519] aspeed-i2c-bus 1e78a300.i2c-bus: i2c
bus 7 registered, irq 45
[25.442063 0.001831] [ 2.286725] aspeed-i2c-bus 1e78a340.i2c-bus: i2c
bus 8 registered, irq 46
[25.443908 0.001845] [ 2.294952] Driver for 1-wire Dallas network
protocol.
[42.321590 16.877682] [ 19.191143] SPI driver bmp280 has no spi_device_id
for bosch,bmp085
[42.369245 0.047655] [ 19.202063] NET: Registered PF_INET6 protocol family
[42.370710 0.001465] [ 19.210275] Segment Routing with IPv6
[42.371670 0.000960] [ 19.214194] In-situ OAM (IOAM) with IPv6
[42.372684 0.001014] [ 19.218587] NET: Registered PF_PACKET protocol
family
[42.373994 0.001310] [ 19.223826] 8021q: 802.1Q VLAN Support v1.8
[42.375069 0.001075] [ 19.240013] printk: console [netcon0] enabled
[42.417406 0.042337] [ 19.244511] netconsole: network logging started
[42.418871 0.001465] [ 19.255290] Freeing unused kernel image (initmem)
memory: 1024K
[42.420469 0.001598] [ 19.265290] Checked W+X mappings: passed, no W+X
pages found
[42.421951 0.001482] [ 19.271013] Run /init as init process
[43.119224 0.697273] rofs = mtd4 squashfs rwfs = mtd5 jffs2
[43.346902 0.227678] [ 20.193806] jffs2: notice: (101)
jffs2_build_xattr_subsystem: complete building xattr subsystem, 26 of
xdatum (15 unchecked, 7 orphan) and 34 of xref (8 dead, 0 orphan) found.
[43.522817 0.175915] Tue Apr 5 23:02:44 UTC 2011
[43.551731 0.028914] [ 20.397227] overlayfs: upper fs does not support
tmpfile.
[43.554043 0.002311] [ 20.403610] overlayfs: upper fs does not support
RENAME_WHITEOUT.
[46.530198 2.976155] [ 23.376894] systemd[1]: Current system time is
further ahead 15y after build time, but cannot correct: Invalid argument
[46.545993 0.015796] [ 23.411753] systemd[1]: Failed to find module
'autofs4'
[46.773107 0.227114] [ 23.598149] systemd[1]: systemd 251.2+ running in
system mode (+PAM -AUDIT -SELINUX -APPARMOR -IMA -SMACK +SECCOMP -GCRYPT
-GNUTLS -OPENSSL -ACL +BLKID -CURL -ELFUTILS -FIDO2 -IDN2 -IDN -IPTC +KMOD
-LIBCRYPTSETUP +LIBFDISK -PCRE2 -PWQUALITY -P11KIT -QRENCODE -TPM2 -BZIP2
-LZ4 -XZ -ZLIB +ZSTD -BPF_FRAMEWORK -XKBCOMMON -UTMP +SYSVINIT
default-hierarchy=hybrid)
[46.783382 0.010274] [ 23.630127] systemd[1]: Detected architecture arm.
[46.832963 0.049582]
[46.833018 0.000055] Welcome to Phosphor OpenBMC (Phosphor OpenBMC Project
Reference Distro) 2.11.0-dev!
[46.836568 0.003550]
[46.880928 0.044360] [ 23.746391] systemd[1]: Hostname set to <s7106>.
[50.045951 3.165023] [ 26.892896] systemd[1]:
/lib/systemd/system/phosphor-ipmi-net at .socket:3: Invalid interface name,
ignoring: sys-subsystem-net-devices-%i.device
[50.214922 0.168972] [ 27.067199] systemd[1]: Queued start job for
default target Multi-User System.
[50.251829 0.036907] [ 27.097063] systemd[1]: Created slice Slice
/system/getty.
[50.254950 0.003120] [ OK ] Created slice Slice /system/getty.
[50.295814 0.040864] [ 27.141348] systemd[1]: Created slice Slice
/system/hostlogger.
[50.298493 0.002680] [ OK ] Created slice Slice /system/hostlogger.
[50.344807 0.046314] [ 27.191243] systemd[1]: Created slice Slice
/system/mapper-wait.
[50.346868 0.002061] [ OK ] Created slice Slice /system/mapper-wait.
[50.394869 0.048001] [ 27.241200] systemd[1]: Created slice Slice
/system/modprobe.
[50.397565 0.002697] [ OK ] Created slice Slice /system/modprobe.
[50.445728 0.048163] [ 27.291502] systemd[1]: Created slice Slice
/system/obmc-console.
[50.448524 0.002795] [ OK ] Created slice Slice /system/obmc-console.
[50.495677 0.047153] [ 27.341588] systemd[1]: Created slice Slice
/system/obmc-led-group-start.
[50.498699 0.003022] [ OK ] Created slice Slice
/system/obmc-led-group-start.
[50.545669 0.046970] [ 27.391644] systemd[1]: Created slice Slice
/system/phosphor-certificate-manager.
[50.548889 0.003220] [ OK ] Created slice Slice
/system/phosphor-certificate-manager.
[50.595607 0.046717] [ 27.441589] systemd[1]: Created slice Slice
/system/phosphor-ipmi-kcs.
[50.597484 0.001877] [ OK ] Created slice Slice /system/phosphor-ipmi-kcs.
[50.645620 0.048136] [ 27.491616] systemd[1]: Created slice Slice
/system/phosphor-ipmi-net.
[50.649161 0.003541] [ OK ] Created slice Slice /system/phosphor-ipmi-net.
[50.695552 0.046391] [ 27.541962] systemd[1]: Created slice Slice
/system/serial-getty.
[50.698557 0.003005] [ OK ] Created slice Slice /system/serial-getty.
[50.751634 0.053077] [ 27.591873] systemd[1]: Created slice Slice
/system/xyz.openbmc_project.Chassis.Control.Power.
[50.755019 0.003385] [ OK ] Created slice Slice
/systeproject.Chassis.Control.Power.
[50.767445 0.012426] [ 27.635053] systemd[1]: Started Dispatch Password
Requests to Console Directory Watch.
[50.795528 0.028083] [ OK ] Started Dispatch Password ts to Console
Directory Watch.
[50.829517 0.033989] [ 27.675029] systemd[1]: Started Forward Password
Requests to Wall Directory Watch.
[50.832890 0.003373] [ OK ] Started Forward Password Ruests to Wall
Directory Watch.
[50.867495 0.034605] [ 27.718553] systemd[1]: Reached target Path Units.
[50.869946 0.002451] [ OK ] Reached target Path Units.
[50.883339 0.013393] [ 27.754327] systemd[1]: Reached target Remote File
Systems.
[50.906378 0.023038] [ OK ] Reached target Remote File Systems.
[50.942467 0.036089] [ 27.793908] systemd[1]: Reached target Slice Units.
[50.945024 0.002557] [ OK ] Reached target Slice Units.
[50.983415 0.038391] [ 27.834719] systemd[1]: Reached target Swaps.
[50.985597 0.002182] [ OK ] Reached target Swaps.
[51.015376 0.029778] [ 27.887004] systemd[1]: Listening on Syslog Socket.
[51.037815 0.022439] [ OK ] Listening on Syslog Socket.
[51.100454 0.062639] [ 27.969505] systemd[1]: Listening on Process Core
Dump Socket.
[51.123107 0.022654] [ OK ] Listening on Process Core Dump Socket.
[51.159312 0.036204] [ 28.005293] systemd[1]: Listening on initctl
Compatibility Named Pipe.
[51.163193 0.003882] [ OK ] Listening on initctl Compatibility Named Pipe.
[51.175196 0.012003] [ 28.045875] systemd[1]: Journal Audit Socket was
skipped because of a failed condition check (ConditionSecurity=audit).
[51.214864 0.039668] [ 28.060598] systemd[1]: Listening on Journal Socket
(/dev/log).
[51.216492 0.001628] [ OK ] Listening on Journal Socket (/dev/log).
[51.256257 0.039765] [ 28.107496] systemd[1]: Listening on Journal Socket.
[51.258725 0.002467] [ OK ] Listening on Journal Socket.
[51.302207 0.043482] [ 28.147892] systemd[1]: Listening on Network
Service Netlink Socket.
[51.305223 0.003016] [ OK ] Listening on Network Service Netlink Socket.
[51.347120 0.041897] [ 28.193666] systemd[1]: Listening on udev Control
Socket.
[51.349171 0.002052] [ OK ] Listening on udev Control Socket.
[51.391152 0.041980] [ 28.236804] systemd[1]: Listening on udev Kernel
Socket.
[51.393638 0.002487] [ OK ] Listening on udev Kernel Socket.
[51.407052 0.013414] [ 28.277443] systemd[1]: Huge Pages File System was
skipped because of a failed condition check
(ConditionPathExists=/sys/kernel/mm/hugepages).
[51.449995 0.042943] [ 28.293533] systemd[1]: POSIX Message Queue File
System was skipped because of a failed condition check
(ConditionPathExists=/proc/sys/fs/mqueue).
[51.478059 0.028064] [ 28.323738] systemd[1]: Mounting Kernel Debug File
System...
[51.480142 0.002083] Mounting Kernel Debug File System...
[51.509969 0.029828] [ 28.380532] systemd[1]: Mounting Kernel Trace File
System...
[51.539350 0.029380] Mounting Kernel Trace File System...
[51.597110 0.057761] [ 28.443241] systemd[1]: Mounting Temporary
Directory /tmp...
[51.599710 0.002600] Mounting Temporary Directory /tmp...
[51.629030 0.029320] [ 28.496720] systemd[1]: Create List of Static
Device Nodes was skipped because of a failed condition check
(ConditionFileNotEmpty=/lib/modules/5.15.59-51fd11b/modules.devname).
[51.694985 0.065954] [ 28.546605] systemd[1]: Starting Load Kernel Module
configfs...
[51.698977 0.003992] Starting Load Kernel Module configfs...
[51.772951 0.073974] [ 28.625054] systemd[1]: Starting Load Kernel Module
fuse...
[51.774767 0.001815] Starting Load Kernel Module fuse...
[51.818924 0.044157] [ 28.665147] systemd[1]: File System Check on Root
Device was skipped because of a failed condition check
(ConditionPathIsReadWrite=!/).
[51.891872 0.072948] [ 28.743206] systemd[1]: Starting Journal Service...
[51.893559 0.001687] Starting Journal Service...
[51.965837 0.072278] [ 28.817654] systemd[1]: Load Kernel Modules was
skipped because all trigger condition checks failed.
[51.997672 0.031836] [ 28.869543] systemd[1]: Starting Generate network
units from Kernel command line...
[52.034659 0.036987] Starting Generate network ts from Kernel
command line...
[52.114632 0.079973] [ 28.985213] systemd[1]: Starting Remount Root and
Kernel File Systems...
[52.136827 0.022195] Starting Remount Root and Kernel File
Systems...
[52.199675 0.062847] [ 29.069243] systemd[1]: Starting Apply Kernel
Variables...
[52.247646 0.047972] Starting Apply Kernel Variables...
[52.343694 0.096048] [ 29.215162] systemd[1]: Starting Coldplug All udev
Devices...
[52.366999 0.023305] Starting Coldplug All udev Devices...
[52.868361 0.501362] [ 29.720007] systemd[1]: Mounted Kernel Debug File
System.
[52.932199 0.063838] [ OK ] Mounted Kernel Debug File System.
[52.989149 0.056950] [ 29.835439] systemd[1]: Mounted Kernel Trace File
System.
[52.991677 0.002527] [ OK ] Mounted Kernel Trace File System.
[53.049128 0.057451] [ 29.895548] systemd[1]: Mounted Temporary Directory
/tmp.
[53.051853 0.002725] [ OK ] Mounted Temporary Directory /tmp.
[53.077029 0.025176] [ 29.929350] systemd[1]: modprobe at configfs.service:
Deactivated successfully.
[53.107001 0.029972] [ 29.953102] systemd[1]: Finished Load Kernel Module
configfs.
[53.109846 0.002845] [ OK ] Finished Load Kernel Module configfs.
[53.168076 0.058229] [ 30.020412] systemd[1]: modprobe at fuse.service:
Deactivated successfully.
[53.200062 0.031986] [ 30.046159] systemd[1]: Finished Load Kernel Module
fuse.
[53.202464 0.002403] [ OK ] Finished Load Kernel Module fuse.
[53.204073 0.001608] [ 30.068653] systemd[1]: Finished Generate network
units from Kernel command line.
[53.254024 0.049951] [ OK ] Finished Generate network units from Kernel
command line.
[53.285877 0.031853] [ 30.158111] systemd[1]: Finished Remount Root and
Kernel File Systems.
[53.338859 0.052982] [ OK ] Finished Remount Root and Kernel File Systems.
[53.370881 0.032022] [ 30.241587] systemd[1]: Finished Apply Kernel
Variables.
[53.393164 0.022284] [ OK ] Finished Apply Kernel Variables.
[53.481021 0.087857] [ 30.318812] systemd[1]: Reached target Preparation
for Network.
[53.484837 0.003816] [ OK ] Reached target Preparation for Network.
[53.496938 0.012101] [ 30.367036] systemd[1]: FUSE Control File System
was skipped because of a failed condition check
(ConditionPathExists=/sys/fs/fuse/connections).
[53.581825 0.084887] [ 30.453374] systemd[1]: Mounting Kernel
Configuration File System...
[53.611489 0.029664] Mounting Kernel Configuration File System...
[53.687846 0.076357] [ 30.534063] systemd[1]: Rebuild Hardware Database
was skipped because of a failed condition check (ConditionNeedsUpdate=/etc).
[53.703639 0.015793] [ 30.574867] systemd[1]: Platform Persistent Storage
Archival was skipped because of a failed condition check
(ConditionDirectoryNotEmpty=/sys/fs/pstore).
[53.778705 0.075066] [ 30.625049] systemd[1]: Create System Users was
skipped because of a failed condition check (ConditionNeedsUpdate=/etc).
[53.847799 0.069094] [ 30.699639] systemd[1]: Starting Create Static
Device Nodes in /dev...
[53.893642 0.045844] Starting Create Static Device Nodes in /dev...
[54.014563 0.120921] [ 30.866554] systemd[1]: Mounted Kernel
Configuration File System.
[54.041466 0.026903] [ OK ] Mounted Kernel Configuration File System.
[54.567170 0.525704] [ 31.413009] systemd[1]: Finished Create Static
Device Nodes in /dev.
[54.569438 0.002267] [ OK ] Finished Create Static Device Nodes in /dev.
[54.599150 0.029712] [ 31.445086] systemd[1]: Reached target Preparation
for Local File Systems.
[54.601663 0.002513] [ OK ] Reached target Preparation for Local File
Systems.
[54.647228 0.045565] [ 31.508256] systemd[1]: Mounting /var/volatile...
[54.679114 0.031887] Mounting /var/volatile...
[54.775250 0.096135] [ 31.647359] systemd[1]: Starting Rule-based Manager
for Device Events and Files...
[54.841080 0.065830] Starting Rule-based Managefor Device Events
and Files...
[54.933032 0.091952] [ 31.784875] systemd[1]: Started Journal Service.
[54.935395 0.002362] [ OK ] Started Journal Service.
[55.012993 0.077598] [ OK ] Mounted /var/volatile.
[55.124927 0.111934] Starting Flush Journal to Persistent
Storage...
[55.284726 0.159799] Starting Load/Save Random Seed...
[55.344767 0.060041] [ OK ] Reached target Local File Systems.
[55.615663 0.270896] [ 32.467582] systemd-journald[134]: Received client
request to flush runtime journal.
[55.677563 0.061900] [ OK ] Finished Flush Journal to Persistent Storage.
[55.764487 0.086923] Starting Create Volatile Files and
Directories...
[55.796511 0.032024] [ OK ] Finished Load/Save Random Seed.
[56.578026 0.781515] [ OK ] Finished Create Volatile Files and
Directories.
[56.705990 0.127965] Starting Network Name Resolution...
[56.833921 0.127931] Starting Network Time Synchronization...
[57.247735 0.413814] [ OK ] Started Rule-based Manager for Device Events
and Files.
[57.375574 0.127839] Starting Network Configuration...
[59.322477 1.946902] [ OK ] Finished Coldplug All udev Devices.
[61.836220 0.003311] [ OK ] Started Network Time Synchronization.
[66.404501 0.003257] [ 44.006597] 8021q: adding VLAN 0 to HW filter on
device eth0
[67.310624 0.906122] [ OK ] Started Network Configuration.
[67.461615 0.150991] [ OK ] Started Network Name Resolution.
[67.573481 0.111866] [ OK ] Found device /sys/subsystem/net/devices/eth0.
[69.840189 2.266707] [ OK ] Created slice Slice
/system/xyz.openbmc_project.Hwmon.
[69.885086 0.044898] [ OK ] Created slice Slice
/systepenbmc_project.led.controller.
[69.917047 0.031961] [ OK ] Reached target Network.
[69.956052 0.039005] [ OK ] Reached target Host and Network Name Lookups.
[69.994986 0.038934] [ OK ] Reached target System Time Set.
[70.024949 0.029963] [ OK ] Reached target Hardware activated USB gadget.
[70.089049 0.064100] Starting Load Kernel Module fuse...
[70.168915 0.079866] Starting Wait for Network to be Configured...
[70.261885 0.092970] Starting Wait for udev To plete Device
Initialization...
[70.378769 0.116884] [ OK ] Finished Load Kernel Module fuse.
[70.511690 0.132921] [ OK ] Finished Wait for udev To Complete Device
Initialization.
[70.623694 0.112004] [ OK ] Started Hardware RNG Entropy Gatherer Daemon.
[70.655513 0.031819] [ OK ] Reached target System Initialization.
[70.736570 0.081057] [ OK ] Started Daily rotation of log files.
[70.775594 0.039024] [ OK ] Started Daily Cleanup of Temporary
Directories.
[70.815531 0.039937] [ OK ] Reached target Timer Units.
[70.871529 0.055998] [ OK ] Listening on Avahi mDNS/DNS-SD Stack
Activation Socket.
[70.966407 0.094877] [ OK ] Listening on BMC Webserver socket.
[71.030405 0.063998] [ OK ] Listening on D-Bus System Message Bus Socket.
[71.196403 0.165998] [ OK ] Listening on dropbear.socket.
[71.292238 0.095835] [ 48.163528] ftgmac100 1e680000.ethernet eth1: Link
is Up - 1Gbps/Full - flow control rx/tx
[71.320861 0.028622] [ 48.171909] IPv6: ADDRCONF(NETDEV_CHANGE): eth1:
link becomes ready
[71.430178 0.109317] [ OK ] Listening on Phosphor Hostole SSH
Per-Connection socket.
[71.526094 0.095916] [ OK ] Listening on phosphor-ipmi-net at eth0.socket.
[71.586054 0.059961] [ OK ] Reached target Socket Units.
[71.666205 0.080151] Starting D-Bus System Message Bus...
[72.801349 1.135144] [ OK ] Started D-Bus System Message Bus.
[73.068098 0.266749] [ OK ] Reached target Basic System.
[73.180175 0.112077] Starting Avahi mDNS/DNS-SD Stack...
[73.242047 0.061872] [ OK ] Started Start bmcweb server.
[73.385968 0.143922] Starting Clear one time boot overrides...
[73.497921 0.111952] [ OK ] Started Collectd.
[73.721807 0.223886] Starting SSH Key Generation...
[73.833714 0.111908] [ OK ] Started LPC Snoop Daemon.
[73.897783 0.064069] Starting Name Service Cache Daemon...
[73.945774 0.047991] Starting LDAP daemon...
[74.370455 0.424681] [ OK ] Started ttyS2 Console Server.
[74.536364 0.165909] [DEPEND] Dependency failed for Host logger for
ttyVUART0.
[74.680219 0.143855] [ OK ] Started Phosphor Dump core monitor..
[75.061063 0.380844] [ OK ] Started Phosphor certificate manager for
authority.
[75.471731 0.410668] [ OK ] Started Phosphor certificate manager for
bmcweb.
[75.845591 0.373860] [ OK ] Started Phosphor certificate manager for
nslcd.
[76.053437 0.207846] Starting BMC health monitoring...
[76.405303 0.351866] [ OK ] Started Lightweight SLP Server.
[76.740922 0.335620] Starting OpenBMC ipKVM daemon...
[77.044809 0.303887] Starting Permit User Sessions...
[77.252684 0.207875] Starting Enable Linux trace events in the
boot loader...
[77.517459 0.264774] Starting Intel Power Control for the Host 0...
[77.789325 0.271866] Starting Phosphor Dump Manager...
[77.917117 0.127793] Starting Entity Manager...
[78.077091 0.159973] [ OK ] Started Fru Device.
[78.371989 0.294899] [ OK ] Started IPMI SEL Logging Service.
[78.595787 0.223798] Starting Phosphor Log Manager...
[79.395339 0.799552] Starting Phosphor DBus Service Discovery
Manager...
[79.523156 0.127818] Starting Phosphor Settings Daemon...
[79.603066 0.079910] Starting Phosphor Download Manager...
[79.922962 0.319896] Starting Post code manager...
[80.050937 0.127975] Starting Rsyslog config updater...
[80.354702 0.303764] Starting Telemetry...
[80.562499 0.207797] Starting Phosphor User Manager...
[80.792450 0.229951] [ OK ] Started Phosphor sysfs LED controller.
[81.256206 0.463756] [ OK ] Started Phosphor sysfs LED controller.
[83.070060 1.813854] [ OK ] Finished Wait for Network to be Configured.
[83.507784 0.437724] [ OK ] Finished SSH Key Generation.
[83.760672 0.252888] [ OK ] Started Name Service Cache Daemon.
[83.851574 0.090902] [ OK ] Started OpenBMC ipKVM daemon.
[83.888570 0.036996] [ 60.740209] ftgmac100 1e660000.ethernet eth0: NCSI:
No channel found to configure!
[83.967398 0.078828] [ OK ] Finished Permit User Sessions.
[84.047391 0.079993] [ OK ] Finished Enable Linux trace events in the
boot loader.
[84.735110 0.687719] [ OK ] Finished Clear one time boot overrides.
[84.894970 0.159860] [ 61.762821] ftgmac100 1e660000.ethernet eth0: Wrong
NCSI state 0x100 in workqueue
[85.549486 0.654515] [ OK ] Started Phosphor Settings Daemon.
[85.765249 0.215764] [ OK ] Started Phosphor Download Manager.
[85.768340 0.003091] [ OK ] Started Post code manager.
[85.869289 0.100949] [ OK ] Started Intel Power Control for the Host 0.
[85.901206 0.031917] [ OK ] Started LDAP daemon.
[86.011219 0.110013] [ OK ] Started BMC health monitoring.
[86.091021 0.079802] [ OK ] Started Phosphor Log Manager.
[86.106979 0.015958] [ OK ] Started Rsyslog config updater.
[86.361989 0.255010] [ OK ] Started Phosphor DBus Service Discovery
Manager.
[86.425885 0.063896] [ OK ] Started Telemetry.
[86.553790 0.127905] [ OK ] Started Phosphor User Manager.
[86.793664 0.239874] [ OK ] Reached target Network is Online.
[86.899669 0.106005] [ OK ] Reached target Phosphor Object Mapper.
[87.272368 0.372699] Starting Wait for
/xyz/opecontrol/host0/boot/one_time...
[87.640217 0.367849] Starting Wait for
/xyz/ope_project/control/host0/boot...
[87.894980 0.254763] Starting Wait for
/xyz/ope/host0/power_restore_policy...
[88.241803 0.346823] Starting Wait for
/xyz/opetrol/host0/restriction_mode...
[88.545633 0.303830] Starting Wait for
/xyz/opeoject/led/groups/bmc_booted...
[88.882431 0.336798] Starting Wait for
/xyz/opemc_project/time/sync_method...
[89.071213 0.188782] [ OK ] Started phosphor systemd target monitor.
[89.375118 0.303905] Starting System Logging Service...
[89.701887 0.326770] [ OK ] Started Serial Getty on ttyS4.
[89.764756 0.062869] [ OK ] Reached target Login Prompts.
[90.459415 0.694659] Starting Phosphor LED Group Management
Daemon...
[90.744264 0.284849] Starting Phosphor Ldap config updater...
[90.920100 0.175835] Starting Phosphor Network Manager...
[91.335809 0.415709] Starting OpenBMC Software Update Manager...
[91.653723 0.317914] Starting Phosphor BMC State Manager...
[94.032272 2.378549] [ OK ] Started System Logging Service.
[94.176078 0.143806] [ OK ] Finished Wait for
/xyz/opet/control/host0/boot/one_time.
[94.325020 0.148942] [ OK ] Finished Wait for
/xyz/opemc_project/control/host0/boot.
[94.452987 0.127967] [ OK ] Finished Wait for
/xyz/opeol/host0/power_restore_policy.
[94.592883 0.139896] [ OK ] Finished Wait for
/xyz/opeontrol/host0/restriction_mode.
[94.714805 0.121922] [ OK ] Finished Wait for
/xyz/openbmc_project/time/sync_method.
[94.825732 0.110927] [ OK ] Started Phosphor Dump Manager.
[95.438527 0.612794]
[95.438650 0.000123] Phosphor OpenBMC (Phosphor OpenBMC Project Reference
Distro) nodistro.0 s7106 ttyS4
[95.442250 0.003600]
[95.442283 0.000033] s7106 login: root (automatic login)
[95.443164 0.000881]
```
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ozlabs.org/pipermail/openbmc/attachments/20220912/4f1be7cc/attachment-0001.htm>
More information about the openbmc
mailing list