From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752804AbcDZNBG (ORCPT ); Tue, 26 Apr 2016 09:01:06 -0400 Received: from mx2.suse.de ([195.135.220.15]:39137 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752305AbcDZNBB (ORCPT ); Tue, 26 Apr 2016 09:01:01 -0400 Date: Tue, 26 Apr 2016 15:00:57 +0200 From: Petr Mladek To: Prarit Bhargava Cc: Thomas Gleixner , linux-kernel@vger.kernel.org, John Stultz , Xunlei Pang , Baolin Wang , Andrew Morton , Greg Kroah-Hartman , Tejun Heo , Peter Hurley , Vasily Averin , Joe Perches Subject: Re: [PATCH 0/2 v6] printk, Add monotonic and real printk timestamps Message-ID: <20160426130057.GD19702@pathway.suse.cz> References: <1456250040-22351-1-git-send-email-prarit@redhat.com> <56DEB17C.9000201@redhat.com> <20160310100012.GQ10940@pathway.suse.cz> <5714FDAC.4080208@redhat.com> <20160419085613.GJ6862@pathway.suse.cz> <5718D3A9.6070005@redhat.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <5718D3A9.6070005@redhat.com> User-Agent: Mutt/1.5.21 (2010-09-15) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Thu 2016-04-21 09:20:41, Prarit Bhargava wrote: > > > On 04/19/2016 04:56 AM, Petr Mladek wrote: > > On Mon 2016-04-18 11:30:52, Prarit Bhargava wrote: > > > Hmm, If you allow to change the timestamp format only at boot time, it > > will make things easier. I just wonder if it would work correctly for > > early messages. For example, are there any messages printed before > > the real time clock is initialized? Which timestamp will they use? > > > > Also note that you still need to modify the dmesg code. It must > > not add boot_time when real time timestamp is used. > > > > I've got a util-linux patch in-hand that does this (sorry for the > cut-and-paste) and I've verified that ctime, delta, iso, notime and > reltime all appear to work 1) without my kernel patches applied, > 2) with my kernel patches applied, and 3) with printk.time=[0-3] > as kernel parameters. > > diff --git a/sys-utils/dmesg.c b/sys-utils/dmesg.c > index cf93331..c49a202 100644 > --- a/sys-utils/dmesg.c > +++ b/sys-utils/dmesg.c > @@ -1194,9 +1194,31 @@ static int which_time_format(const char *optarg) > errx(EXIT_FAILURE, _("unknown time format: %s"), optarg); > } > > -#ifdef TEST_DMESG > +static int needs_boot_time(void) > +{ > + FILE *fd; > + int ret = 1; > + int val; > + > + /* > + * Newer kernels have /sys/modules/printk/parameter/time = [0-3] > + * where 0 = off, 1 = local clock, 2 = boot time, and 3 = real time. > + * If the file isn't present it means the functionality isn't there > + * and the boot_time offset is needed. > + */ > + fd = fopen("/sys/module/printk/parameters/time", "r"); > + if (!fd) > + return ret; > + fscanf(fd, "%d", &val); > + if (val == 3) > + ret = 0; > + fclose(fd); > + return ret; > +} > + > static inline int dmesg_get_boot_time(struct timeval *tv) > { > +#ifdef TEST_DMESG > char *str = getenv("DMESG_TEST_BOOTIME"); > uintmax_t sec, usec; > > @@ -1205,12 +1227,15 @@ static inline int dmesg_get_boot_time(struct timeval *tv) > tv->tv_usec = usec; > return tv->tv_sec >= 0 && tv->tv_usec >= 0 ? 0 : -EINVAL; > } > +#endif > + > + if (needs_boot_time()) > + return get_boot_time(tv); > > - return get_boot_time(tv); > + tv->tv_sec = 0; > + tv->tv_usec = 0; > + return 0; > } > -#else > -# define dmesg_get_boot_time get_boot_time > -#endif > > int main(int argc, char *argv[]) > { > -- > 1.8.3.1 This produces the following result. The time stamp jumps when the timekeeping stuf gets initialized: dmesg [ 0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=4 [ 0.000000] NR_IRQS:524544 nr_irqs:456 16 [1461600428.402984] Console: colour dummy device 80x25 [1461600428.402984] console [tty0] enabled dmesg --time-format ctime [Thu Jan 1 01:00:00 1970] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=4 [Thu Jan 1 01:00:00 1970] NR_IRQS:524544 nr_irqs:456 16 [Mon Apr 25 18:07:08 2016] Console: colour dummy device 80x25 [Mon Apr 25 18:07:08 2016] console [tty0] enabled dmesg --time-format iso 1970-01-01T01:00:00,000000+0100 RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=4 1970-01-01T01:00:00,000000+0100 NR_IRQS:524544 nr_irqs:456 16 2016-04-25T18:07:08,402984+0200 Console: colour dummy device 80x25 2016-04-25T18:07:08,402984+0200 console [tty0] enabled dmesg --time-format reltime [ +0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=4 [ +0.000000] NR_IRQS:524544 nr_irqs:456 16 [Apr25 18:07] Console: colour dummy device 80x25 [ +0.000000] console [tty0] enabled I think that it would be better to fallback to the boot time before the timekeeping stuff is initialized. It is easy to detect because the timestamp is zero. I played with it. Please find an alternative patch below. I have got the following output with it: dmesg [ 0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=4 [ 0.000000] NR_IRQS:524544 nr_irqs:456 16 [1461600428.402984] Console: colour dummy device 80x25 [1461600428.402984] console [tty0] enabled dmesg --time-format ctime [Mon Apr 25 18:07:08 2016] Build-time adjustment of leaf fanout to 64. [Mon Apr 25 18:07:08 2016] RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [Mon Apr 25 18:07:08 2016] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=4 [Mon Apr 25 18:07:08 2016] NR_IRQS:524544 nr_irqs:456 16 dmesg --time-format iso 2016-04-25T18:07:08,000000+0200 Build-time adjustment of leaf fanout to 64. 2016-04-25T18:07:08,000000+0200 RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. 2016-04-25T18:07:08,000000+0200 RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=4 2016-04-25T18:07:08,000000+0200 NR_IRQS:524544 nr_irqs:456 16 dmesg --time-format reltime [ +0.000000] Build-time adjustment of leaf fanout to 64. [ +0.000000] RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ +0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=4 [ +0.000000] NR_IRQS:524544 nr_irqs:456 16 > > > And you need to modify also the other tools, e.g. crash. > > > > I spoke with anderson@redhat.com this morning and he agrees > that no change should be necessary for crash. A quick test shows that > the logging mechanism (dmesg or log) works after the patches are applied > and printk is in REALTIME mode. I see. crash shows the timestamp value as it. It does not have the ctime or iso modes that would add the boot time. > > IMO dmesg is the big one and I will modify that after I see acceptance > of this patch. OK, here is my alternative patch based on your one: --- sys-utils/dmesg.c.orig 2016-03-16 10:39:39.000000000 +0100 +++ sys-utils/dmesg.c 2016-04-26 14:36:52.403747573 +0200 @@ -170,6 +170,7 @@ struct dmesg_control { struct timeval lasttime; /* last printed timestamp */ struct tm lasttm; /* last localtime */ struct timeval boot_time; /* system boot time */ + int realtime_stamp; /* using realtime stamps */ int action; /* SYSLOG_ACTION_* */ int method; /* DMESG_METHOD_* */ @@ -800,7 +801,13 @@ static struct tm *record_localtime(struc struct dmesg_record *rec, struct tm *tm) { - time_t t = ctl->boot_time.tv_sec + rec->tv.tv_sec; + time_t t = rec->tv.tv_sec; + /* + * Use the boot time also when the real time stamp is zero. It was + * generated before the timekeeping stuff was initialized. + */ + if (!ctl->realtime_stamp || !t) + t += ctl->boot_time.tv_sec; return localtime_r(&t, tm); } @@ -1194,9 +1201,31 @@ static int which_time_format(const char errx(EXIT_FAILURE, _("unknown time format: %s"), optarg); } -#ifdef TEST_DMESG +static int use_realtime_stamp(void) +{ + FILE *fd; + int ret = 0; + int val; + + /* + * Newer kernels have /sys/modules/printk/parameter/time = [0-3] + * where 0 = off, 1 = local clock, 2 = boot time, and 3 = real time. + * If the file isn't present it means the functionality isn't there + * and the boot_time offset is needed. + */ + fd = fopen("/sys/module/printk/parameters/time", "r"); + if (!fd) + return 0; + fscanf(fd, "%d", &val); + if (val == 3) + ret = 1; + fclose(fd); + return ret; +} + static inline int dmesg_get_boot_time(struct timeval *tv) { +#ifdef TEST_DMESG char *str = getenv("DMESG_TEST_BOOTIME"); uintmax_t sec, usec; @@ -1205,12 +1234,9 @@ static inline int dmesg_get_boot_time(st tv->tv_usec = usec; return tv->tv_sec >= 0 && tv->tv_usec >= 0 ? 0 : -EINVAL; } - +#endif return get_boot_time(tv); } -#else -# define dmesg_get_boot_time get_boot_time -#endif int main(int argc, char *argv[]) { @@ -1396,6 +1422,7 @@ int main(int argc, char *argv[]) if (is_timefmt(&ctl, RELTIME) || is_timefmt(&ctl, CTIME) || is_timefmt(&ctl, ISO8601)) { + ctl.realtime_stamp = use_realtime_stamp(); if (dmesg_get_boot_time(&ctl.boot_time) != 0) ctl.time_fmt = DMESG_TIMEFTM_NONE; } > > P. >