[Crash-utility] [PATCH v2] add log -T option to display the message text with human readable timestamp

Wang Long w at laoqinren.net
Tue Apr 21 02:08:09 UTC 2020


Sometimes, we need to know the accurate time of the log, which
helps us analyze the problem.

add -T option(like dmesg -T command) for log command to display
the message text with human readable timestamp.

Signed-off-by: Wang Long <w at laoqinren.net>
---
 defs.h   |  2 ++
 help.c   | 28 +++++++++++++++++++++++++++-
 kernel.c | 23 +++++++++++++++++++++--
 3 files changed, 50 insertions(+), 3 deletions(-)

diff --git a/defs.h b/defs.h
index d8eda5e..4e57a56 100644
--- a/defs.h
+++ b/defs.h
@@ -763,6 +763,7 @@ struct kernel_table {                   /* kernel data */
 	} vmcoreinfo;
 	ulonglong flags2;
 	char *source_tree;
+	struct timespec boot_date;
 };
 
 /*
@@ -5577,6 +5578,7 @@ void dump_log(int);
 #define SHOW_LOG_DICT  (0x2)
 #define SHOW_LOG_TEXT  (0x4)
 #define SHOW_LOG_AUDIT (0x8)
+#define SHOW_LOG_CTIME (0x10)
 void set_cpu(int);
 void clear_machdep_cache(void);
 struct stack_hook *gather_text_list(struct bt_info *);
diff --git a/help.c b/help.c
index c443cad..1ee70f7 100644
--- a/help.c
+++ b/help.c
@@ -3892,12 +3892,13 @@ NULL
 char *help_log[] = {
 "log",
 "dump system message buffer",
-"[-tdma]",
+"[-Ttdma]",
 "  This command dumps the kernel log_buf contents in chronological order.  The",
 "  command supports the older log_buf formats, which may or may not contain a",
 "  timestamp inserted prior to each message, as well as the newer variable-length", 
 "  record format, where the timestamp is contained in each log entry's header.",
 "  ",
+"    -T  Display the message text with human readable timestamp.",
 "    -t  Display the message text without the timestamp; only applicable to the",
 "        variable-length record format.",
 "    -d  Display the dictionary of key/value pair properties that are optionally",
@@ -4031,6 +4032,31 @@ char *help_log[] = {
 "    type=1307 audit(1489384479.809:4346):  cwd=\"/proc\"",
 "    ...",
 " ",
+"  Display the message text with human readable timestamp.\n"
+"    %s> log -T",
+"    [Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable",
+"    [Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved",
+"    [Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved",
+"    [Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 0x0000000000100000-0x00000000dffeffff] usable",
+"    [Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 0x00000000dfff0000-0x00000000dfffffff] ACPI data",
+"    [Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 0x00000000fec00000-0x00000000fec00fff] reserved",
+"    [Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 0x00000000fee00000-0x00000000fee00fff] reserved",
+"    [Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved",
+"    [Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 0x0000000100000000-0x000000011fffffff] usable",
+"    [Sat Apr  4 07:41:09 2020] NX (Execute Disable) protection: active",
+"    [Sat Apr  4 07:41:09 2020] SMBIOS 2.5 present.",
+"    [Sat Apr  4 07:41:09 2020] DMI: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006",
+"    [Sat Apr  4 07:41:09 2020] Hypervisor detected: KVM",
+"    [Sat Apr  4 07:41:09 2020] kvm-clock: Using msrs 4b564d01 and 4b564d00",
+"    [Sat Apr  4 07:41:09 2020] kvm-clock: cpu 0, msr 6de01001, primary cpu clock",
+"    [Sat Apr  4 07:41:09 2020] kvm-clock: using sched offset of 11838753697 cycles",
+"    [Sat Apr  4 07:41:09 2020] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns",
+"    [Sat Apr  4 07:41:09 2020] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved",
+"    [Sat Apr  4 07:41:09 2020] e820: remove [mem 0x000a0000-0x000fffff] usable",
+"    [Sat Apr  4 07:41:09 2020] last_pfn = 0x120000 max_arch_pfn = 0x400000000",
+"    [Sat Apr  4 07:41:09 2020] MTRR default type: uncachable",
+"    [Sat Apr  4 07:41:09 2020] MTRR variable ranges disabled:",
+"    ...",
 NULL               
 };
 
diff --git a/kernel.c b/kernel.c
index 7604fac..7e68e6d 100644
--- a/kernel.c
+++ b/kernel.c
@@ -4912,9 +4912,12 @@ cmd_log(void)
 
 	msg_flags = 0;
 
-        while ((c = getopt(argcnt, args, "tdma")) != EOF) {
+        while ((c = getopt(argcnt, args, "Ttdma")) != EOF) {
                 switch(c)
                 {
+		case 'T':
+			msg_flags |= SHOW_LOG_CTIME;
+			break;
 		case 't':
 			msg_flags |= SHOW_LOG_TEXT;
 			break;
@@ -4936,6 +4939,15 @@ cmd_log(void)
         if (argerrs)
                 cmd_usage(pc->curcmd, SYNOPSIS);
 
+	if (kt->boot_date.tv_sec == 0) {
+		ulonglong uptime_jiffies;
+		ulong  uptime_sec;
+		get_uptime(NULL, &uptime_jiffies);
+		uptime_sec = (uptime_jiffies)/(ulonglong)machdep->hz;
+		kt->boot_date.tv_sec = kt->date.tv_sec - uptime_sec;
+		kt->boot_date.tv_nsec = 0;
+	}
+
 	if (msg_flags & SHOW_LOG_AUDIT) {
 		dump_audit();
 		return;
@@ -5154,7 +5166,12 @@ dump_log_entry(char *logptr, int msg_flags)
 	if ((msg_flags & SHOW_LOG_TEXT) == 0) {
 		nanos = (ulonglong)ts_nsec / (ulonglong)1000000000;
 		rem = (ulonglong)ts_nsec % (ulonglong)1000000000;
-		sprintf(buf, "[%5lld.%06ld] ", nanos, rem/1000);
+		if (msg_flags & SHOW_LOG_CTIME) {
+			time_t t = kt->boot_date.tv_sec + nanos;
+			sprintf(buf, "[%s] ", strip_linefeeds(ctime(&t)));
+		}
+		else
+			sprintf(buf, "[%5lld.%06ld] ", nanos, rem/1000);
 		ilen = strlen(buf);
 		fprintf(fp, "%s", buf);
 	}
@@ -6018,6 +6035,8 @@ dump_kernel_table(int verbose)
 		get_xtime(&kt->date);
         fprintf(fp, "          date: %s\n",
                 strip_linefeeds(ctime(&kt->date.tv_sec)));
+        fprintf(fp, "    boot_ date: %s\n",
+                strip_linefeeds(ctime(&kt->boot_date.tv_sec)));
         fprintf(fp, "  proc_version: %s\n", strip_linefeeds(kt->proc_version));
         fprintf(fp, "   new_utsname: \n");
         fprintf(fp, "      .sysname: %s\n", uts->sysname);
-- 
1.8.3.1







More information about the Crash-utility mailing list