Re: [PATCH 2/2] printk, allow different timestamps for printk.time

[Andrew Morton]

On Fri, 22 Apr 2016 08:03:09 -0400 Prarit Bhargava <prarit@xxxxxxxxxx> wrote:

> Over the past years I've seen many reports of bugs that include
> time-stamped kernel logs (enabled when CONFIG_PRINTK_TIME=y or
> print.time=1 is specified as a kernel parameter) that do not align
> with either external time stamped logs or /var/log/messages.  This
> also makes determining the time of a failure difficult in cases where
> /var/log/messages is unavailable.
> 
> For example,
> 
> [root@intel-wildcatpass-06 ~]# date; echo "Hello!" > /dev/kmsg ; date
> Thu Dec 17 13:58:31 EST 2015
> Thu Dec 17 13:58:31 EST 2015
> 
> which displays
> 
> [83973.768912] Hello!
> 
> on the serial console.
> 
> Running a script to convert this to the stamped time,
> 
> [root@intel-wildcatpass-06 ~]# ./human.sh  | tail -1
> [Thu Dec 17 13:59:57 2015] Hello!
> 
> which is already off by 1 minute and 26 seconds off after ~24 hours of
> uptime.
> 
> This occurs because the time stamp is obtained from a call to
> local_clock() which (on x86) is a direct call to the hardware.  These
> hardware clock reads are not modified by the standard ntp or ptp protocol,
> while the other timestamps are, and that results in situations external
> time sources are further and further offset from the kernel log
> timestamps.
> 
> This patch introduces printk.time=[0-3] allowing a user to specify an adjusted
> clock to use with printk timestamps.  The hardware clock, or the existing
> functionality, is preserved by default.
> 
> Real clock & 32-bit systems:  Selecting the real clock printk timestamp may
> lead to unlikely situations where a timestamp is wrong because the real time
> offset is read without the protection of a sequence lock in the call to
> ktime_get_log_ts() in printk_get_ts().

Looks OK to me.  Timekeeping stuff makes my head spin nowadays but I
trust you've sorted out the obvious deadlock/reentrancy/etc issues. 
I'll toss it in for some testing.

> @@ -1042,6 +1044,12 @@ static inline void boot_delay_msec(int level)
>  
>  static int printk_time = CONFIG_PRINTK_TIME;
>  
> +/*
> + * Real clock & 32-bit systems:  Selecting the real clock printk timestamp may
> + * lead to unlikely situations where a timestamp is wrong because the real time
> + * offset is read without the protection of a sequence lock in the call to
> + * ktime_get_log_ts() in printk_get_ts() below.
> + */
>  static int printk_time_param_set(const char *val,
>  				 const struct kernel_param *kp)
>  {
> @@ -1063,6 +1071,14 @@ static int printk_time_param_set(const char *val,
>  	case 'y':
>  		printk_time = 1;
>  		break;
> +	/* 2 = monotonic clock */
> +	case '2':
> +		printk_time = 2;
> +		break;
> +	/* 3 = real clock */
> +	case '3':
> +		printk_time = 3;
> +		break;

Maybe it's time to enumerate these values.

>  	default:
>  		pr_warn("printk: invalid timestamp value\n");
>  		return -EINVAL;
> @@ -1080,6 +1096,21 @@ static struct kernel_param_ops printk_time_param_ops = {
>  
>  module_param_cb(time, &printk_time_param_ops, &printk_time, S_IRUGO);
>  
> +static u64 printk_get_ts(void)
> +{
> +	u64 mono, offset_real;
> +
> +	if (printk_time <= 1)
> +		return local_clock();
> +
> +	mono = ktime_get_log_ts(&offset_real);
> +
> +	if (printk_time == 2)
> +		return mono;
> +
> +	return mono + offset_real;
> +}

Because the magic constants set a bad example for any children in the
audience.