On 12/01/19 3:41 AM, Michael Stone wrote: > On Fri, Jan 11, 2019 at 02:03:44PM +1300, Richard Hector wrote: >> According to dmesg, this is where it appears to hang: >> >> [ 2.717311] device-mapper: uevent: version 1.0.3 >> [ 2.717398] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23) >> initialised: dm-d >> evel@redhat.com >> [ 2.978281] clocksource: Switched to clocksource tsc >> [ 121.459392] md: linear personality registered for level -1 >> [ 121.460391] md: multipath personality registered for level -4 >> [ 121.461444] md: raid0 personality registered for level 0 > > dmesg is the wrong tool for this, as it only shows kernel messages and > the delay is probably not in the kernel. try "journalctl -b", which will > show both kernel messages and other logs for the current boot. > I think it is in the kernel, actually. Compare: dmesg: [ 2.655799] random: crng init done [ 2.655828] random: 7 urandom warning(s) missed due to ratelimiting [ 2.666315] md8: detected capacity change from 0 to 499965231104 [ 2.839576] device-mapper: uevent: version 1.0.3 [ 2.839664] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23) initialised: dm-devel@redhat.com [ 2.979835] clocksource: Switched to clocksource tsc [ 131.281666] PM: Starting manual resume from disk [ 131.281699] PM: Hibernation image partition 253:8 present [ 131.281699] PM: Looking for hibernation image. [ 131.281783] PM: Image not found (code -22) [ 131.281784] PM: Hibernation image not present or could not be loaded. [ 141.617008] EXT4-fs (md0): mounted filesystem with ordered data mode. Opts: (null) [ 172.514409] ip_tables: (C) 2000-2006 Netfilter Core Team [ 172.556027] systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN) [ 172.556181] systemd[1]: Detected architecture x86-64. journalctl -b: Jan 12 16:12:37 rh-khost1 kernel: random: crng init done Jan 12 16:12:37 rh-khost1 kernel: random: 7 urandom warning(s) missed due to ratelimiting Jan 12 16:12:37 rh-khost1 kernel: md8: detected capacity change from 0 to 499965231104 Jan 12 16:12:37 rh-khost1 kernel: device-mapper: uevent: version 1.0.3 Jan 12 16:12:37 rh-khost1 kernel: device-mapper: ioctl: 4.35.0-ioctl (2016-06-23) initialised: dm-devel@redhat.com Jan 12 16:12:37 rh-khost1 kernel: clocksource: Switched to clocksource tsc Jan 12 16:12:37 rh-khost1 kernel: PM: Starting manual resume from disk Jan 12 16:12:37 rh-khost1 kernel: PM: Hibernation image partition 253:8 present Jan 12 16:12:37 rh-khost1 kernel: PM: Looking for hibernation image. Jan 12 16:12:37 rh-khost1 kernel: PM: Image not found (code -22) Jan 12 16:12:37 rh-khost1 kernel: PM: Hibernation image not present or could not be loaded. Jan 12 16:12:37 rh-khost1 kernel: EXT4-fs (md0): mounted filesystem with ordered data mode. Opts: (null) Jan 12 16:12:37 rh-khost1 kernel: ip_tables: (C) 2000-2006 Netfilter Core Team Jan 12 16:12:37 rh-khost1 systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS Jan 12 16:12:37 rh-khost1 systemd[1]: Detected architecture x86-64. So dmesg _does_ show systemd messages, systemd starts a couple of lines later, and it then reads all the kernel messages and writes them out with the same timestamp. I did try systemd-analyze (blame and critical-path) earlier, but they also showed that the delay wasn't on systemd's watch. Thanks, Richard
Attachment:
signature.asc
Description: OpenPGP digital signature