[PATCH] dmesg.c: print human readable timestamp

[PATCH] dmesg.c: print human readable timestamp

[corentin.labbe]

[-- Attachment #1: Type: text/plain, Size: 146 bytes --]

Hello

This patch add the -H option to dmesg which allow to print human readable time instead of the number of seconds since boot.

Best regards,

[-- Attachment #2: dmesg.patch --]
[-- Type: text/x-patch, Size: 2743 bytes --]

--- dmesg.c.orig	2011-05-20 13:32:58.000000000 +0200
+++ dmesg.c	2011-05-20 13:58:09.000000000 +0200
@@ -35,6 +35,11 @@
 #include <stdlib.h>
 #include <sys/klog.h>
 #include <ctype.h>
+#include <sys/sysinfo.h>
+#include <time.h>
+#include <sys/time.h>
+#include <error.h>
+#include <errno.h>
 
 #include "c.h"
 #include "nls.h"
@@ -44,7 +49,7 @@
 static void __attribute__ ((noreturn)) usage(void)
 {
 	fprintf(stderr,
-		_("Usage: %s [-c] [-n level] [-r] [-s bufsize]\n"),
+		_("Usage: %s [-c] [-n level] [-r] [-s bufsize] [-H]\n"),
 		program_invocation_short_name);
 	exit(EXIT_FAILURE);
 
@@ -62,12 +67,16 @@
 	int  lastc;
 	int  cmd = 3;		/* Read all messages in the ring buffer */
 	int  raw = 0;
+	int hr = 0;/* hr for human readable*/
+	char *hr_date = NULL;
+	struct sysinfo info;
+	struct timeval mytv;
 
 	setlocale(LC_ALL, "");
 	bindtextdomain(PACKAGE, LOCALEDIR);
 	textdomain(PACKAGE);
 
-	while ((c = getopt(argc, argv, "crn:s:")) != -1) {
+	while ((c = getopt(argc, argv, "Hcrn:s:")) != -1) {
 		switch (c) {
 		case 'c':
 			cmd = 4;	/* Read and clear all messages */
@@ -79,6 +88,9 @@
 		case 'r':
 			raw = 1;
 			break;
+		case 'H':
+			hr = 1;
+			break;
 		case 's':
 			bufsize = strtol_or_err(optarg, _("failed to parse buffer size"));
 			if (bufsize < 4096)
@@ -140,12 +152,58 @@
 			if (buf[i] == '>')
 				i++;
 		}
+		if (hr > 0 && i > 0 && buf[i] == '[' && buf[i-1] == '>' && (buf[i+1] == ' ' || (buf[i+1] >= '0' && buf[i+1] <= '9'))) {
+			i++;
+			/* we will read all between those [] and convert them */
+			/* zap all spaces */
+			while (buf[i] == ' ')
+				i++;
+			hr = i;/* start of timestamp*/
+			while (buf[i] != '.')
+				i++;
+			/* end of timestamp */
+			buf[i] = '\0';
+			if (sysinfo(&info) != 0) {
+				error(0, errno, "sysinfo error\n");
+				free(buf);
+				free(hr_date);
+				exit(EXIT_FAILURE);
+			}
+			if (gettimeofday(&mytv, NULL) != 0) {
+				error(0, errno, "gettimeofday error\n");
+				free(buf);
+				free(hr_date);
+				exit(EXIT_FAILURE);
+			}
+			mytv.tv_sec -= info.uptime;
+			mytv.tv_sec += strtol(buf + hr, NULL, 10);
+			if (hr_date == NULL)
+				hr_date = malloc(256);/* ctime_r expect a buffer of 26 at minmum, 256 is enought */
+			if (hr_date == NULL) {
+				error(0, errno, "malloc error\n");
+				free(buf);
+				exit(EXIT_FAILURE);
+			}
+			if (ctime_r(&mytv.tv_sec, hr_date) == NULL) {
+				error(0, errno, "ctime_r error\n");
+				free(buf);
+				free(hr_date);
+				exit(EXIT_FAILURE);
+			}
+			hr_date[strlen(hr_date) - 1] = '\0';
+			printf("[%s]", hr_date);
+			i++;
+			while (buf[i] != ']')
+				i++;
+			i++;
+		}
 		lastc = buf[i];
 		putchar(lastc);
 	}
 	if (lastc != '\n')
 		putchar('\n');
 	free(buf);
+	free(hr_date);
 
 	return EXIT_SUCCESS;
 }

Re: [PATCH] dmesg.c: print human readable timestamp

[Karel Zak]

On Fri, May 20, 2011 at 02:06:21PM +0200, corentin.labbe wrote:
> 
> This patch add the -H option to dmesg which allow to print human
> readable time instead of the number of seconds since boot.

 Nice idea, but it's not so simple :-(

 The time stamp used for printk() is not based on normal system time
 (as you know from gettimeofday()). It uses cpu_clock() (IMHO to
 keep printk() robust and without xtime_lock).

 The problem is that the cpu_clock is not updated after system resume,
 so if you suspend (e.g. pm-suspend(8)) and resume than the dmesg -H
 command prints nonsenses...

 For example (copy & past from /var/log/messages):

  Jun 27 23:39:53 nb kernel: [50065.238635] PM: Syncing filesystems  ... done.
  Jun 28 20:23:29 nb kernel: [50065.284226] Freezing user space  processes ... (elapsed 0.09 seconds) done.
                              ^^^^^
 The first line is before suspend and second is after resume. The time
 stamp [50065.xxxxxx] is still the same although the system was
 suspended for almost whole day.
 
 The same system, the latest kernel message:

    # date
    Wed Jun 29 16:29:28 CEST 2011

    # mount /dev/sdb1 /mnt/test

    # ./sys-utils/dmesg -H | tail -1 
    [Tue Jun 28 11:10:41 2011] EXT4-fs (sdb1): mounted filesystem with ordered data mode. Opts: (null)


  Karel

Re: [PATCH] dmesg.c: print human readable timestamp

[corentin.labbe]

Le 29/06/2011 16:59, Karel Zak a écrit :
> On Fri, May 20, 2011 at 02:06:21PM +0200, corentin.labbe wrote:
>>
>> This patch add the -H option to dmesg which allow to print human
>> readable time instead of the number of seconds since boot.
>
>  Nice idea, but it's not so simple :-(
>
>  The time stamp used for printk() is not based on normal system time
>  (as you know from gettimeofday()). It uses cpu_clock() (IMHO to
>  keep printk() robust and without xtime_lock).
>
>  The problem is that the cpu_clock is not updated after system resume,
>  so if you suspend (e.g. pm-suspend(8)) and resume than the dmesg -H
>  command prints nonsenses...
>
>  For example (copy & past from /var/log/messages):
>
>   Jun 27 23:39:53 nb kernel: [50065.238635] PM: Syncing filesystems  ... done.
>   Jun 28 20:23:29 nb kernel: [50065.284226] Freezing user space  processes ... (elapsed 0.09 seconds) done.
>                               ^^^^^
>  The first line is before suspend and second is after resume. The time
>  stamp [50065.xxxxxx] is still the same although the system was
>  suspended for almost whole day.
>
>  The same system, the latest kernel message:
>
>     # date
>     Wed Jun 29 16:29:28 CEST 2011
>
>     # mount /dev/sdb1 /mnt/test
>
>     # ./sys-utils/dmesg -H | tail -1
>     [Tue Jun 28 11:10:41 2011] EXT4-fs (sdb1): mounted filesystem with ordered data mode. Opts: (null)
>
>
>   Karel
>

Perhaps we could keep my patch and add a warning about "problem with suspend/resume" (both at first line when -H is used and in manpages).
Like "Warning timestamp could be inaccurate if you have used SUSPEND/RESUME"

If you are agree with that I will update my patch accordingly.

Bests regards

Re: [PATCH] dmesg.c: print human readable timestamp

[Karel Zak]

On Mon, Jul 18, 2011 at 04:56:54PM +0200, corentin.labbe wrote:
> Perhaps we could keep my patch and add a warning about "problem with
> suspend/resume" (both at first line when -H is used and in
> manpages).  Like "Warning timestamp could be inaccurate if you have
> used SUSPEND/RESUME"

 I agree.

> If you are agree with that I will update my patch accordingly.

 I have already added this feature to the code.

 The latest dmesg(1) changes:

  * -T, --ctime       : print human readable timestamps

[Mon Jul 18 22:30:51 2011] Bluetooth: L2CAP ver 2.15
[Mon Jul 18 22:30:51 2011] Bluetooth: L2CAP socket layer initialized
[Mon Jul 18 22:30:51 2011] Bluetooth: BNEP (Ethernet Emulation) ver 1.3


  * -d, --show-delta  : display the time spent between messages.
                       (based on kernel scripts/show_delat).

[   37.727490 <    0.157379>] Bluetooth: L2CAP ver 2.15
[   37.729090 <    0.001600>] Bluetooth: L2CAP socket layer initialized
[   37.964308 <    0.235218>] Bluetooth: BNEP (Ethernet Emulation) ver 1.3


 It's possible to mix the options (dmesg -d -T):

[Mon Jul 18 22:30:51 2011 <    0.157379>] Bluetooth: L2CAP ver 2.15
[Mon Jul 18 22:30:51 2011 <    0.001600>] Bluetooth: L2CAP socket layer initialized
[Mon Jul 18 22:30:51 2011 <    0.235218>] Bluetooth: BNEP (Ethernet Emulation) ver 1.3


    Karel

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

RE: [PATCH] dmesg.c: print human readable timestamp

[Voelker, Bernhard]

Karel Zak wrote:

> The latest dmesg(1) changes:
>
>  * -T, --ctime       : print human readable timestamps

shouln'd -T and -t or -r be mutually exclusive?

Currently, -T wins over -t, and -r wins over -T.

Have a nice day,
Berny=

Re: [PATCH] dmesg.c: print human readable timestamp

[Karel Zak]

On Wed, Jul 20, 2011 at 03:33:04PM +0200, Voelker, Bernhard wrote:
> Karel Zak wrote:
> 
> > The latest dmesg(1) changes:
> >
> >  * -T, --ctime       : print human readable timestamps
> 
> shouln'd -T and -t or -r be mutually exclusive?
> 
> Currently, -T wins over -t, and -r wins over -T.

 Should be fixed now. Thanks!

    Karel

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

RE: [PATCH] dmesg.c: print human readable timestamp

[Voelker, Bernhard]

Karel Zak wrote:

> On Wed, Jul 20, 2011 at 03:33:04PM +0200, Voelker, Bernhard wrote:
>> Karel Zak wrote:
>>=20
>> > The latest dmesg(1) changes:
>> >
>> >  * -T, --ctime       : print human readable timestamps
>>=20
>> shouln'd -T and -t or -r be mutually exclusive?
>>=20
>> Currently, -T wins over -t, and -r wins over -T.
>
> Should be fixed now. Thanks!

It works. Thanks!

Have a nice day,
Berny=