Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1381838 > unrolled thread

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

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [PATCH 0/2 v6] printk, Add monotonic and real printk timestamps Prarit Bhargava <prarit@redhat.com> - 2016-04-18 17:40 +0200
    Re: [PATCH 0/2 v6] printk, Add monotonic and real printk timestamps Petr Mladek <pmladek@suse.com> - 2016-04-19 11:00 +0200
      Re: [PATCH 0/2 v6] printk, Add monotonic and real printk timestamps Prarit Bhargava <prarit@redhat.com> - 2016-04-20 19:10 +0200
      Re: [PATCH 0/2 v6] printk, Add monotonic and real printk timestamps Prarit Bhargava <prarit@redhat.com> - 2016-04-21 15:30 +0200
        Re: [PATCH 0/2 v6] printk, Add monotonic and real printk timestamps Petr Mladek <pmladek@suse.com> - 2016-04-26 15:10 +0200

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

On 03/10/2016 05:00 AM, Petr Mladek wrote:
> On Tue 2016-03-08 06:03:24, Prarit Bhargava wrote:
>>
>>
>> On 03/08/2016 02:59 AM, Thomas Gleixner wrote:
>>> On Tue, 23 Feb 2016, Prarit Bhargava wrote:
>>>
>>>> This patchset adds monotonic and real printk timestamps.  The first patch
>>>> changes CONFIG_PRINT_TIME from a bool to an int to allow for the additional
>>>> timestamps that are added in patch 2.
>>>>
>>>> Changes from v6: Petr Mladek pointed out that the current patch
>>>> fails to indicate to userspace programs which timestamp is being used.
>>>
>>> How is that solved?
>>
>> Hi Thomas,
>>
>> Userspace programs can now look at /sys/modules/printk/parameters/time which
>> will contain [0-3] for the timestamp clock.
> 
> But it includes only the current setting that is valid only for
> messages printed with this setting. The ring buffer might include
> different messages produced with different setting.
> 
> I suggest to look how dmesg handles the time stamp. I wonder how it
> converts the relative time into an absolute one. I wonder if you
> could convert all timestamps to the relative format, so that you
> do not need to change all userspace tools at all.

I looked into this and the only thing I can come up with is that I modify the
patchset to allow users to set the timestamp type at boot but not runtime.
Having to set it at runtime would require additional timestamp information be
added to the output of /dev/kmsg.

Petr -- the dmesg code can be found in the utils-linux package,
sys-utils/dmesg.c.  The timestamping displaying code is this function:

static struct tm *record_localtime(struct dmesg_control *ctl,
                                   struct dmesg_record *rec,
                                   struct tm *tm)
{
        time_t t = ctl->boot_time + rec->tv.tv_sec;
        return localtime_r(&t, tm);
}

If you have any suggestion on how to modify it, I'm more than willing to do it.
 If not, then I suggest I change the code to make the timestamp RO during runtime.

P.
> 
> Best regards,
> Petr
> 

[toc] | [next] | [standalone]

#1382296

On Mon 2016-04-18 11:30:52, Prarit Bhargava wrote:
> 
> 
> On 03/10/2016 05:00 AM, Petr Mladek wrote:
> > On Tue 2016-03-08 06:03:24, Prarit Bhargava wrote:
> >>
> >>
> >> On 03/08/2016 02:59 AM, Thomas Gleixner wrote:
> >>> On Tue, 23 Feb 2016, Prarit Bhargava wrote:
> >>>
> >>>> This patchset adds monotonic and real printk timestamps.  The first patch
> >>>> changes CONFIG_PRINT_TIME from a bool to an int to allow for the additional
> >>>> timestamps that are added in patch 2.
> >>>>
> >>>> Changes from v6: Petr Mladek pointed out that the current patch
> >>>> fails to indicate to userspace programs which timestamp is being used.
> >>>
> >>> How is that solved?
> >>
> >> Hi Thomas,
> >>
> >> Userspace programs can now look at /sys/modules/printk/parameters/time which
> >> will contain [0-3] for the timestamp clock.
> > 
> > But it includes only the current setting that is valid only for
> > messages printed with this setting. The ring buffer might include
> > different messages produced with different setting.
> > 
> > I suggest to look how dmesg handles the time stamp. I wonder how it
> > converts the relative time into an absolute one. I wonder if you
> > could convert all timestamps to the relative format, so that you
> > do not need to change all userspace tools at all.
> 
> I looked into this and the only thing I can come up with is that I modify the
> patchset to allow users to set the timestamp type at boot but not runtime.
> Having to set it at runtime would require additional timestamp information be
> added to the output of /dev/kmsg.
> 
> Petr -- the dmesg code can be found in the utils-linux package,
> sys-utils/dmesg.c.  The timestamping displaying code is this function:
> 
> static struct tm *record_localtime(struct dmesg_control *ctl,
>                                    struct dmesg_record *rec,
>                                    struct tm *tm)
> {
>         time_t t = ctl->boot_time + rec->tv.tv_sec;
>         return localtime_r(&t, tm);
> }
>
> If you have any suggestion on how to modify it, I'm more than willing to do it.
>  If not, then I suggest I change the code to make the timestamp RO during runtime.

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.

