主页 / ubuntu / 问题 / 749419
Accepted
Mostafa Ahangarha
Asked: 2016-03-24 09:53:54 +0800 CST

在 dmesg 中理解时间

  • 772

我知道时间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

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

我看到很多次对于哪条线路dmesg应该对慢速启动负责。

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

debugging

3 个回答

  1. Best Answer

    dmesg不是启动过程持续多长时间或瓶颈所在位置的可靠测试。根据Wikipedia page：

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

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

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

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

    • 4

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

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

    正如我猜测的那样，这可能因行动而异。当内核发生事件时，即插入 USB 设备，内核将在获得可用信息后立即记录。当内核执行计划任务时，在作业完成后记录结果是有意义的。如果这是一项复杂的工作，它可能会在运行时产生一些日志条目，但我猜通常是在发生一些有趣的事情或花费了一点时间之后。

    此处解释了如何访问内核的 printk 缓冲区。

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

    • 2

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

    • -2

相关问题