Re: [PATCH 0/2 v6] printk, Add monotonic and real printk timestamps
From: Petr Mladek
Date: Tue Apr 26 2016 - 09:01:10 EST
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@xxxxxxxxxx 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.
>