And you need to modify also the other tools, e.g. crash.


Best Regards,
Petr

[toc] | [prev] | [next] | [standalone]

#1383567

On 04/19/2016 04:56 AM, Petr Mladek wrote:
> On Mon 2016-04-18 11:30:52, Prarit Bhargava wrote:
>>
>>
>> On 03/10/2016 05:00 AM, Petr Mladek wrote:
>>> On Tue 2016-03-08 06:03:24, Prarit Bhargava wrote:
>>>>
>>>>
>>>> On 03/08/2016 02:59 AM, Thomas Gleixner wrote:
>>>>> On Tue, 23 Feb 2016, Prarit Bhargava wrote:
>>>>>
>>>>>> This patchset adds monotonic and real printk timestamps.  The first patch
>>>>>> changes CONFIG_PRINT_TIME from a bool to an int to allow for the additional
>>>>>> timestamps that are added in patch 2.
>>>>>>
>>>>>> Changes from v6: Petr Mladek pointed out that the current patch
>>>>>> fails to indicate to userspace programs which timestamp is being used.
>>>>>
>>>>> How is that solved?
>>>>
>>>> Hi Thomas,
>>>>
>>>> Userspace programs can now look at /sys/modules/printk/parameters/time which
>>>> will contain [0-3] for the timestamp clock.
>>>
>>> But it includes only the current setting that is valid only for
>>> messages printed with this setting. The ring buffer might include
>>> different messages produced with different setting.
>>>
>>> I suggest to look how dmesg handles the time stamp. I wonder how it
>>> converts the relative time into an absolute one. I wonder if you
>>> could convert all timestamps to the relative format, so that you
>>> do not need to change all userspace tools at all.
>>
>> I looked into this and the only thing I can come up with is that I modify the
>> patchset to allow users to set the timestamp type at boot but not runtime.
>> Having to set it at runtime would require additional timestamp information be
>> added to the output of /dev/kmsg.
>>
>> Petr -- the dmesg code can be found in the utils-linux package,
>> sys-utils/dmesg.c.  The timestamping displaying code is this function:
>>
>> static struct tm *record_localtime(struct dmesg_control *ctl,
>>                                    struct dmesg_record *rec,
>>                                    struct tm *tm)
>> {
>>         time_t t = ctl->boot_time + rec->tv.tv_sec;
>>         return localtime_r(&t, tm);
>> }
>>
>> If you have any suggestion on how to modify it, I'm more than willing to do it.
>>  If not, then I suggest I change the code to make the timestamp RO during runtime.
> 
> 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?

0.0000 is printed out before the clock is initialized.   I'll make sure it does
the right thing.

> 
> Also note that you still need to modify the dmesg code. It must
> not add boot_time when real time timestamp is used.
> 

Yep.  It looks like the output of the ctime and iso timestamps need to be verified.

> And you need to modify also the other tools, e.g. crash.

I'm going to talk with anderson@redhat.com about this tomorrow.

P.
> 
> 
> Best Regards,
> Petr
> 

[toc] | [prev] | [next] | [standalone]

#1384219

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

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

IMO dmesg is the big one and I will modify that after I see acceptance
of this patch.

P.

[toc] | [prev] | [next] | [standalone]

#1387453

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

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web