Making sense of Time in dmesg

Question

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?

Answer 1

dmesg is not a suitable way to analyse or investigate the performance of the boot process. You should use bootchart or in younger distributions the already in systemd integrated version of bootchart systemd-analyse.

Because these are complex processes I will not copy the tutorials to this answer.

How to install bootchart is explained here.

How to use systemd-analyse is explained here.

Answer 2

Each log entry shows the time at which the log entry was printed. No more, no less. If the log entry describes a process that is not instantaneous, there's no rule that the log entry must come before or after that process is carried out, it's up to what the developer chose to do. Grammar is a clue: “did this” indicates that the action is complete, “will do this” indicates that it hasn't been done yet; but “doing this” is ambiguous.

As cmks explains, dmesg only shows kernel logs, it doesn't paint a useful picture of what happens on the system once the initramfs or the init program has started. None of the lines that you show describe events that take more than a fraction of a second, so none of them are responsible for a long boot time. It's something else, which isn't happening in the kernel.