Re: [PATCH RESEND 1/3] printk: convert byte-buffer to variable-length record buffer

[Kay Sievers <kay@vrfy.org>]

On Sat, May 12, 2012 at 8:35 PM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
> On Sat, May 12, 2012 at 12:43 AM, Sasha Levin <levinsasha928@gmail.com> wrote:
>>
>> So I got something like this:
>>
>> # sleep 61 ; echo foo > /dev/kmsg ; sleep 61 ; echo bar > /dev/kmsg ;
>> sleep 5 ; echo zoot > /dev/kmsg ; sleep 10 ; echo foo > /dev/kmsg ;
>> echo bar > /dev/kmsg ; sleep 61 ; echo zoot > /dev/kmsg ; echo foo >
>> /dev/kmsg
>>
>> [  673.222632] foo
>> [  734.315249] bar
>> [   +5.077527] zoot
>> [  +10.235225] foo
>> [   +0.002971] bar
>> [  810.883085] zoot
>> [   +0.003081] foo
>>
>> If that looks right, I can send a patch once this printf overhaul is
>> stable, unless Kay already plans on doing it as part of his work.
>
> So judging by my own use, I really think that
>
>  (a) the microseconds are *totally* useless for the absolute time. In
> fact, they are worse than useless: they take up space and are actively
> distracting.
>
>      If the last message was over a minute ago, *nobody* cares about
> the microsecond. The microseconds are useful when there are multiple
> messages and you see that "oh, those events happened within a couple
> of ms of each other", but for the absolute time they are just bad.
>
>     Even the *seconds* are probably not that interesting.
>
>  (b) The one thing I have often wanted is not "after how many seconds
> of boot", but "when". So it would actually be nice if the absolute
> time was converted into local time. The kernel can actually do that,
> so I suspect that the best format for the relative timestamps would
> really be something like
>
>   > [May12 11:27] foo
>   > [May12 11:28] bar
>   > [  +5.077527] zoot
>   > [ +10.235225] foo
>   > [  +0.002971] bar
>   > [May12 11:29] zoot
>   > [  +0.003081] foo
>
> because that would be really useful sometimes.
>
> (And no, never mind the year. If you log those things long-term, the
> year will be in the full log, so logging the year in the dmesg is just
> pointless.)
>
> I dunno. The above is what I would have liked to see quite often. I
> look at dmesg, and notice that I had an WARN_ON_ONCE in it, and I have
> no idea when it happened, because the "seconds since boot" is totally
> useless information for me, as I'm too lazy to try to use /proc/uptime
> to calculate what it is.

Yeah, that looks generally more useful.

"dmesg -T" tries to translate that to wall clock time too. At the
moment, it can't really do that reliable at the point of reading the
timestamps though, because the monotonic time used does not include
the time spent in suspend.

One other problem with the current logic is that the timestamp we get
at the moment is not guaranteed to monotonic, log lines from different
CPUs at the same time can jump forth and back, so the relative-time
calculation could, with the current code, show negative values.

Not sure what options we have to use a more better clock source, if
things are expected to work in NMIs and IRQs.

Kay