On Apr 19, 2020, at 4:01 PM, crash-utility-request(a)redhat.com wrote: Send Crash-utility mailing list submissions to crash-utility(a)redhat.com To subscribe or unsubscribe via the World Wide Web, visit https://www.redhat.com/mailman/listinfo/crash-utility or, via email, send a message with subject or body 'help' to crash-utility-request(a)redhat.com You can reach the person managing the list at crash-utility-owner(a)redhat.com When replying, please edit your Subject line so it is more specific than "Re: Contents of Crash-utility digest..." Today's Topics: 1. Re: [PATCH] add log -T option to display the message text with human readable timestamp (Dave Anderson) 2. Re: [PATCH] add log -T option to display the message text with human readable timestamp (Dave Anderson) 3. Re: [PATCH] add log -T option to display the message text with human readable timestamp (Moore, Martin (Linux ERT)) ---------------------------------------------------------------------- Message: 1 Date: Sun, 19 Apr 2020 15:34:46 -0400 (EDT) From: Dave Anderson <anderson(a)redhat.com&gt; To: Wang Long <w(a)laoqinren.net&gt; Cc: crash-utility(a)redhat.com Subject: Re: [Crash-utility] [PATCH] add log -T option to display the message text with human readable timestamp Message-ID: <116726603.23908736.1587324886732.JavaMail.zimbra(a)redhat.com&gt; Content-Type: text/plain; charset=utf-8 ----- 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 > > > > ------------------------------ Message: 2 Date: Sun, 19 Apr 2020 15:48:55 -0400 (EDT) From: Dave Anderson <anderson(a)redhat.com&gt; To: "Discussion list for crash utility usage, maintenance and development" <crash-utility(a)redhat.com&gt; Subject: Re: [Crash-utility] [PATCH] add log -T option to display the message text with human readable timestamp Message-ID: <2105444223.23908999.1587325735354.JavaMail.zimbra(a)redhat.com&gt; Content-Type: text/plain; charset=utf-8 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 > ------------------------------ Message: 3 Date: Sun, 19 Apr 2020 20:01:12 +0000 From: "Moore, Martin (Linux ERT)" <martin.moore(a)hpe.com&gt; To: "Discussion list for crash utility usage, maintenance and development" <crash-utility(a)redhat.com&gt;, &quot;anderson(a)redhat.com&quot; <anderson(a)redhat.com&gt; Subject: Re: [Crash-utility] [PATCH] add log -T option to display the message text with human readable timestamp Message-ID: <AT5PR8401MB05480CDBEEE71C6F900654B991D70(a)AT5PR8401MB0548.NAMPRD84.PROD.OUTLOOK.COM&gt; Content-Type: text/plain; charset=WINDOWS-1252 Just to mention an alternative possibility, the pykdump extension to crash (https://sourceforge.net/projects/pykdump/) includes the 'tslog' command to accomplish this. Martin Moore Linux Engineering Resolution Team HPE Pointnext Services Hewlett Packard Enterprise Martin.Moore(a)hpe.com? 8AM-5PM EDT (GMT-4) Monday-Friday Manager: Becky McBride (becky.mcbride(a)hpe.com) -----Original Message----- From: crash-utility-bounces(a)redhat.com <crash-utility-bounces(a)redhat.com&gt; On Behalf Of Wang Long Sent: Saturday, April 18, 2020 10:21 PM To: anderson(a)redhat.com; crash-utility(a)redhat.com Subject: [Crash-utility] [PATCH] add log -T option to display the message text with human readable timestamp 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 -- Crash-utility mailing list Crash-utility(a)redhat.com https://www.redhat.com/mailman/listinfo/crash-utility ------------------------------ -- Crash-utility mailing list Crash-utility(a)redhat.com https://www.redhat.com/mailman/listinfo/crash-utility End of Crash-utility Digest, Vol 175, Issue 27 **********************************************