Re: [PATCH 3/3] printk: using booting time as the timestamp

[John Stultz <john.stultz@linaro.org>]

On 04/03/2014 08:18 PM, Lei Wen wrote:
> As people may want to align the kernel log with some other processor
> running over the same machine but not the same copy of linux, we
> need to keep their log aligned, so that it would not make debug
> process hard and confused.
>
> Signed-off-by: Lei Wen <leiwen@marvell.com>
> ---
>  kernel/printk/printk.c | 4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index a45b509..af96fbd 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -349,7 +349,7 @@ static void log_store(int facility, int level,
>  	if (ts_nsec > 0)
>  		msg->ts_nsec = ts_nsec;
>  	else
> -		msg->ts_nsec = local_clock();
> +		msg->ts_nsec = ktime_to_ns(ktime_get_boottime());

No no... Since ktime_get_boottime() takes the timekeeping seqlock, this
will cause any printk (or WARN_ON, etc) that is done while holding a
write in the timekeeping seqlock to deadlock (which I mentioned last time).

I think the better solution here is to have the timekeeping code provide
the printk logic the offset value whenever the sleep time is updated.
That way the printk logic can manage its own values w/o having to take
any timekeeping locks.

That said, I'm still not really fond of trying to add this
functionality. The printk timestamping code was always a little fuzzy,
using jiffies or sched_clock in order to give a rough estimate of boot
delays (and didn't include ntp freq correction, etc). When it was
introduced, I feel like folks were concerned about this, but folks
agreed the rough estimates were worth it, and it didn't have to involve
the real timekeeping code.  Now, trying to raise the bar here to make
printk timestamps actually correlate with
CLOCK_BOOTTIME/REALTIME/MONOTONIC (which I'll admit, seems quite
reasonable given we have timestamps already - but ends up being feature
creep) will add quite a bit of complexity due to the fact that printk is
supposed to be safe to call from everywhere.

And again, syslog can add timestamps to the kernel messages relatively
well in userland. So I'm not sure the need is clear.

thanks
-john