☰

理解 dmesg 中的时间

tag-icon • tag-icon debugging dmesg
理解 dmesg 中的时间

我知道输入的时间dmesg是启动后的时间。但我的具体问题是，这个时间是在行中提到的进程开始时还是结束时计算的？

为什么这很重要？
请看这个例子：

[    4.352025] floppy0: no floppy controllers found
[    5.718270] random: nonblocking pool is initialized
[   94.134265] Adding 2094076k swap on /dev/sda5.  Priority:-1 extents:1 across:2094076k FS**
[   96.988453] init: bootchart main process (274) terminated with status 127

如果时间是在进程结束后计算的，那么第 3 行中的进程应该对启动缓慢负责。
但如果时间是从进程开始时计算的，那么第 2 行应该对此负责。

dmesg但是当我们在启动后很长时间检查时，情况会变得更加复杂。
例如：

[28047.749604] wlp3s0: associated
[28941.112855] [drm:intel_pipe_update_end [i915]] *ERROR* Atomic update failure on pipe A (start=757985 end=757986)
[31407.938694] cfg80211: World regulatory domain updated:
[31407.938699] cfg80211:  DFS Master region: unset

这个2466的差距不应该有任何有用的意义。

我发现很多时候人们对于哪一行dmesg应该对启动缓慢负责感到困惑。

我们如何理解 dmesg 中的时间？

答案1

dmesg不能可靠地测试启动过程需要多长时间或瓶颈在哪里。根据Wikipedia page：

计算机系统在首次启动时会将其内核加载到内存中。在此阶段，内核中的设备驱动程序被设置为驱动相关硬件。此类驱动程序以及内核中的其他元素可能会产生输出（“消息”），报告模块的存在以及所采用的任何参数的值

换句话说，dmesg它本身只是收集信息，驱动程序和其他系统进程会输出这些消息，并且它们可以在任何时间点输出这些消息。在这些消息之间可能会或可能不会产生其他进程，因此它不是系统启动时间的指标。

dmesg还从环形缓冲区连续收集消息，因此 2466 秒的延迟并不表示某个挂起的进程，而仅仅是 2466 秒后发生了一个事件，并且当时处于活动状态的任何进程都只会输出一条内核消息。

然而，你想要的是启动图，它专门用于查找启动过程中的瓶颈。我只在多个论坛和本网站上看到过它的引用，但我自己从未使用过，因此无法为您提供更多信息

答案2

dmesg 命令通过以下方式使用用户空间访问模式读取内核的 printk 缓冲区/dev/kmsg。每个条目都有一个以微秒为单位的单调时间戳这是在创建日志条目时设置的。

所以问题不可能是，dmesg（或内核）将记录哪个时间戳，而必须是内核为其执行的特定操作创建日志条目的时间。

我猜，这可能因操作而异。当内核发生事件时，即插入 USB 设备，内核会在获得可用信息后立即记录此事件。当内核执行计划任务时，在作业完成后记录结果是有意义的。如果这是一项复杂的作业，也许它会在运行时生成一些日志条目，但我想通常是在发生了一些有趣的事情或过了一段时间后。

解释了如何访问内核的 printk 缓冲区这里。

因此，如果您特别想知道某个条目是在操作的开始还是结束时记录的，则需要在程序调用日志函数时查看内核或模块源代码。

答案3

阅读man dmesg，尤其是：

   -d, --show-delta
          Display the timestamp and time delta spent between messages.  If
          used together with --notime then only the time delta without the
          timestamp is printed.


   -T, --ctime
          Print  human  readable  timestamps.  The  timestamp   could   be
          inaccurate!

          The  time  source  used for the logs is not updated after system
          SUSPEND/RESUME.

时间戳值为“自启动以来的微秒数/1000000”（看起来像“精确到小数点后 6 位的秒数”。时间戳设置为0启动时。

就像 @cmks 所说的那样，当日志条目插入内核缓冲区时，“自启动以来的微秒数”值将被复制到日志条目中。以dmesg几种不同的方式解释这个值。dmesg -T -d | less将显示增量。我确实读过这个问题，以及 @cmks 的回答

相关内容