Hi Edward, thank you for the patch. On 2023/12/26 2:38, Edward Chron wrote: > Subject: [PATCH] crash add log dmesg PRINTK_CALLER id support please update the prefix like "[PATCH v2]" when you revise a patch so that we can determine which is the latest. > From: Edward Chron <echron@xxxxxxxxx> > > Submission to Project: crash > Component: dmesg > Files: printk.c makedumpfile.c makedumpfile.h > Code level patch applied against: 8.0.4++ - latest code pulled from > https://github.com/crash-utility/crash.git > crash Issue #164 > 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 > 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 > > 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 (-P) is selected: > > crash> log -m -P I agree about adding a new option, but how about "-c" for "caller"? > ... > [ 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: -P > > The PRINTK_CALLER id field is printed only if the -P option is selected. > The description of the log -P option that is seen in the help is: > > crash> log help > > log > dump system message buffer > [-TtdmasP] > > ... > ... > > -P Display the PRINTK_CALLER id field that identifies the thread id or > the CPU id of the task that issued the printk to add the message to > the kernel ring buffer. Displaying this field is only possible for > Linux kernels that are Linux 5.1 or newer since kernels prior to > Linux 5.1 did not provide a PRINTK_CALLER field. So, this option is > ignored for kernels older than Linux 5.1. The CONFIG_PRINTK_CALLER > kernel configuration option should be selected to make the caller_id > field available and for vmcore files your version of makedumpfile > must support dumping the caller_id field for it to be available here. > > Also seen in the help file : > > On systems that are properly configured to make the log caller_id field > available to the crash utility, you can select to print log records and > include the caller_id field with each log record. The log PRINTK_CALLER > id option (-P) will print either the Thread id or the CPU id depending on > the context of the process at the time the printk request was made. The > output of the thread id (begins with T) or the CPU id (begins with C) is > placed inside square brackets and is padded with leading space to keep > alignment. The caller_id field follows the timestamp field if that field > is selected: > > crash> log -P > ... > [ 0.014179] [ T1] Secure boot disabled > [ 0.014179] [ T29] RAMDISK: [mem 0x3cf4f000-0x437bbfff] > [ 0.198789] [ C0] DMAR: DRHD: handling fault status reg 3 > ... > crash> log -P -m > ... > [ 0.014179] [ T1] <6>Secure boot disabled > [ 0.014179] [ T29] <6>RAMDISK: [mem 0x3cf4f000-0x437bbfff] > [ 0.198789] [ C0] <6>DMAR: DRHD: handling fault status reg 3 > ... > crash> log -t -P -m > ... > [ T1] <6>Secure boot disabled > [ T29] <6>RAMDISK: [mem 0x3cf4f000-0x437bbfff] > [ C0] <6>DMAR: DRHD: handling fault status reg 3 > ... > crash> log -T -P -m > ... > [Tue Dec 12 23:25:03 PST 2023] [ T1] <6>Secure boot disabled > [Tue Dec 12 23:25:03 PST 2023] [ T29] <6>RAMDISK: [mem 0x3cf4f000-0x437bbfff] > [Tue Dec 12 23:25:03 PST 2023] [ C0] <6>DMAR: DRHD: handling fault status reg 3 > ... > > Signed-off-by: Ivan Delalande <colona@xxxxxxxxxx> > Signed-off-by: Edward Chron <echron@xxxxxxxxxx> > --- > defs.h | 15 +++++++++------ > help.c | 48 ++++++++++++++++++++++++++++++++++++++++++++++-- > kernel.c | 47 +++++++++++++++++++++++++++++++++++++++++++++-- > printk.c | 39 +++++++++++++++++++++++++++++++++++++++ > symbols.c | 2 ++ > 6 files changed, 150 insertions(+), 19 deletions(-) > > diff --git a/defs.h b/defs.h > index 20237b7..a61e832 100644 > --- a/defs.h > +++ b/defs.h > @@ -784,6 +784,7 @@ struct kernel_table { /* kernel data */ > long log_len_OFFSET; > long log_text_len_OFFSET; > long log_dict_len_OFFSET; > + ulong log_caller_id_OFFSET; This is for "crash --log" option, but actually it's kind of deprecated (it's does not support the lockless ringbuffer, log_buf_len= parameter and etc.). personally I would like to drop this support. Lianbo, what do you think? > ulong phys_base_SYMBOL; > ulong _stext_SYMBOL; > } vmcoreinfo; > @@ -1943,6 +1944,7 @@ struct offset_table { /* stash of commonly-used offsets */ > long log_dict_len; > long log_level; > long log_flags_level; > + long log_caller_id; Please move this to the end of the offset_table. For more information: https://github.com/crash-utility/crash/wiki If you add struct members to tables in global_data.c i.e. offset_table, size_table and etc., they have to be appended to the end of the tables. > long timekeeper_xtime_sec; > long neigh_table_hash_mask; > long sched_rt_entity_my_q; > @@ -6037,12 +6039,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 cc7ab20..1de1292 100644 > --- a/help.c > +++ b/help.c > @@ -4023,7 +4023,7 @@ NULL > char *help_log[] = { > "log", > "dump system message buffer", > -"[-Ttdmas]", > +"[-TtdmasP]", > " 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,16 @@ 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.", > -" ", > +" -P Display the PRINTK_CALLER id field that identifies the thread id or", > +" the CPU id of the task that issued the printk to add the message to", > +" the kernel ring buffer. Displaying this field is only possible for", > +" Linux kernels that are Linux 5.1 or newer since kernels prior to", > +" Linux 5.1 did not provide a PRINTK_CALLER field. So, this option is", > +" ignored for kernels older than Linux 5.1. The CONFIG_PRINTK_CALLER", > +" kernel configuration option should be selected to make the caller_id", > +" field available and for vmcore files your version of makedumpfile", > +" must support dumping the caller_id field for it to be available here.", This feels a bit too long for the help page, and the version of makedumpfile does not matter to this crash function. How about this? "Display the caller id that identifies the thread id of the task or the processor id that called printk(), if available. Generally it is available on Linux 5.1 to 5.9 kernels configured with CONFIG_PRINTK_CALLER or Linux 5.10 and later ones." > +" ", > "\nEXAMPLES", > " Dump the kernel message buffer:\n", > " %s> log", > @@ -4214,6 +4223,41 @@ char *help_log[] = { > " CPU: 0 ADDR: ffff8ca4fbc1ad00 LEN: 0 MESSAGE_LOST: 0", > " (empty)", > " ...", > +" ", > +" On systems that are properly configured to make the log caller_id field", > +" available to the crash utility, you can select to print log records and", > +" include the caller_id field with each log record. The log PRINTK_CALLER", > +" id option (-P) will print either the Thread id or the CPU id depending on", > +" the context of the process at the time the printk request was made. The", > +" output of the thread id (begins with T) or the CPU id (begins with C) is", > +" placed inside square brackets and is padded with leading space to keep", > +" alignment. The caller_id field follows the timestamp field if that field", > +" is selected:\n", How about this? "Display the caller id that identifies the thread id of the task (begins with "T") or the processor id (begins with "C"; if not in task context) that called printk(), if available:" > +" %s> log -P", > +" ...", > +" [ 0.014179] [ T1] Secure boot disabled", > +" [ 0.014179] [ T29] RAMDISK: [mem 0x3cf4f000-0x437bbfff]", > +" [ 0.198789] [ C0] DMAR: DRHD: handling fault status reg 3", > +" ...", This is enough for the help text, please remove the following. > +" %s> log -P -m", > +" ...", > +" [ 0.014179] [ T1] <6>Secure boot disabled", > +" [ 0.014179] [ T29] <6>RAMDISK: [mem 0x3cf4f000-0x437bbfff]", > +" [ 0.198789] [ C0] <6>DMAR: DRHD: handling fault status reg 3", > +" ...", > +" %s> log -t -P -m", > +" ...", > +" [ T1] <6>Secure boot disabled", > +" [ T29] <6>RAMDISK: [mem 0x3cf4f000-0x437bbfff]", > +" [ C0] <6>DMAR: DRHD: handling fault status reg 3", > +" ...", > +" %s> log -T -P -m", > +" ...", > +" [Tue Dec 12 23:25:03 PST 2023] [ T1] <6>Secure boot disabled", > +" [Tue Dec 12 23:25:03 PST 2023] [ T29] <6>RAMDISK: [mem 0x3cf4f000-0x437bbfff]", > +" [Tue Dec 12 23:25:03 PST 2023] [ C0] <6>DMAR: DRHD: handling fault status reg 3", > +" ...", > + > NULL > }; > > diff --git a/kernel.c b/kernel.c > index 6dcf414..0475b07 100644 > --- a/kernel.c > +++ b/kernel.c > @@ -29,6 +29,9 @@ > #endif > #include "bfd.h" > > +#define PID_CHARS_MAX 16 /* Max Number of PID characters */ > +#define PID_CHARS_DEFAULT 8 /* Default number of PID characters */ > + > static void do_module_cmd(ulong, char *, ulong, char *, char *); > static void show_module_taint(void); > static char *find_module_objfile(char *, char *, char *); > @@ -5089,7 +5092,7 @@ cmd_log(void) > > msg_flags = 0; > > - while ((c = getopt(argcnt, args, "Ttdmas")) != EOF) { > + while ((c = getopt(argcnt, args, "TtdmasP")) != EOF) { > switch(c) > { > case 'T': > @@ -5110,6 +5113,9 @@ cmd_log(void) > case 's': > msg_flags |= SHOW_LOG_SAFE; > break; > + case 'P': > + msg_flags |= SHOW_LOG_CALLER; > + break; > default: > argerrs++; > break; > @@ -5369,6 +5375,29 @@ 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 && > + kt->kernel_version[0] >= 5 && > + kt->kernel_version[1] >= 1 && > + VALID_MEMBER(log_caller_id)) { As there can be kernels that have newer patches backported, please do not use a kernel version as far as possible: if ((msg_flags & SHOW_LOG_CALLER) && VALID_MEMBER(log_caller_id)) { > + const unsigned int cpuid = 0x80000000; > + char cidbuf[PID_CHARS_MAX]; > + unsigned int pkc; > + char idtype; > + > + /* Get id type, isolate id value in pkc for print */ > + pkc = UINT(logptr + OFFSET(log_caller_id)); > + idtype = (pkc & cpuid) ? 'C' : 'T'; > + pkc &= ~cpuid; > + sprintf(cidbuf, "%c%d", idtype, pkc); is there need to separate the lines? and I prefer "caller_id" or "cid", so sprintf(cidbuf, "%c%d", (caller_id & cpuid) ? 'C' : 'T', caller_id & ~cpuid); > + sprintf(buf, "[%*s] ", PID_CHARS_DEFAULT, cidbuf); > + > + ilen += strlen(buf); > + fprintf(fp, "%s", buf); > + } > + > level = LOG_LEVEL(level); > > if (msg_flags & SHOW_LOG_LEVEL) { > @@ -5424,8 +5453,13 @@ dump_variable_length_record_log(int msg_flags) > * from log to printk_log. See 62e32ac3505a0cab. > */ > log_struct_name = "printk_log"; > - } else > + if (MEMBER_EXISTS("printk_log", "caller_id")) > + MEMBER_OFFSET_INIT(log_caller_id, "printk_log", > + "caller_id"); There is no need to call MEMBER_EXISTS() in advance. > + } else { > log_struct_name = "log"; > + INVALID_MEMBER(log_caller_id); Please remove this, a leftover of something? the warning occurs: In file included from kernel.c:18: kernel.c: In function 'dump_variable_length_record_log': defs.h:2478:44: warning: statement with no effect [-Wunused-value] #define INVALID_MEMBER(X) (offset_table.X == INVALID_OFFSET) ~~~~~~~~~~~~~~~~^~~~~~~~~~~~~~~~~~ kernel.c:5461:4: note: in expansion of macro 'INVALID_MEMBER' INVALID_MEMBER(log_caller_id); ^~~~~~~~~~~~~~ > + } > > STRUCT_SIZE_INIT(log, log_struct_name); > MEMBER_OFFSET_INIT(log_ts_nsec, log_struct_name, "ts_nsec"); > @@ -11132,6 +11166,15 @@ get_log_from_vmcoreinfo(char *file) > vmc->log_dict_len_OFFSET); > free(string); > } > + /* The caller_id field exists only in printk_log if kernel >= 5.1 > + * and if CONFIG_PRINTK_CALLER was set in the kernel config file*/ > + if ((string = pc->read_vmcoreinfo("OFFSET(printk_log.caller_id"))) { > + vmc->log_dict_len_OFFSET = dtol(string, RETURN_ON_ERROR, NULL); > + if (CRASHDEBUG(1)) > + fprintf(fp, "OFFSET(printk_log.caller_id): %ld\n", > + vmc->log_caller_id_OFFSET); > + free(string); > + } I would like to drop this. > if ((string = pc->read_vmcoreinfo("SIZE(log)"))) { > vmc->log_SIZE = dtol(string, RETURN_ON_ERROR, NULL); > if (CRASHDEBUG(1)) > diff --git a/printk.c b/printk.c > index 8658016..d1b3f40 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; > @@ -37,6 +38,9 @@ enum desc_state { > #define DESC_ID_MASK (~DESC_FLAGS_MASK) > #define DESC_ID(sv) ((sv) & DESC_ID_MASK) > > +#define PID_CHARS_MAX 16 /* Max Number of PID characters */ > +#define PID_CHARS_DEFAULT 8 /* Default number of PID characters */ > + > /* > * get_desc_state() taken from kernel source: > * > @@ -162,6 +166,27 @@ 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 cidbuf[PID_CHARS_MAX]; > + unsigned int pkc; > + char idtype; > + > + /* Get id type, isolate id value in pkc for print */ > + pkc = UINT(info + OFFSET(printk_info_caller_id)); > + idtype = (pkc & cpuid) ? 'C' : 'T'; > + pkc &= ~cpuid; > + sprintf(cidbuf, "%c%d", idtype, pkc); unsigned int caller_id already exists in this function, so sprintf(cidbuf, "%c%d", (caller_id & cpuid) ? 'C' : 'T', caller_id & ~cpuid); > + sprintf(buf, "[%*s] ", PID_CHARS_DEFAULT, cidbuf); m.pid_max_chars? > + > + 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 +287,20 @@ dump_lockless_record_log(int msg_flags) > goto out_text_data; > } > > + /* Get pid_max and fill it in if we need it */ > + if (msg_flags & SHOW_LOG_CALLER) { > + char pid_chars[PID_CHARS_MAX]; > + size_t pc_size = sizeof(pid_chars); > + size_t pid_chars_length; > + unsigned int pid_max; > + > + get_symbol_data("pid_max", sizeof(pid_max), &pid_max); > + pid_chars_length = snprintf(pid_chars, pc_size, "%u", &pid_max); > + m.pid_max_chars = pid_chars_length + 1; This also can be shorten? m.pid_max_chars = snprintf(pid_chars, sizeof(pid_chars), "%u", &pid_max) + 1; > + } 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 5d91991..7969409 100644 > --- a/symbols.c > +++ b/symbols.c > @@ -11521,6 +11521,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)); Thanks, Kazu -- Crash-utility mailing list -- devel@xxxxxxxxxxxxxxxxxxxxxxxxxxx To unsubscribe send an email to devel-leave@xxxxxxxxxxxxxxxxxxxxxxxxxxx https://${domain_name}/admin/lists/devel.lists.crash-utility.osci.io/ Contribution Guidelines: https://github.com/crash-utility/crash/wiki
