Util-Linux Archive on lore.kernel.org
 help / color / Atom feed
* [PATCH util-linux] dmesg: adjust timestamps according to suspended time
@ 2020-06-01 19:21 Konstantin Khlebnikov
  2020-06-04  9:30 ` Karel Zak
  2020-06-04  9:35 ` Karel Zak
  0 siblings, 2 replies; 5+ messages in thread
From: Konstantin Khlebnikov @ 2020-06-01 19:21 UTC (permalink / raw)
  To: util-linux; +Cc: linux-kernel

Timestamps in kernel log comes from monotonic clocksource which does not
tick when system suspended. Suspended time easily sums into hours and days
rendering human readable timestamps in dmesg useless.

Adjusting timestamps accouring to current delta between boottime and
monotonic clocksources produces accurate timestamps for messages printed
since last resume. Which are supposed to be most interesting.

Signed-off-by: Konstantin Khlebnikov <khlebnikov@yandex-team.ru>
---
 include/monotonic.h |    2 ++
 lib/monotonic.c     |   12 ++++++++++++
 sys-utils/dmesg.1   |    2 ++
 sys-utils/dmesg.c   |   22 +++++++++++++++++-----
 4 files changed, 33 insertions(+), 5 deletions(-)

diff --git a/include/monotonic.h b/include/monotonic.h
index 7a69d9e4b51e..380e59c3791e 100644
--- a/include/monotonic.h
+++ b/include/monotonic.h
@@ -15,6 +15,8 @@
 
 extern int get_boot_time(struct timeval *boot_time);
 
+extern time_t get_suspended_time(void);
+
 extern int gettime_monotonic(struct timeval *tv);
 
 #endif /* UTIL_LINUX_MONOTONIC_H */
diff --git a/lib/monotonic.c b/lib/monotonic.c
index b684d8dd650a..f0aeba6828e7 100644
--- a/lib/monotonic.c
+++ b/lib/monotonic.c
@@ -48,6 +48,18 @@ int get_boot_time(struct timeval *boot_time)
 #endif
 }
 
+time_t get_suspended_time(void)
+{
+#if defined(CLOCK_BOOTTIME) && defined(CLOCK_MONOTONIC)
+	struct timespec boot, mono;
+
+	if (clock_gettime(CLOCK_BOOTTIME, &boot) == 0 &&
+	    clock_gettime(CLOCK_MONOTONIC, &mono) == 0)
+		return boot.tv_sec - mono.tv_sec;
+#endif
+	return 0;
+}
+
 int gettime_monotonic(struct timeval *tv)
 {
 #ifdef CLOCK_MONOTONIC
diff --git a/sys-utils/dmesg.1 b/sys-utils/dmesg.1
index 61a6ce89465d..6c5773a6b211 100644
--- a/sys-utils/dmesg.1
+++ b/sys-utils/dmesg.1
@@ -161,6 +161,8 @@ source used for the logs is
 .B not updated after
 system
 .BR SUSPEND / RESUME .
+Timestamps are adjusted according to current delta between boottime and monotonic
+clocks, this works only for messages printed after last resume.
 .IP "\fB\-t\fR, \fB\-\-notime\fR"
 Do not print kernel's timestamps.
 .IP "\fB\-\-time\-format\fR \fIformat\fR"
diff --git a/sys-utils/dmesg.c b/sys-utils/dmesg.c
index ae1ebc74a2d9..c78f01ca8755 100644
--- a/sys-utils/dmesg.c
+++ b/sys-utils/dmesg.c
@@ -169,6 +169,7 @@ struct dmesg_control {
 	struct timeval	lasttime;	/* last printed timestamp */
 	struct tm	lasttm;		/* last localtime */
 	struct timeval	boot_time;	/* system boot time */
+	time_t		suspended_time;	/* time spent in suspeneded state */
 
 	int		action;		/* SYSLOG_ACTION_* */
 	int		method;		/* DMESG_METHOD_* */
@@ -824,7 +825,7 @@ static struct tm *record_localtime(struct dmesg_control *ctl,
 				   struct dmesg_record *rec,
 				   struct tm *tm)
 {
-	time_t t = ctl->boot_time.tv_sec + rec->tv.tv_sec;
+	time_t t = ctl->boot_time.tv_sec + ctl->suspended_time + rec->tv.tv_sec;
 	return localtime_r(&t, tm);
 }
 
@@ -852,7 +853,7 @@ static char *iso_8601_time(struct dmesg_control *ctl, struct dmesg_record *rec,
 			   char *buf, size_t bufsz)
 {
 	struct timeval tv = {
-		.tv_sec = ctl->boot_time.tv_sec + rec->tv.tv_sec,
+		.tv_sec = ctl->boot_time.tv_sec + ctl->suspended_time + rec->tv.tv_sec,
 		.tv_usec = rec->tv.tv_usec
 	};
 
@@ -1301,8 +1302,16 @@ static inline int dmesg_get_boot_time(struct timeval *tv)
 
 	return get_boot_time(tv);
 }
+
+static inline time_t dmesg_get_suspended_time(void)
+{
+	if (getenv("DMESG_TEST_BOOTIME"))
+		return 0;
+	return get_suspended_time();
+}
 #else
 # define dmesg_get_boot_time	get_boot_time
+# define dmesg_get_suspended_time	get_suspended_time
 #endif
 
 int main(int argc, char *argv[])
@@ -1499,9 +1508,12 @@ int main(int argc, char *argv[])
 
 	if ((is_timefmt(&ctl, RELTIME) ||
 	     is_timefmt(&ctl, CTIME)   ||
-	     is_timefmt(&ctl, ISO8601))
-	    && dmesg_get_boot_time(&ctl.boot_time) != 0)
-		ctl.time_fmt = DMESG_TIMEFTM_NONE;
+	     is_timefmt(&ctl, ISO8601))) {
+		if (dmesg_get_boot_time(&ctl.boot_time) != 0)
+			ctl.time_fmt = DMESG_TIMEFTM_NONE;
+		else
+			ctl.suspended_time = dmesg_get_suspended_time();
+	}
 
 	if (delta)
 		switch (ctl.time_fmt) {


^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH util-linux] dmesg: adjust timestamps according to suspended time
  2020-06-01 19:21 [PATCH util-linux] dmesg: adjust timestamps according to suspended time Konstantin Khlebnikov
