Re: [GIT pull] printk updates for 4.15

[Petr Mladek]

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:
> > Linus,
> >
> > please pull the latest core-printk-for-linus git tree from:
> >
> >    git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git core-printk-for-linus
> >
> > This update adds the mechanisms to emit printk timestamps based on
> > different clocks:
> >
> >   - scheduler clock (default)
> >   - monotonic time
> >   - boot time
> >   - wall clock time
> >
> > This helps to correlate dmesg with user space log information, tracing,
> > etc. This can be local correlation or in case of wall clock time correlated
> > across machines, assumed that all machines are synchronized via
> > NTP/PTP.
> 
> 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


> Then it's easy to see what the printk time source is, in relation to
> any _number_ of other timesources. And if that synchronization printk
> is nicely formatted, it will even be something that people appreciate
> seeing in dmesg _irrespective_ of any actual synchronization issues.
> 
> And something that reads the journal could trivially pick up on the
> synchronization printk line, and then correct the local timesource to
> whatever internal journal timesource it wants to. And the important
> thing is that because you just give *all* timesources in the
> synchronization line, that choice isn't fixed by some random kernel
> configuration or setting.

One risk is that the messages might get lost. For example, they might be
filtered by loglevel or during a flood of messages on slow consoles.


> Instead, this seems to have a completely broken "pick one time source
> model at random" approach, so now different machines will have
> different models, and it will likely _break_ existing code that picks
> the timesource from the kernel dmesg, unless you just pick the local
> one.

AFAIK, local clock is not synchronous between different machines
and even CPUs on the same machine. It was used in printk() because
it was lockless. Therefore it is kind of random itself.

You could make some post-synchronization using that printed
time stamps from other clocks. But it is not reliable (lost
messages) and somehow inconvenient.

I am not super happy that userspace might need update with
the approach in this pull request. But it seems to be rather
trivial. The timestamp (number) in the log can be converted into
the date+time as following:

  + realtime: timestamp ~= number of micro sec. since 1.1.1970
  + other clocks: timestamp ~= number of micro sec. since boot


> That seems like bad design, and really stupid.
>
> Am I missing something? Because as-is, this just seems like a horribly
> bad feature to me. I'm not pulling it without some very good arguments
> for this all.

I wonder if the current approach might be acceptable if we print
some suffix after real-time or any non-local_clock timestamps.
This would allow userspace to always handle this correctly.
IMHO, it would be more reliable and convenient than the
"synchronization printks".

Best Regards,
Petr