Re: [Ksummit-discuss] [TECH TOPIC] printk redesign

[Sergey Senozhatsky <sergey.senozhatsky@gmail.com>]

On (06/20/17 16:44), Luck, Tony wrote:
> >> This is a configuration option (PRINTK_TIME) and isn't 100% reliable,
> >> I've got examples in the syslog of my current system with multiple
> >> prints being issued with the same timestamp.
> >
> > yes, as far as I know, timestamps are not in complete sync between CPUs.
> 
> We are pretty deep into the printk() code before we call local_clock() to
> find out what timestamp to print.

correct, we basically keep the time when the message was finally
stored (there can be a 'lengthy' spinning on logbuf_lock before
that), not when the caller issued printk().

> Would it be helpful to grab that much earlier ... so it is closer to
> the time at which the code that called printk()?
> 
> This would make it more likely that messages would appear out of order,
> but I think it would be better to know when things actually happened, not
> when we got around to printing them.

so, yes, we probably can do it. and _perhaps_ it makes sense to do it even
in the current printk, I think. this won't make messages ordered, tho.
printk() does not sort logbuf records. and the way things work now, even
if we would sort logbuf entries, we still would have cases of out of
order messages - because printk_safe and printk_nmi messages in general
(in general; there is a shortcut for printk_nmi, but not for printk_safe)
cannot be stored directly to the logbuf because we can deadlock. we flush
those messages later from irq work instead. so those messages are expected
to be out of order.

another thing that I found useful is a CPU number of the processor
that stored a particular line to the logbuf.

	-ss