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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite for Android: free password hash cracker in your pocket

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <533F2A57.1060808@linaro.org>
Date:	Fri, 04 Apr 2014 14:55:35 -0700
From:	John Stultz <john.stultz@...aro.org>
To:	Lei Wen <leiwen@...vell.com>, Thomas Gleixner <tglx@...utronix.de>,
	Stephen Boyd <sboyd@...eaurora.org>,
	Andrew Morton <akpm@...ux-foundation.org>,
	Steven Rostedt <rostedt@...dmis.org>,
	Michael Opdenacker <michael.opdenacker@...e-electrons.com>,
	Joe Perches <joe@...ches.com>, Tejun Heo <tj@...nel.org>,
	Petr Mladek <pmladek@...e.cz>, linux-kernel@...r.kernel.org,
	Peter Zijlstra <peterz@...radead.org>
Subject: Re: [PATCH 3/3] printk: using booting time as the timestamp

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@...vell.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

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/