Re: [PATCH 0/2 v6] printk, Add monotonic and real printk timestamps

[Petr Mladek <pmladek@suse.com>]

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.
>