Home / ubuntu / Questions / 749419
Accepted
Mostafa Ahangarha
Asked: 2016-03-24 09:53:54 +0800 CST

Making sense of Time in dmesg

  • 772

I know the time in dmesg is the time since boot. But my specific question is this time is calculated at the start or end of the process mentioned in the line?

Why this is important?
take this example:

[    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

If the time, is calculated after finishing the process, the process in the 3rd line should be taken responsible for slow boot.
But if time is calculated from the beginning of the process, the 2nd line should be taken responsible for it.

But it become more complicated when we check dmesg long after boot.
Take this for example:

[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

This 2466s gap shouldn't have any useful meaning.

I see many times there is confusion about which line in dmesg should be hold responsible for a slow boot.

How can we make sense of time in dmesg?

debugging

3 Answers

  1. Best Answer

    dmesg is not a reliable test of how long a boot-up process goes or where there are bottle-necks. According to Wikipedia page:

    When initially booted, a computer system loads its kernel into memory. At this stage device drivers present in the kernel are set up to drive relevant hardware. Such drivers, as well as other elements within the kernel, may produce output ("messages") reporting both the presence of modules and the values of any parameters adopted

    In other words, dmesg itself merely collects information, it's the drivers and other system processes that output those messages, and they can output them at any point in time. Between those messages there may or may not have been other processes spawning, so it is not an indicator of how long system boots.

    dmesg also collects messages continuously from the ring buffer, so your 2466s delay does not indicate some hanging process, merely an event occurred 2466s later and whatever process was active at that time just output a kernel message.

    What you do want, however , is bootchart , which is used specifically for the purpose of finding bottle-necks in the boot process. I've only seen it being referenced across multiple forums and on this site, but never used myself, so cannot give you more information than that

    • 4

  2. The dmesg command reads the kernel's printk buffer using the user space access mode via /dev/kmsg. Each entry has a monotonic timestamp in microseconds which is set when the log entry is created.

    So the question can not be, which timestamp dmesg (or the kernel) will log but must be when the kernel will create the log entry for a specific action it does.

    As I guess, this may differ from action to action. When an event happens to the kernel, i.e. plug in an USB device, the kernel will log this as soon as it has usable information. When the kernel does a planned task, it makes sense to log the results when the job is done. If it is a complex job, maybe it produces some log entries while it runs, but as I guess generally after something interesting has happend or a little amount of time is gone.

    How you may access the kernel's printk buffer is explained here.

    So if you specially want to know if a certain entry is logged at the beginning or the end of an action you need to look in the kernel- or module-sorcecode when the program call the log-function.

    • 2

  3. Read man dmesg, especially: 

       -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.

    The timestamp value is "microseconds since boot/1000000" (looks like "seconds to 6 decimal places). The timestamp is set to 0 at boot.

    Like @cmks said, the "microseconds since boot" value is copied into the log entry when the log entry is inserted into the kernel's buffer. dmesg interprets this value several different ways. dmesg -T -d | less will show the deltas. I did read the Question, and the answer from @cmks

    • -2