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

2020-04-21 Thread Dave Anderson



- 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 

Hi Wang, 

This is a nice feature.  Note that I did add a stanza for 
backwards-compatibility 
with Linux 3.4 and earlier kernels that didn't have variable length records:

@@ -4962,6 +4974,8 @@ dump_log(int msg_flags)
return;
}
 
+   if (msg_flags & SHOW_LOG_CTIME)
+   option_not_supported('T');
if (msg_flags & SHOW_LOG_DICT)
option_not_supported('d');
if ((msg_flags & SHOW_LOG_TEXT) && STREQ(pc->curcmd, "log"))

Queued for crash-7.2.9:

  
https://github.com/crash-utility/crash/commit/c86250bce29f17610647772f838e1bb9d622ea8c

Thanks,
  Dave











> ---
>  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
> 0x-0x0009fbff] usable",
> +"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem
> 0x0009fc00-0x0009] reserved",
> +"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem
> 0x000f-0x000f] reserved",
> +"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem
> 0x0010-0xdffe] usable",
> +"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem
> 0xdfff-0xdfff] ACPI data",
> +"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem
> 0xfec0-0xfec00fff] reserved",
> +"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem
> 0xfee0-0xfee00fff] reserved",
> +"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem
> 0xfffc-0x] reserved",
> +"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem
> 0x0001-0x00011fff] 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:
> 0x max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns",
> +"[Sat Apr  4 07:41:09 2020] e820: update [mem 0x-0x0fff]
> usable ==> reserved",
> +"[Sat Apr  4 07:41:09 2020] e820: remove [mem 0x000a-0x000f]
> usable",
> +"[Sat Apr  4 07:41:09 2020] last_pfn = 0x12 max_arch_pfn =
> 0x4",
> +"[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;
>  

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

2020-04-20 Thread Wang Long
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 
---
 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 
0x-0x0009fbff] usable",
+"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 
0x0009fc00-0x0009] reserved",
+"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 
0x000f-0x000f] reserved",
+"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 
0x0010-0xdffe] usable",
+"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 
0xdfff-0xdfff] ACPI data",
+"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 
0xfec0-0xfec00fff] reserved",
+"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 
0xfee0-0xfee00fff] reserved",
+"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 
0xfffc-0x] reserved",
+"[Sat Apr  4 07:41:09 2020] BIOS-e820: [mem 
0x0001-0x00011fff] 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: 
0x max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns",
+"[Sat Apr  4 07:41:09 2020] e820: update [mem 0x-0x0fff] 
usable ==> reserved",
+"[Sat Apr  4 07:41:09 2020] e820: remove [mem 0x000a-0x000f] 
usable",
+"[Sat Apr  4 07:41:09 2020] last_pfn = 0x12 max_arch_pfn = 
0x4",
+"[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, _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;
+   }