[Crash-utility] Re: [PATCHv2] crash add log dmesg PRINTK_CALLER id support

On 2024/01/22 3:31, Edward Chron wrote: Thanks for the update, looks good to me. Acked-by: Kazuhito Hagio <k-hagio-ab(a)nec.com&gt; Thanks, Kazu > Tested with Kernel version and makedumpfile version: > Linux Kernel Testing: Linux catalina 6.6.6 #4 SMP PREEMPT_DYNAMIC > Tue Dec 12 23:11:30 PST 2023 x86_64 GNU/Linux > Linux 5.4.264 #9 SMP > Thu Dec 21 07:00:08 PST 2023 > makedumpfile Testing: makedumpfile: version 1.7.4++ > (released on 6 Nov 2023) > Issue 13 for makedumpfile: adds support for > demsg PRINTK_CALLER id field patch applied > dmesg Testing: util-linux 2.39.3++ > Issue 2609 for sys-utils dmesg: adds support for > dmesg PRINTK_CALLER id field to standard > dmesg kmsg interface patch applied > > Add support so that dmesg entries include the optional Linux Kernel > debug CONFIG option PRINTK_CALLER which adds an optional dmesg field > that contains the Thread Id or CPU Id that is issuing the printk to > add the message to the kernel ring buffer. If enabled, this CONFIG > option makes debugging simpler as dmesg entries for a specific > thread or CPU can be recognized. > > The dmesg command supports printing the PRINTK_CALLER field. The > old syslog format (dmesg -S) and recently support was added for dmesg > using /dev/kmsg interface with util-linux Issue #2609 as we upstreamed > a commit that is under review. > > We've upstreamed a patch for makedumpfile that adds support for > the PRINTK_CALLER id field so it will be available with the > commands: > > makedumpfile --dump-dmesg /proc/vmcore dmesgfile > makedumpfile --dump-dmesg -x vmlinux /proc/vmcore dmesgfile > > The additional field provided by PRINTK_CALLER is only present > if it was configured for the Linux kernel on the running system. The > PRINTK_CALLER is a debug option and not configured by default so the > dmesg output will only change for those kernels where the option was > configured when the kernel was built. For users who went to the > trouble to configure PRINTK_CALLER and have the extra field available > for debugging, having dmesg print the field is very helpful and so > will be makedumpfile and so it would be very useful to have crash > support for dump analysis. > > Size of the PRINTK_CALLER field is determined by the maximum number > tasks that can be run on the system which is limited by the value of > /proc/sys/kernel/pid_max as pid values are from 0 to value - 1. > This value determines the number of id digits needed by the caller id. > The PRINTK_CALLER field is printed as T<id> for a Task Id or C<id> > for a CPU Id for a printk in CPU context. The values are left space > padded and enclosed in parentheses such as: > [ T123] or [ C16] > > Displaying the PRINTK_CALLER field in the log/dmesg record output: > ----------------------------------------------------------------- > > Given the layout of log/dmesg records printed by crash, for example: > > crash> log -m > ... > [ 0.000000] <7>e820: remove [mem 0xff000000-0xffffffff] reserved > [ 0.000000] <6>SMBIOS 3.4.0 present. > ... > [ 0.014179] <6>Secure boot disabled > [ 0.014179] <6>RAMDISK: [mem 0x3cf4f000-0x437bbfff] > ... > [ 663.328848] <6>sysrq: Trigger a crash > [ 663.328859] <0>Kernel panic - not syncing: sysrq triggered crash > > Our patch adds the PRINTK_CALLER field after the timestamp if the > printk_caller log / dmesg option (-c) is selected: > > crash> log -m -c > ... > [ 0.014179] [ T1] <6>Secure boot disabled > [ 0.014179] [ T29] <6>RAMDISK: [mem 0x3cf4f000-0x437bbfff] > ... > > This is consistent placement with dmesg and makedumpfile. > > To produce dmesg output with the PRINTK_CALLER id included, we add > a new log / dmesg command option: -c > > The PRINTK_CALLER id field is printed only if the -c option is selected. > The description of the log -c option that is seen in the help is: > > crash> log help > > log > dump system message buffer > [-Ttdmasc] > > ... > ... > > -c Display the caller id field that identifies either the thread id or > the CPU id (if in CPU context) that called printk(), if available. > Generally available on Linux 5.1 to 5.9 kernels configured with > CONFIG_PRINTK_CALLER or Linux 5.10 and later kernels. > > Also seen in the help file : > > Display the caller id that identifies the thread id of the task (begins > with 'T') or the processor id (begins with 'C' for in CPU context) that > called printk(), if available. > > crash> log -c > ... > [ 0.014179] [ T1] Secure boot disabled > [ 0.014179] [ T29] RAMDISK: [mem 0x3cf4f000-0x437bbfff] > [ 0.198789] [ C0] DMAR: DRHD: handling fault status reg 3 > ... > > Signed-off-by: Ivan Delalande <colona(a)arista.com&gt; > Signed-off-by: Edward Chron <echron(a)arista.com&gt; > --- > defs.h | 18 ++++++++++++------ > help.c | 19 +++++++++++++++++-- > kernel.c | 25 ++++++++++++++++++++++++- > printk.c | 34 ++++++++++++++++++++++++++++++++++ > symbols.c | 2 ++ > 6 files changed, 98 insertions(+), 18 deletions(-) > > diff --git a/defs.h b/defs.h > index 2a29c07..488214f 100644 > --- a/defs.h > +++ b/defs.h > @@ -2228,8 +2228,13 @@ struct offset_table { /* stash of commonly-used offsets */ > long irq_data_irq; > long zspage_huge; > long zram_comp_algs; > + long log_caller_id; > }; > > +/* caller_id default and max character sizes based on pid field size */ > +#define PID_CHARS_MAX 16 /* Max Number of PID characters */ > +#define PID_CHARS_DEFAULT 8 /* Default number of PID characters */ > + > struct size_table { /* stash of commonly-used sizes */ > long page; > long free_area_struct; > @@ -6044,12 +6049,13 @@ void dump_log(int); > void parse_kernel_version(char *); > > #define LOG_LEVEL(v) ((v) & 0x07) > -#define SHOW_LOG_LEVEL (0x1) > -#define SHOW_LOG_DICT (0x2) > -#define SHOW_LOG_TEXT (0x4) > -#define SHOW_LOG_AUDIT (0x8) > -#define SHOW_LOG_CTIME (0x10) > -#define SHOW_LOG_SAFE (0x20) > +#define SHOW_LOG_LEVEL (0x1) > +#define SHOW_LOG_DICT (0x2) > +#define SHOW_LOG_TEXT (0x4) > +#define SHOW_LOG_AUDIT (0x8) > +#define SHOW_LOG_CTIME (0x10) > +#define SHOW_LOG_SAFE (0x20) > +#define SHOW_LOG_CALLER (0x40) > 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 a4319dd..ae02a57 100644 > --- a/help.c > +++ b/help.c > @@ -4023,7 +4023,7 @@ NULL > char *help_log[] = { > "log", > "dump system message buffer", > -"[-Ttdmas]", > +"[-Ttdmasc]", > " 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", > @@ -4046,7 +4046,11 @@ char *help_log[] = { > " been copied out to the user-space audit daemon.", > " -s Dump the printk logs remaining in kernel safe per-CPU buffers that", > " have not been flushed out to log_buf.", > -" ", > +" -c Display the caller id field that identifies either the thread id or", > +" the CPU id (if in CPU context) that called printk(), if available.", > +" Generally available on Linux 5.1 to 5.9 kernels configured with", > +" CONFIG_PRINTK_CALLER or Linux 5.10 and later kernels.", > +" ", > "\nEXAMPLES", > " Dump the kernel message buffer:\n", > " %s> log", > @@ -4214,6 +4218,17 @@ char *help_log[] = { > " CPU: 0 ADDR: ffff8ca4fbc1ad00 LEN: 0 MESSAGE_LOST: 0", > " (empty)", > " ...", > +" ", > +" Display the caller id that identifies the thread id of the task (begins", > +" with 'T') or the processor id (begins with 'C' for in CPU context) that", > +" called printk(), if available.\n", > +" %s> log -c", > +" ...", > +" [ 0.014179] [ T1] Secure boot disabled", > +" [ 0.014179] [ T29] RAMDISK: [mem 0x3cf4f000-0x437bbfff]", > +" [ 0.198789] [ C0] DMAR: DRHD: handling fault status reg 3", > +" ...", > + > NULL > }; > > diff --git a/kernel.c b/kernel.c > index 6dcf414..bcd10f9 100644 > --- a/kernel.c > +++ b/kernel.c > @@ -5089,7 +5089,7 @@ cmd_log(void) > > msg_flags = 0; > > - while ((c = getopt(argcnt, args, "Ttdmas")) != EOF) { > + while ((c = getopt(argcnt, args, "Ttdmasc")) != EOF) { > switch(c) > { > case 'T': > @@ -5110,6 +5110,9 @@ cmd_log(void) > case 's': > msg_flags |= SHOW_LOG_SAFE; > break; > + case 'c': > + msg_flags |= SHOW_LOG_CALLER; > + break; > default: > argerrs++; > break; > @@ -5369,6 +5372,24 @@ dump_log_entry(char *logptr, int msg_flags) > fprintf(fp, "%s", buf); > } > > + /* The PRINTK_CALLER id field was introduced with Linux-5.1 so if > + * requested, Kernel version >= 5.1 and field exists print caller_id. > + */ > + if (msg_flags & SHOW_LOG_CALLER && > + VALID_MEMBER(log_caller_id)) { > + const unsigned int cpuid = 0x80000000; > + char cbuf[PID_CHARS_MAX]; > + unsigned int cid; > + > + /* Get id type, isolate just id value in cid for print */ > + cid = UINT(logptr + OFFSET(log_caller_id)); > + sprintf(cbuf, "%c%d", (cid & cpuid) ? 'C' : 'T', cid & ~cpuid); > + sprintf(buf, "[%*s] ", PID_CHARS_DEFAULT, cbuf); > + > + ilen += strlen(buf); > + fprintf(fp, "%s", buf); > + } > + > level = LOG_LEVEL(level); > > if (msg_flags & SHOW_LOG_LEVEL) { > @@ -5424,6 +5445,8 @@ dump_variable_length_record_log(int msg_flags) > * from log to printk_log. See 62e32ac3505a0cab. > */ > log_struct_name = "printk_log"; > + MEMBER_OFFSET_INIT(log_caller_id, "printk_log", > + "caller_id"); > } else > log_struct_name = "log"; > > diff --git a/printk.c b/printk.c > index 8658016..ae3fa4f 100644 > --- a/printk.c > +++ b/printk.c > @@ -9,6 +9,7 @@ struct prb_map { > unsigned long desc_ring_count; > char *descs; > char *infos; > + unsigned int pid_max_chars; > > char *text_data_ring; > unsigned long text_data_ring_size; > @@ -162,6 +163,24 @@ dump_record(struct prb_map *m, unsigned long id, int msg_flags) > fprintf(fp, "%s", buf); > } > > + /* > + * The lockless ringbuffer introduced in Linux-5.10 always has > + * the caller_id field available, so if requested, print it. > + */ > + if (msg_flags & SHOW_LOG_CALLER) { > + const unsigned int cpuid = 0x80000000; > + char cbuf[PID_CHARS_MAX]; > + unsigned int cid; > + > + /* Get id type, isolate id value in cid for print */ > + cid = UINT(info + OFFSET(printk_info_caller_id)); > + sprintf(cbuf, "%c%d", (cid & cpuid) ? 'C' : 'T', cid & ~cpuid); > + sprintf(buf, "[%*s] ", m->pid_max_chars, cbuf); > + > + ilen += strlen(buf); > + fprintf(fp, "%s", buf); > + } > + > if (msg_flags & SHOW_LOG_LEVEL) { > level = UCHAR(info + OFFSET(printk_info_level)) >> 5; > sprintf(buf, "<%x>", level); > @@ -262,6 +281,21 @@ dump_lockless_record_log(int msg_flags) > goto out_text_data; > } > > + /* If caller_id was requested, get the pid_max value for print */ > + if (msg_flags & SHOW_LOG_CALLER) { > + unsigned int pidmax; > + > + get_symbol_data("pid_max", sizeof(pidmax), &pidmax); > + if (pidmax <= 99999) > + m.pid_max_chars = 6; > + else if (pidmax <= 999999) > + m.pid_max_chars = 7; > + else > + m.pid_max_chars = PID_CHARS_DEFAULT; > + } else { > + m.pid_max_chars = PID_CHARS_DEFAULT; > + } > + > /* ready to go */ > > tail_id = ULONG(m.desc_ring + OFFSET(prb_desc_ring_tail_id) + > diff --git a/symbols.c b/symbols.c > index 88a3fd1..554d109 100644 > --- a/symbols.c > +++ b/symbols.c > @@ -11524,6 +11524,8 @@ dump_offset_table(char *spec, ulong makestruct) > OFFSET(log_level)); > fprintf(fp, " log_flags_level: %ld\n", > OFFSET(log_flags_level)); > + fprintf(fp, " log_caller_id: %ld\n", > + OFFSET(log_caller_id)); > > fprintf(fp, " printk_info_seq: %ld\n", OFFSET(printk_info_seq)); > fprintf(fp, " printk_info_ts_nseq: %ld\n", OFFSET(printk_info_ts_nsec));