From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752380AbcDVTrg (ORCPT ); Fri, 22 Apr 2016 15:47:36 -0400 Received: from mail.linuxfoundation.org ([140.211.169.12]:57272 "EHLO mail.linuxfoundation.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750902AbcDVTre (ORCPT ); Fri, 22 Apr 2016 15:47:34 -0400 Date: Fri, 22 Apr 2016 12:47:30 -0700 From: Andrew Morton To: Prarit Bhargava Cc: linux-kernel@vger.kernel.org, "Cc: Petr Mladek" , John Stultz , Xunlei Pang , Thomas Gleixner , Baolin Wang , Greg Kroah-Hartman , Petr Mladek , Tejun Heo , Peter Hurley , Vasily Averin , Joe Perches Subject: Re: [PATCH 2/2] printk, allow different timestamps for printk.time Message-Id: <20160422124730.fc690cac6d713f8e8aef92ed@linux-foundation.org> In-Reply-To: <1461326589-27722-3-git-send-email-prarit@redhat.com> References: <1461326589-27722-1-git-send-email-prarit@redhat.com> <1461326589-27722-3-git-send-email-prarit@redhat.com> X-Mailer: Sylpheed 3.4.1 (GTK+ 2.24.23; x86_64-pc-linux-gnu) Mime-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Fri, 22 Apr 2016 08:03:09 -0400 Prarit Bhargava 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.