Making sense of Time in dmesg

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?

Solution 1:

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

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