在dmesg中理解时间

Question

我知道在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行应采取的慢速启动。

但是，如果从一开始就计算出时间，那么第二行就应该负责。

但是，当我们在启动后很长时间检查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中理解时间呢？

Answer 1

dmesg并不是对启动过程进行多长时间或哪里有瓶颈的可靠测试。根据Wikipedia page的说法：

在最初引导时，计算机系统将其内核加载到内存中。在这个阶段，内核中存在的设备驱动程序被设置为驱动相关硬件。这些驱动程序以及内核中的其他元素可能会产生输出(“消息”)，报告模块的存在和所采用的任何参数的值。

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

dmesg还不断地从环形缓冲区收集消息，因此您的2466 s延迟并不表示某个挂起进程，只是在2466秒之后发生了一个事件，当时任何进程都是活动的，只是输出了一个内核消息。

然而，您想要的是引导图，它专门用于在引导过程中查找瓶颈。我只看到它在多个论坛和这个网站上被引用，但从未使用过我自己，所以不能给你更多的信息。

Answer 2

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

因此，问题不可能是，哪个时间戳dmesg (或内核)将进行日志记录，但必须是当内核为它所做的特定操作创建日志条目时。

正如我所猜测的那样，这可能因行动而异。当发生在内核上的事件，即插入USB设备时，一旦有可用信息，内核就会将其记录下来。当内核执行计划的任务时，在完成任务时记录结果是有意义的。如果它是一项复杂的工作，也许它在运行时会生成一些日志条目，但正如我所猜测的，通常在发生了一些有趣的事情之后，或者一小段时间已经过去了。

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

因此，如果您特别想知道某个条目是在某个操作的开始还是结束时记录的，那么当程序调用log-函数时，您需要查看内核-或模块-sorcecode。

Answer 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的答案