☰

为什么 `journalctl -k -b -0` 和 `ps ho lstart 1` 之间有差距？

tag-icon • tag-icon systemd ps systemd-journald real-time journalctl
为什么 `journalctl -k -b -0` 和 `ps ho lstart 1` 之间有差距？

我遇到一个奇怪的观察：

如果我做：journalctl -k -b -0 | sed -e 's/^\(.\{76\}\).*/\1.../;3q'

我会看到类似的东西：

-- Journal begins at Sun 2022-08-07 12:06:55 CEST, ends at Mon 2023-02-20 08...
Jan 09 15:07:39 magnet kernel: Linux version 5.10.0-20-amd64 (debian-kernel@...
Jan 09 15:07:39 magnet kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-5.10.0...

哪个应该匹配：dmesg | sed -e 's/^\(.\{76\}\).*/\1.../;2q'

 [    0.000000] Linux version 5.10.0-20-amd64 ([email protected]...
 [    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-5.10.0-20-amd64 root=/...

太酷了，我看到启动的第一行带有完整的时间戳！

但：如果我击中：ps ho lstart,cmd 1

Mon Jan  9 15:07:26 2023 /sbin/init

如果我正确解释：过程init开始 13 秒前核心！？

使用此类命令在许多其他主机上进行了测试：

initSeconds() { 
    sdtext=(before after)
    { read -r kstart
      read -r sstart ;} < <(
        date -f <(LC_ALL=C journalctl -k -b -0 |
            sed -e "2{s/$HOSTNAME.*//;q};d"
            LC_ALL=C ps ho lstart 1) +%s
    )
    sdiff=$((sstart-kstart))
    printf 'Kernel : %(%a %d %b %T)T\nSystemd: %(%a %d %b %T)T (%s" %s)\n' \
        $kstart $sstart ${sdiff#-} ${sdtext[sdiff>0]}
}

然后

sudo bash < <(declare -f initSeconds;echo initSeconds)

Kernel : Mon 09 Jan 11:33:53
Systemd: Mon 09 Jan 11:33:23 (30" before)

ssh pi@raspberrypi sudo bash < <(declare -f initSeconds;echo initSeconds)

我收到了不同的结果：

  • 13"，18"， 取决于30"：init 前 kernel，在不同的主机上，
  • -50"，-3354在不同的树莓派...哪里init 可能会在大约一小时后开始核心？

这是一个错误吗？

如果是的话（我想是的），这是一个ps错误还是一个journactl错误！？

注：我读过ps lstart 的输出已更改，但我不能同意在短短 41 天里看到 30 秒的差距！

日志摘录（来自联想笔记本电脑）：

（完整命令下根用户：

# paste -d\   <( dmesg |
    sed 's/$/                        /;s/^\(.\{32\}\).*/    \1/'
  ) <(
    LANG=C journalctl -k -b -0|sed 's/\(.\{40\}\).*/\1/'
  )

）

还有一些手册版本：

|--       dmesg output       --| |--        journalctl output         --|
-------------------------------- ----------------------------------------
[    0.000000] Linux version 5.1 -- Journal begins at Sun 2021-10-03 13:2
[    0.000000] Command line: BOO Feb 26 12:09:12 host kernel: Linux versi
[    0.000000] x86/fpu: x87 FPU  Feb 26 12:09:12 host kernel: Command lin
[    0.000000] BIOS-provided phy Feb 26 12:09:12 host kernel: x86/fpu: x8
[    0.000000] BIOS-e820: [mem 0 Feb 26 12:09:12 host kernel: BIOS-provid
[    0.000000] BIOS-e820: [mem 0 Feb 26 12:09:12 host kernel: BIOS-e820: 
... 58 lines skipped
[    0.018652] RAMDISK: [mem 0x3 Feb 26 12:09:12 host kernel: found SMP M
...802 lines skipped
...102 lines skipped
[    4.557467] EXT4-fs (dm-0): m Feb 26 12:09:12 host kernel: PM: Image n
[    4.623199] Not activating Ma Feb 26 12:09:12 host kernel: EXT4-fs (dm
[    4.730262] systemd[1]: Inser Feb 26 12:09:12 host kernel: Not activat
[    4.751319] systemd[1]: syste Feb 26 12:09:12 host systemd[1]: Inserte
[    4.767877] systemd[1]: Detec Feb 26 12:09:12 host systemd[1]: systemd
...140 lines skipped
[    5.882062] iwlwifi 0000:03:0 Feb 26 12:09:12 host kernel: iwlwifi 000
[    5.895585] uvcvideo: Found U Feb 26 12:09:12 host kernel: uvcvideo: F
[    5.898230] input: Integrated Feb 26 12:09:13 host kernel: input: Inte
[    5.898319] usbcore: register Feb 26 12:09:13 host kernel: usbcore: re
... 49 lines skipped
[   10.702190] e1000e 0000:00:19 Feb 26 12:09:17 host kernel: e1000e 0000

和

initSeconds
Kernel : dim 26 fév 12:09:12
Systemd: dim 26 fév 12:09:07 (5" before)

事实上systemd启动了5秒后内核（4.730262），但这不能解释负差距。

答案1

进程的启动时间基本上以“系统启动后的秒数”的形式存储在内核中。您可以通过检查来确认这一点/proc/1/stat文件的格式。

该ps命令将其转换为人类可读的挂钟时间戳当你运行命令时。

另一方面，日志中的时间戳已经从“启动后的秒数”格式转换为 UTC 等效形式（可能是 Unix 时间戳或类似形式）写入日志条目时。

大多数 Raspberry Pi 型号不包含电池供电的实时时钟 (RTC)，因此当内核启动时，真实系统时间将不确定。一个很可能避免向后跳跃时间的需要的合理假设是，在系统上次运行时将最后一个时间戳写入根文件系统，并添加一秒，并将其用作系统时间，直到 NTP 服务器可以达到。

如果系统已停机很长一段时间，则第一次 NTP 同步将需要显着的向前时间跳跃 - 但这比向后转动时钟更安全，并且由于系统无论如何都处于早期启动阶段，因此没有什么可以对时间一致和流畅的硬性要求应该还在运行。

由于系统通常几乎在根文件系统准备好并可写时就开始写入日志，因此日志中早期启动的时间戳将会有一定程度的偏差，除非系统具有准确的 RTC。当系统时间调整时，调整事件本身应该记录在日志中，但是journald会不是返回并调整已写入日志条目的时间戳。如果您查看整个日志，您应该会发现在调整系统时钟的任何点上时间戳都会出现不连续性。

因此，内核启动时间和第一个 NTP 同步建立时间之间记录的时间戳只能被解释相对于彼此，因为它们与真实挂钟时间的对应关系是不确定的，尤其在没有精确的电池支持 RTC 的系统上。

systemd实际上包括两个适用于此的目标：在具有 RTC 的系统上，标记time-set.target启动过程中已使用 RTC 时间设置系统时钟的点，因此系统时间至少应该在正确的范围内，假设RTC 很好。

第二个目标是time-sync.target，它标记系统时钟已与 NTP 或其他可靠的外部时间源同步的点。在没有功能性电池支持 RTC 的系统上，例如（大多数）RasPi，在达到此目标之前记录的任何早期启动时间戳都应假定仅在彼此相关时可用。

相关内容