Re: [GIT pull] printk updates for 4.15

From: Mark Salyzyn
Date: Tue Nov 14 2017 - 10:57:08 EST


On 11/14/2017 02:03 AM, Petr Mladek wrote:
On Mon 2017-11-13 17:18:33, Linus Torvalds wrote:
On Mon, Nov 13, 2017 at 1:36 AM, Thomas Gleixner <tglx@xxxxxxxxxxxxx> wrote:
Honestly, this just seems bogus to me, particularly since it's a single choice.

The *sane* model would be to

(a) continue to use the existing time that we always have
(local_clock()) in the printk timestamps, and don't confuse people
with the semantics of that field changing.

(b) just emit a "synchronization printk" every once in a while, which
is obviously also using the same standard time source, but the line
actually _says_ what the other time sources are.
This was actually the original approach by Mark Salyzyn, see
https://lkml.kernel.org/r/20170720182505.9357-1-salyzyn@xxxxxxxxxxx

Thanks for the vote of confidence :-) but we were holding back re spinning that set until the ability to switch the primary timestamp got accepted. (we were to use U suffix for realtime, B for boottime etc to designate them).

Printing the other timebases during major disruptions (suspend/resume/etc) was needed for our battery monitoring analysis tools, and we only used them as synchronization markers as a secondary effect.

But we _also_ had Android partners asking if it was possible to switch the primary (dmesg) timestamp to one of boottime or realtime to aid in triaging temporal issues. Doing so in the tool was sometimes too inaccurate (~+/-20ms) even with help sniffing the periodic synchronization/disruption prints. Switching the timebase for dmesg gave us roughly 1000 times more comparative time precision which helps immensely when trying to correlate and order the sequence of events in user space and kernel activities.

-- Mark