[Bug 1615685] Re: systemd-analyze stats for kernel startup time looks suspect

[Chris Cheney]

Its also not clear why Ubuntu's systemd-analyze doesn't report more than
just kernel + userspace times even on Ubuntu 18.04. Both CentOS 7 and
Fedora 27 report times properly, which are using older versions of
systemd.

---

CentOS 7 - systemd-219-42.el7_4.7.x86_64

$ systemd-analyze time
Startup finished in 846ms (kernel) + 2.678s (initrd) + 2min 29.307s (userspace) = 2min 32.832s

---

Fedora 27 - systemd-234-10.git5f8984e.fc27.x86_64

$ systemd-analyze time
Startup finished in 21.114s (firmware) + 2.086s (loader) + 1.131s (kernel) + 8.841s (initrd) + 6.125s (userspace) = 39.298s

---

Ubuntu systemd 237-3ubuntu4

$ systemd-analyze time
Startup finished in 2.561s (kernel) + 12.868s (userspace) = 15.429s
graphical.target reached after 12.842s in userspace

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to systemd in Ubuntu.
https://bugs.launchpad.net/bugs/1615685

Title:
  systemd-analyze stats for kernel startup time looks suspect

Status in systemd package in Ubuntu:
  New

Bug description:
  I've instrumented a kernel so I can clearly see when processes start
  and exit, this allows me to see when exactly the kernel has handed off
  control to userspace.  The time the kernel actually takes to
  initialize compared to the time systemd-analyze reports are different.

  $ systemd-analyze 
  Startup finished in 16.878s (kernel) + 43.152s (userspace) = 1min 30ms

  For example:

  [    2.286330] Freeing unused kernel memory: 1532K (ffffffffb1755000 - ffffffffb18d4000)
  [    2.296300] Write protecting the kernel read-only data: 12288k
  [    2.304356] Freeing unused kernel memory: 1872K (ffff9d9c6e42c000 - ffff9d9c6e600000)
  [    2.317659] Freeing unused kernel memory: 1208K (ffff9d9c6e8d2000 - ffff9d9c6ea00000)
  [    2.344896] x86/mm: Checked W+X mappings: passed, no W+X pages found.
  [    2.368095] exec: 1 (swapper/0) -> /init
  [    2.377284] _do_fork: 1 init
  [    2.381933] exit 53 init
  [    2.386444] _do_fork: 1 init
  [    2.390741] exit 54 init
  [    2.394899] _do_fork: 1 init

  and we have the initramfs initialization occurring, and then finally
  systemd starts:

  [   16.571630] exec: 1 (run-init) -> /sbin/init
  [   17.287342] systemd[1]: systemd 229 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ -LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN)
  [   17.307892] systemd[1]: Detected virtualization microsoft.
  [   17.314765] systemd[1]: Detected architecture x86-64.
  [   17.421589] systemd[1]: Set hostname to <boottest>.

  So it seems that systemd is accounting initramfs time in the kernel
  time stats.  It would be preferable to be able to report the kernel
  init time, the initramfs time and the userspace time rather just
  kernel + userspace.

  As it stands, the kernel passed off control to systemd at 16.571630
  seconds, so I have no no idea why systemd is reporting 16.878 seconds.

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/1615685/+subscriptions