Some of the early kernel boot time variations occur when detecting and spinning up devices sda and sbd and reading the partition information. Given this is probably spinny disc media, one would expect variations of this kind in early boot.
The other variations I can see are also due to probing of hardware, which again is probably expected. I'm finding it hard to see anything really too problematic with the kernel side boot timings given that we are dealing with H/W style variations in the boot. If there are issues that are glaring and I'm missing it, can you point me to them? -- You received this bug notification because you are a member of Kernel Packages, which is subscribed to linux-signed-azure in Ubuntu. https://bugs.launchpad.net/bugs/1858495 Title: multiple long delays during kernel and userspace boot Status in linux-signed-azure package in Ubuntu: New Bug description: Booting some Bionic instances in Azure (gen1 machines), I see some large delays during kernel/userspace boot that it would be good to understand what's going on. Additionally, there areas during boot that see delays is different for an image that's been created from a template vs. stock images. I'm attaching some data, 10 runs of the same image in a scaling set that run the initial boot. Processing the journal output, looking at delays of over 2.0 shows some concern. [ 1.788581] localhost.localdomain kernel: * Found PM-Timer Bug on the chipset. Due to workarounds for a bug, * this clock source is slow. Consider trying other clock sources [ 3.545974] localhost.localdomain kernel: Unstable clock detected, switching default tracing clock to "global" If you want to keep using the local clock, then add: "trace_clock=local" on the kernel command line [ 6.401684] localhost.localdomain kernel: EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null) [ 15.280390] localhost.localdomain kernel: EXT4-fs (sda1): re-mounted. Opts: discard After capturing bionic image as a template, and creating a new VM, we see new hot spots we didn't see before. # HotSpot maximum delta between kernel messages: 2.00000 # [ 2.846188] localhost.localdomain kernel: AES CTR mode by8 optimization enabled # [ 5.919313] localhost.localdomain kernel: raid6: avx2x4 gen() 21512 MB/s # # [ 6.591530] localhost.localdomain kernel: EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null) # [ 9.031051] localhost.localdomain systemd[1]: systemd 237 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid) # # [ 13.773554] localhost.localdomain sh[871]: + exit 0 # [ 21.625467] localhost.localdomain kernel: UDF-fs: INFO Mounting volume 'UDF Volume', timestamp 2019/12/17 00:00 (1000) # # [ 24.919359] bugbif2be000001 systemd-timesyncd[771]: Synchronized to time server 91.189.89.198:123 (ntp.ubuntu.com). # [ 29.787339] bugbif2be000001 cloud-init[1026]: Cloud-init v. 19.2-36-g059d049c-0ubuntu2~18.04.1 running 'init' at Mon, 16 Dec 2019 18:14:47 +0000. Up 25.20 seconds. The easiest comparison kernel-side is the systemd-analyze value: Grepping in the debug data: % grep "Startup finished.*kernel" bug-bionic-baseline-no*.debug/*/journal.log | cut -d" " -f 7- Startup finished in 3.209s (kernel) + 49.305s (userspace) = 52.515s. Startup finished in 3.355s (kernel) + 51.732s (userspace) = 55.088s. Startup finished in 3.287s (kernel) + 51.747s (userspace) = 55.035s. Startup finished in 3.129s (kernel) + 50.066s (userspace) = 53.195s. Startup finished in 3.350s (kernel) + 50.682s (userspace) = 54.032s. Startup finished in 3.355s (kernel) + 49.322s (userspace) = 52.678s. Startup finished in 3.219s (kernel) + 51.124s (userspace) = 54.343s. Startup finished in 3.128s (kernel) + 49.226s (userspace) = 52.354s. Startup finished in 3.193s (kernel) + 53.197s (userspace) = 56.390s. Startup finished in 3.118s (kernel) + 46.203s (userspace) = 49.322s. foofoo % grep "Startup finished.*kernel" bug-bionic-baseline-after*.debug/*/journal.log | cut -d" " -f 7- Startup finished in 7.685s (kernel) + 32.463s (userspace) = 40.148s. Startup finished in 7.041s (kernel) + 35.998s (userspace) = 43.040s. Startup finished in 7.808s (kernel) + 35.444s (userspace) = 43.253s. Startup finished in 7.206s (kernel) + 37.952s (userspace) = 45.159s. Startup finished in 8.426s (kernel) + 36.976s (userspace) = 45.403s. Startup finished in 6.731s (kernel) + 35.484s (userspace) = 42.216s. Startup finished in 7.152s (kernel) + 32.664s (userspace) = 39.817s. Startup finished in 7.429s (kernel) + 36.177s (userspace) = 43.606s. Startup finished in 9.075s (kernel) + 32.494s (userspace) = 41.570s. Startup finished in 7.281s (kernel) + 32.732s (userspace) = 40.013s. ProblemType: Bug DistroRelease: Ubuntu 18.04 Package: linux-image-5.0.0-1027-azure 5.0.0-1027.29~18.04.1 ProcVersionSignature: User Name 5.0.0-1027.29~18.04.1-azure 5.0.21 Uname: Linux 5.0.0-1027-azure x86_64 ApportVersion: 2.20.9-0ubuntu7.9 Architecture: amd64 Date: Mon Jan 6 18:44:10 2020 ProcEnviron: TERM=xterm-256color PATH=(custom, no user) XDG_RUNTIME_DIR=<set> LANG=C.UTF-8 SHELL=/bin/bash SourcePackage: linux-signed-azure UpgradeStatus: No upgrade log present (probably fresh install) To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/linux-signed-azure/+bug/1858495/+subscriptions -- Mailing list: https://launchpad.net/~kernel-packages Post to : kernel-packages@lists.launchpad.net Unsubscribe : https://launchpad.net/~kernel-packages More help : https://help.launchpad.net/ListHelp
