Re: [PATCH 1/2] printk: Store all three timestamps

[John Ogness]

On 2020-09-23, Petr Mladek <pmladek@xxxxxxxx> wrote:
> printk() historically shows the timestamps from the monotonic clock.

printk() uses the local clock, not the monotonic clock.

> It is fast, available early during boot, in any context, and even
> without using any lock.
>
> There are repeated requests [1][2][3] to show the timestamps from other
> clocks. The main motivation is to make it easier to correlate the kernel
> and userspace logs. Where userspace logs usually use the real time
> clock.
>
> Unfortunately, it is not possible to simply replace the default clock.
> Userspace tools, like journalctl, dmesg, expect to get the timestamps
> from the mono via /dev/kmsg interface or syslog syscall [4].
> Also administrators would be confused when logs from different
> systems use different clocks depending on kernel version or
> build option [5].
>
> As a result, the mono clock has to stay as the default clock
> and has to be used in the current user interfaces.

Actually this series is changing the default clock from local to
monotonic. I for one welcome this change (and wish ftrace would do it as
well), but it is a change.

> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 1560649cbd35..0ed8901916f4 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -520,10 +522,10 @@ static int log_store(u32 caller_id, int facility, int level,
>  	r.info->facility = facility;
>  	r.info->level = level & 7;
>  	r.info->flags = flags & 0x1f;
> -	if (ts_nsec > 0)
> -		r.info->ts_nsec = ts_nsec;
> +	if (ts)
> +		r.info->ts = *ts;
>  	else
> -		r.info->ts_nsec = local_clock();
> +		ktime_get_fast_timestamps(&r.info->ts);

I am wondering if we still want to keep the local_clock() as well (and
as the default). ftrace also uses it by default, which means traces and
printk logs could be coordinated by default until now.

The two clocks can vary quite a bit. I have a laptop where the local
clock drifts away from monotonic at about 50us per second.

> diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
> index 0adaa685d1ca..09082c8472d3 100644
> --- a/kernel/printk/printk_ringbuffer.h
> +++ b/kernel/printk/printk_ringbuffer.h
> @@ -14,7 +15,7 @@
>   */
>  struct printk_info {
>  	u64	seq;		/* sequence number */
> -	u64	ts_nsec;	/* timestamp in nanoseconds */
> +	struct ktime_timestamps ts; /* timestamps */
>  	u16	text_len;	/* length of text message */
>  	u8	facility;	/* syslog facility */
>  	u8	flags:5;	/* internal record flags */

If we wanted to keep the local clock, should the local clock be a part
of struct ktime_timestamps? Or should struct printk_info maintain that
separately (either as @ts_nsec or @ts_local or whatever).

John Ogness