@ 2020-06-04  9:30 ` Karel Zak
  2020-06-04  9:43   ` Konstantin Khlebnikov
  2020-06-04  9:35 ` Karel Zak
  1 sibling, 1 reply; 5+ messages in thread
From: Karel Zak @ 2020-06-04  9:30 UTC (permalink / raw)
  To: Konstantin Khlebnikov; +Cc: util-linux, linux-kernel

On Mon, Jun 01, 2020 at 10:21:34PM +0300, Konstantin Khlebnikov wrote:
> Timestamps in kernel log comes from monotonic clocksource which does not
> tick when system suspended. Suspended time easily sums into hours and days
> rendering human readable timestamps in dmesg useless.
> 
> Adjusting timestamps accouring to current delta between boottime and
> monotonic clocksources produces accurate timestamps for messages printed
> since last resume. Which are supposed to be most interesting.

It's definitely better than the current broken timestamps, but the real
and final solution is to have exact information about system suspends.

It would be enough to maintain in kernel memory a simple log with
   <bootime> <monotonic> <state_change>
and export this info by /proc/suspendlog, after that we can all 
re-count /dev/kmsg timestamps to something useful.

  Karel


-- 
 Karel Zak  <kzak@redhat.com>
 http://karelzak.blogspot.com


^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH util-linux] dmesg: adjust timestamps according to suspended time
  2020-06-01 19:21 [PATCH util-linux] dmesg: adjust timestamps according to suspended time Konstantin Khlebnikov
  2020-06-04  9:30 ` Karel Zak
@ 2020-06-04  9:35 ` Karel Zak
  1 sibling, 0 replies; 5+ messages in thread
From: Karel Zak @ 2020-06-04  9:35 UTC (permalink / raw)
  To: Konstantin Khlebnikov; +Cc: util-linux

On Mon, Jun 01, 2020 at 10:21:34PM +0300, Konstantin Khlebnikov wrote:
>  include/monotonic.h |    2 ++
>  lib/monotonic.c     |   12 ++++++++++++
>  sys-utils/dmesg.1   |    2 ++
>  sys-utils/dmesg.c   |   22 +++++++++++++++++-----
>  4 files changed, 33 insertions(+), 5 deletions(-)

Applied, thanks.

-- 
 Karel Zak  <kzak@redhat.com>
 http://karelzak.blogspot.com


^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH util-linux] dmesg: adjust timestamps according to suspended time
  2020-06-04  9:30 ` Karel Zak
