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(a)laoqinren.net&gt; --- 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