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 | 22 ++++++++++++++++++++-- 3 files changed, 49 insertions(+), 3 deletions(-) diff --git a/defs.h b/defs.h index d8eda5e..1644dbd 100644 --- a/defs.h/ +++ b/defs.h @@ -689,6 +689,7 @@ struct kernel_table { /* kernel data */ ulong kernel_module; int mods_installed; struct timespec date; + struct timespec boot_date; char proc_version[BUFSIZE]; struct new_utsname utsname; uint kernel_version[3]; @@ -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..016d8d9 100644 --- a/kernel.c +++ b/kernel.c @@ -111,6 +111,8 @@ kernel_init() char *irq_desc_type_name; ulong pv_init_ops;/ struct gnu_request req; + ulonglong uptime_jiffies; + ulong uptime_sec; if (pc->flags & KERNEL_DEBUG_QUERY) return; @@ -294,6 +296,14 @@ kernel_init() } else error(INFO, "cannot determine base kernel version\n"); + 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 (CRASHDEBUG(1)) + fprintf(fp, "boot_date: %lx: %s\n", + kt->boot_date.tv_sec, strip_linefeeds(ctime(&kt->boot_date.tv_sec))); verify_version(); @@ -4912,9 +4922,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; @@ -5154,7 +5167,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); } -- 1.8.3.1

FWIW, I tried it on another RHEL7 machine running live, but then also on a RHEL8 kernel dumpfile, and they all hang:

$ crash vmlinux vmcore crash 7.2.9rc13 Copyright (C) 2002-2020 Red Hat, Inc. Copyright (C) 2004, 2005, 2006, 2010 IBM Corporation Copyright (C) 1999-2006 Hewlett-Packard Co Copyright (C) 2005, 2006, 2011, 2012 Fujitsu Limited Copyright (C) 2006, 2007 VA Linux Systems Japan K.K. Copyright (C) 2005, 2011 NEC Corporation Copyright (C) 1999, 2002, 2007 Silicon Graphics, Inc. Copyright (C) 1999, 2000, 2001, 2002 Mission Critical Linux, Inc. This program is free software, covered by the GNU General Public License, and you are welcome to change it and/or distribute copies of it under certain conditions. Enter "help copying" to see the conditions. This program has absolutely no warranty. Enter "help warranty" for details. GNU gdb (GDB) 7.6 Copyright (C) 2013 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-unknown-linux-gnu"... WARNING: kernel relocated [950MB]: patching 94929 gdb minimal_symbol values crash: start patch... ----- Original Message ----- > > > ----- Original Message ----- >> 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; > > Did you attempt this patch on a live system? Because your patch to > kernel_init() hangs the session. I didn't bother to investigate beyond > adding these two debug statements around your addition to kernel_init(): > > error(INFO, "start patch...\n"); > 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; > error(INFO, "end patch...\n"); > > And that's where it hangs: > > $ ./crash > > crash 7.2.9rc13 > Copyright (C) 2002-2020 Red Hat, Inc. > Copyright (C) 2004, 2005, 2006, 2010 IBM Corporation > Copyright (C) 1999-2006 Hewlett-Packard Co > Copyright (C) 2005, 2006, 2011, 2012 Fujitsu Limited > Copyright (C) 2006, 2007 VA Linux Systems Japan K.K. > Copyright (C) 2005, 2011 NEC Corporation > Copyright (C) 1999, 2002, 2007 Silicon Graphics, Inc. > Copyright (C) 1999, 2000, 2001, 2002 Mission Critical Linux, Inc. > This program is free software, covered by the GNU General Public License, > and you are welcome to change it and/or distribute copies of it under > certain conditions. Enter "help copying" to see the conditions. > This program has absolutely no warranty. Enter "help warranty" for > details. > > GNU gdb (GDB) 7.6 > Copyright (C) 2013 Free Software Foundation, Inc. > License GPLv3+: GNU GPL version 3 or later > <http://gnu.org/licenses/gpl.html> > This is free software: you are free to change and redistribute it. > There is NO WARRANTY, to the extent permitted by law. Type "show copying" > and "show warranty" for details. > This GDB was configured as "x86_64-unknown-linux-gnu"... > > WARNING: kernel relocated [796MB]: patching 85687 gdb minimal_symbol values > > crash: start patch... > > <hang> > > And it shows a cpu spinning at 100%: > > $ top > top - 15:26:43 up 38 days, 3:41, 5 users, load average: 1.00, 0.89, 0.65 > Tasks: 280 total, 2 running, 278 sleeping, 0 stopped, 0 zombie > %Cpu(s): 3.9 us, 8.7 sy, 0.0 ni, 87.3 id, 0.0 wa, 0.0 hi, 0.0 si, > 0.0 st > KiB Mem : 15907600 total, 455876 free, 1232832 used, 14218892 buff/cache > KiB Swap: 8060924 total, 7395580 free, 665344 used. 14176220 avail Mem > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND > 26668 root 20 0 350268 213688 5680 R 100.0 1.3 5:42.70 crash > 1707 root 20 0 115692 1184 688 S 0.3 0.0 2:16.52 > ksmtuned > 12852 anderson 20 0 4235240 274608 20320 S 0.3 1.7 601:46.85 > gnome-shell > 13060 anderson 20 0 804924 14100 3744 S 0.3 0.1 118:44.59 > gsd-color > 27045 anderson 20 0 172452 2532 1648 R 0.3 0.0 0:00.08 top > 1 root 20 0 210504 5592 3224 S 0.0 0.0 18:14.19 systemd > ... > > I'll let you figure it out... > > Dave > > > > > > >> --- >> defs.h | 2 ++ >> help.c | 28 +++++++++++++++++++++++++++- >> kernel.c | 22 ++++++++++++++++++++-- >> 3 files changed, 49 insertions(+), 3 deletions(-) >> >> diff --git a/defs.h b/defs.h >> index d8eda5e..1644dbd 100644 >> --- a/defs.h/ >> +++ b/defs.h >> @@ -689,6 +689,7 @@ struct kernel_table { /* kernel data >> */ >> ulong kernel_module; >> int mods_installed; >> struct timespec date; >> + struct timespec boot_date; >> char proc_version[BUFSIZE]; >> struct new_utsname utsname; >> uint kernel_version[3]; >> @@ -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..016d8d9 100644 >> --- a/kernel.c >> +++ b/kernel.c >> @@ -111,6 +111,8 @@ kernel_init() >> char *irq_desc_type_name; >> ulong pv_init_ops;/ >> struct gnu_request req; >> + ulonglong uptime_jiffies; >> + ulong uptime_sec; >> >> if (pc->flags & KERNEL_DEBUG_QUERY) >> return; >> @@ -294,6 +296,14 @@ kernel_init() >> } else >> error(INFO, "cannot determine base kernel version\n"); >> >> + 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 (CRASHDEBUG(1)) >> + fprintf(fp, "boot_date: %lx: %s\n", >> + kt->boot_date.tv_sec, strip_linefeeds(ctime(&kt->boot_date.tv_sec))); >> >> verify_version(); >> >> @@ -4912,9 +4922,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; >> @@ -5154,7 +5167,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); >> } >> -- >> 1.8.3.1 >> >> >> >> > > -- > Crash-utility mailing list > Crash-utility(a)redhat.com > https://www.redhat.com/mailman/listinfo/crash-utility >