@ 2020-06-04  9:43   ` Konstantin Khlebnikov
  2020-06-04 10:21     ` Karel Zak
  0 siblings, 1 reply; 5+ messages in thread
From: Konstantin Khlebnikov @ 2020-06-04  9:43 UTC (permalink / raw)
  To: Karel Zak; +Cc: util-linux, linux-kernel

On 04/06/2020 12.30, Karel Zak wrote:
> On Mon, Jun 01, 2020 at 10:21:34PM +0300, Konstantin Khlebnikov wrote:
>> Timestamps in kernel log comes from monotonic clocksource which does not
>> tick when system suspended. Suspended time easily sums into hours and days
>> rendering human readable timestamps in dmesg useless.
>>
>> Adjusting timestamps accouring to current delta between boottime and
>> monotonic clocksources produces accurate timestamps for messages printed
>> since last resume. Which are supposed to be most interesting.
> 
> It's definitely better than the current broken timestamps, but the real
> and final solution is to have exact information about system suspends.
> 
> It would be enough to maintain in kernel memory a simple log with
>     <bootime> <monotonic> <state_change>
> and export this info by /proc/suspendlog, after that we can all
> re-count /dev/kmsg timestamps to something useful.

Boottime or real time could be simply printed into kernel log at
suspend and resume. So demsg could detect current offset while reading.

But for older kernel dmesg still needs guessing like this.

> 
>    Karel
> 
> 

^ permalink raw reply	[flat|nested] 5+ messages in thread

* Re: [PATCH util-linux] dmesg: adjust timestamps according to suspended time
  2020-06-04  9:43   ` Konstantin Khlebnikov
@ 2020-06-04 10:21     ` Karel Zak
  0 siblings, 0 replies; 5+ messages in thread
From: Karel Zak @ 2020-06-04 10:21 UTC (permalink / raw)
  To: Konstantin Khlebnikov; +Cc: util-linux, linux-kernel

On Thu, Jun 04, 2020 at 12:43:52PM +0300, Konstantin Khlebnikov wrote:
> On 04/06/2020 12.30, Karel Zak wrote:
> > On Mon, Jun 01, 2020 at 10:21:34PM +0300, Konstantin Khlebnikov wrote:
> > > Timestamps in kernel log comes from monotonic clocksource which does not
> > > tick when system suspended. Suspended time easily sums into hours and days
> > > rendering human readable timestamps in dmesg useless.
> > > 
> > > Adjusting timestamps accouring to current delta between boottime and
> > > monotonic clocksources produces accurate timestamps for messages printed
> > > since last resume. Which are supposed to be most interesting.
> > 
> > It's definitely better than the current broken timestamps, but the real
> > and final solution is to have exact information about system suspends.
> > 
> > It would be enough to maintain in kernel memory a simple log with
> >     <bootime> <monotonic> <state_change>
> > and export this info by /proc/suspendlog, after that we can all
> > re-count /dev/kmsg timestamps to something useful.
> 
> Boottime or real time could be simply printed into kernel log at
> suspend and resume. So demsg could detect current offset while reading.

 Yes, but not sure if this is the most robust way (dmesg --clear will
 remove this info) and I guess the suspendlog can be useful
 independently on kmsg.

    Karel

-- 
 Karel Zak  <kzak@redhat.com>
 http://karelzak.blogspot.com


^ permalink raw reply	[flat|nested] 5+ messages in thread

end of thread, back to index

Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-06-01 19:21 [PATCH util-linux] dmesg: adjust timestamps according to suspended time Konstantin Khlebnikov
2020-06-04  9:30 ` Karel Zak
2020-06-04  9:43   ` Konstantin Khlebnikov
2020-06-04 10:21     ` Karel Zak
2020-06-04  9:35 ` Karel Zak

Util-Linux Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/util-linux/0 util-linux/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 util-linux util-linux/ https://lore.kernel.org/util-linux \
		util-linux@vger.kernel.org
	public-inbox-index util-linux

Example config snippet for mirrors

Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.util-linux


AGPL code for this site: git clone https://public-inbox.org/public-inbox.git