Edit: I couldn't find out why this weird effect happens, but I found the culprit of the actual problem (slow bootup) to be the same as described here:
I will still leave this open as the question remains.
I'm trying to analyze the startup time of a friend whose laptop "suddenly" became slower.
dmesg shows me this:
[ 2.348642] usb 1-8: New USB device found, idVendor=0bda, idProduct=0129
[ 2.348644] usb 1-8: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 2.348645] usb 1-8: Product: USB2.0-CRW
[ 2.348646] usb 1-8: Manufacturer: Generic
[ 2.348648] usb 1-8: SerialNumber: 20100201396000000
[ 2.352517] usbcore: registered new interface driver rtsx_usb
[ 2.844331] [drm] RC6 on
[ 34.760930] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[ 34.933397] ip_tables: (C) 2000-2006 Netfilter Core Team
[ 35.006893] 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)which also confirms manual measurements and the output of systemd-analyze saying that the laptop spends roughly 35 secs in the kernel for bootup, the remaining ~12 secs in user are due to a unit waiting for NetworkManager getting online -- but they do not matter here. Anyhow, with an SSD the laptop shouldn't spend so long booting up, especially not for mounting the filesystem.
I also ran journalctl -k which should give the same output, but I get:
Aug 30 21:13:45 laptop kernel: usb 1-8: New USB device found, idVendor=0bda, idProduct=0129
Aug 30 21:13:45 laptop kernel: usb 1-8: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Aug 30 21:13:45 laptop kernel: usb 1-8: Product: USB2.0-CRW
Aug 30 21:13:45 laptop kernel: usb 1-8: Manufacturer: Generic
Aug 30 21:13:45 laptop kernel: usb 1-8: SerialNumber: 20100201396000000
Aug 30 21:13:45 laptop kernel: usbcore: registered new interface driver rtsx_usb
Aug 30 21:13:45 laptop kernel: [drm] RC6 on
Aug 30 21:13:45 laptop kernel: EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
Aug 30 21:13:45 laptop kernel: ip_tables: (C) 2000-2006 Netfilter Core Team
Aug 30 21:13:45 laptop 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)... so there's no such time gap from journalctls perspective.
I have no idea where this time difference might come from.
1 Answer
To get the same timestamp format as dmesg with journalctl, try
journalctl -o short-monotonic -bExample output with journalctl
...
[ 1.003458] marvin kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 1.003460] marvin kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 1.003461] marvin kernel: usb usb1: Product: xHCI Host Controller
[ 1.003462] marvin kernel: usb usb1: Manufacturer: Linux 4.15.0-33-generic xhci-hcd
[ 1.003463] marvin kernel: usb usb1: SerialNumber: 0000:00:14.0
[ 1.003596] marvin kernel: hub 1-0:1.0: USB hub found
[ 1.003611] marvin kernel: hub 1-0:1.0: 16 ports detected
[ 1.004505] marvin kernel: xhci_hcd 0000:00:14.0: xHCI Host Controller
[ 1.004507] marvin kernel: xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 2
[ 1.004510] marvin kernel: xhci_hcd 0000:00:14.0: Host supports USB 3.0 SuperSpeed
[ 1.004533] marvin kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003
[ 1.004535] marvin kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 1.004536] marvin kernel: usb usb2: Product: xHCI Host Controller
[ 1.004537] marvin kernel: usb usb2: Manufacturer: Linux 4.15.0-33-generic xhci-hcd
[ 1.004538] marvin kernel: usb usb2: SerialNumber: 0000:00:14.0
...Compared to the same output from dmesg
...
[ 1.003458] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 1.003460] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 1.003461] usb usb1: Product: xHCI Host Controller
[ 1.003462] usb usb1: Manufacturer: Linux 4.15.0-33-generic xhci-hcd
[ 1.003463] usb usb1: SerialNumber: 0000:00:14.0
[ 1.003596] hub 1-0:1.0: USB hub found
[ 1.003611] hub 1-0:1.0: 16 ports detected
[ 1.004505] xhci_hcd 0000:00:14.0: xHCI Host Controller
[ 1.004507] xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 2
[ 1.004510] xhci_hcd 0000:00:14.0: Host supports USB 3.0 SuperSpeed
[ 1.004533] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003
[ 1.004535] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 1.004536] usb usb2: Product: xHCI Host Controller
[ 1.004537] usb usb2: Manufacturer: Linux 4.15.0-33-generic xhci-hcd
[ 1.004538] usb usb2: SerialNumber: 0000:00:14.0
...
