On Fri, 22 Apr 2016 08:03:09 -0400 Prarit Bhargava <pra...@redhat.com> 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.
