On 2023/12/13 19:13, Edward Chron wrote: > Submission to Project: makedumpfile > Component: dmesg > Files: printk.c makedumpfile.c makedumpfile.h > Code level patch applied against: 1.7.4++ - latest code pulled from > https://github.com/makedumpfile/makedumpfile > makedumpfile Issue #13 > https://github.com/makedumpfile/makedumpfile/issues/13 > > 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. Hi Edward, thanks for the patch. How can I try the dmesg using /dev/kmsg with the caller support? I tried the latest one [1] and "dmesg -S" prints them but "dmesg" doesn't. # ./dmesg -S [11894.954745] [T59093] XFS (sdb2): Unmounting Filesystem a41e38db-e035-4995-8276-763f499a33df [11897.572717] [T59101] XFS (sdb2): Mounting V5 Filesystem a41e38db-e035-4995-8276-763f499a33df [11897.647821] [T59101] XFS (sdb2): Ending clean mount # ./dmesg [11894.954745] XFS (sdb2): Unmounting Filesystem a41e38db-e035-4995-8276-763f499a33df [11897.572717] XFS (sdb2): Mounting V5 Filesystem a41e38db-e035-4995-8276-763f499a33df [11897.647821] XFS (sdb2): Ending clean mount I would like to make the log format consistent with "dmesg" output. # ./makedumpfile --dump-dmesg /proc/kcore a The dmesg log is saved to a. makedumpfile Completed. [root@t110h ~]# tail -n 3 a [11894.954745][ T59093] XFS (sdb2): Unmounting Filesystem a41e38db-e035-4995-8276-763f499a33df [11897.572717][ T59101] XFS (sdb2): Mounting V5 Filesystem a41e38db-e035-4995-8276-763f499a33df [11897.647821][ T59101] XFS (sdb2): Ending clean mount [1] https://github.com/util-linux/util-linux (top: be59729281c6) Thanks, Kazu > > 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 > it would be very useful to add makedumpfile support for it. > > 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] > For dmesg command the PRINTK_CALLER field when present is the last > field before the dmesg text so it makes sense to use the same format. > > Signed-off-by: Ivan Delalande <colona@xxxxxxxxxx> > Signed-off-by: Edward Chron <echron@xxxxxxxxxx> > --- > makedumpfile.c | 35 ++++++++++++++++++++++++++++++++++- > makedumpfile.h | 22 ++++++++++++++++++++++ > printk.c | 29 ++++++++++++++++++++++++++++- > 3 files changed, 84 insertions(+), 2 deletions(-) > > diff --git a/makedumpfile.c b/makedumpfile.c > index a6ec9d4..5172ee2 100644 > --- a/makedumpfile.c > +++ b/makedumpfile.c > @@ -2118,6 +2118,7 @@ module_end: > SIZE_INIT(printk_info, "printk_info"); > OFFSET_INIT(printk_info.ts_nsec, "printk_info", "ts_nsec"); > OFFSET_INIT(printk_info.text_len, "printk_info", "text_len"); > + OFFSET_INIT(printk_info.caller_id, "printk_info", "caller_id"); > > OFFSET_INIT(atomic_long_t.counter, "atomic_long_t", "counter"); > > @@ -2133,6 +2134,7 @@ module_end: > OFFSET_INIT(printk_log.ts_nsec, "printk_log", "ts_nsec"); > OFFSET_INIT(printk_log.len, "printk_log", "len"); > OFFSET_INIT(printk_log.text_len, "printk_log", "text_len"); > + OFFSET_INIT(printk_info.caller_id, "printk_log", "caller_id"); > } else { > info->flag_use_printk_ringbuffer = FALSE; > info->flag_use_printk_log = FALSE; > @@ -2462,6 +2464,7 @@ write_vmcoreinfo_data(void) > > WRITE_MEMBER_OFFSET("printk_info.ts_nsec", printk_info.ts_nsec); > WRITE_MEMBER_OFFSET("printk_info.text_len", printk_info.text_len); > + WRITE_MEMBER_OFFSET("printk_info.caller_id", printk_info.caller_id); > > WRITE_MEMBER_OFFSET("atomic_long_t.counter", atomic_long_t.counter); > > @@ -2470,6 +2473,7 @@ write_vmcoreinfo_data(void) > WRITE_MEMBER_OFFSET("printk_log.ts_nsec", printk_log.ts_nsec); > WRITE_MEMBER_OFFSET("printk_log.len", printk_log.len); > WRITE_MEMBER_OFFSET("printk_log.text_len", printk_log.text_len); > + WRITE_MEMBER_OFFSET("printk_log.caller_id", printk_log.caller_id); > } else { > /* Compatibility with pre-3.11-rc4 */ > WRITE_MEMBER_OFFSET("log.ts_nsec", printk_log.ts_nsec); > @@ -2921,6 +2925,7 @@ read_vmcoreinfo(void) > READ_STRUCTURE_SIZE("printk_info", printk_info); > READ_MEMBER_OFFSET("printk_info.ts_nsec", printk_info.ts_nsec); > READ_MEMBER_OFFSET("printk_info.text_len", printk_info.text_len); > + READ_MEMBER_OFFSET("printk_info.caller_id", printk_info.caller_id); > > READ_MEMBER_OFFSET("atomic_long_t.counter", atomic_long_t.counter); > > @@ -2932,6 +2937,7 @@ read_vmcoreinfo(void) > READ_MEMBER_OFFSET("printk_log.ts_nsec", printk_log.ts_nsec); > READ_MEMBER_OFFSET("printk_log.len", printk_log.len); > READ_MEMBER_OFFSET("printk_log.text_len", printk_log.text_len); > + READ_MEMBER_OFFSET("printk_log.caller_id", printk_log.caller_id); > } else { > info->flag_use_printk_ringbuffer = FALSE; > info->flag_use_printk_log = FALSE; > @@ -5603,7 +5609,34 @@ dump_log_entry(char *logptr, int fp, const char *file_name) > msg = logptr + SIZE(printk_log); > > bufp = buf; > - bufp += sprintf(buf, "[%5lld.%06ld] ", nanos, rem/1000); > + bufp += sprintf(buf, "[%5lld.%06ld]", nanos, rem/1000); > + > + if (OFFSET(printk_log.caller_id) > 0) { > + ssize_t numspaces; > + unsigned int pkc; > + char idtype; > + int digits; > + > + /* Get id type, isolate id value in pkc for print */ > + pkc = UINT(logptr + OFFSET(printk_log.caller_id)); > + idtype = (pkc & 0x80000000) ? 'C' : 'T'; > + pkc &= ~0x80000000; > + /* Determine size of padding space if needed */ > + digits = snprintf(NULL, 0, "%u", pkc); > + numspaces = CALLER_ID_SIZE - digits; > + if (numspaces > 0) { > + char spc[16]; > + > + memset(spc, 0, sizeof(spc)); > + memset(spc, ' ', numspaces); > + bufp += sprintf(bufp, "[%s%c%u] ", spc, idtype, pkc); > + } else { > + bufp += sprintf(bufp, "[%c%u] ", idtype, pkc); > + } > + } else { > + bufp = stpcpy(bufp, " "); > + } > + > indent_len = strlen(buf); > > /* How much buffer space is needed in the worst case */ > diff --git a/makedumpfile.h b/makedumpfile.h > index f1619c5..0a7acb5 100644 > --- a/makedumpfile.h > +++ b/makedumpfile.h > @@ -2116,10 +2116,16 @@ struct offset_table { > long p_memsz; > } elf64_phdr; > > + /* The caller_id was added by the Linux-5.1 Kernel to hold > + * the Thread id or CPU id of the caller adding a printk > + * dmesg to the ring buffer. As such older versions of the > + * kernel can ignore this field as it won't be filled in. > + */ > struct printk_log_s { > long ts_nsec; > long len; > long text_len; > + long caller_id; > } printk_log; > > /* > @@ -2671,6 +2677,22 @@ struct elf_prstatus { > > #endif > > +/* > + * Minimum size of the id portion of the PRINTK_CALLER dmesg field if it is > + * configured in the Linux Kernel. The size is used to pad with spaces the > + * PRINTK_CALLER field in each dmesg. For 32 bit kernels the maximum number > + * of PIDs supported was 2^15 so pid values 0 to 32,767 while 64 bit systems > + * support the value specified in /proc/sys/kernel/pid_max which is capped at > + * PID_MAX_LIMIT. We can use 7 digits as that accomodates both 32 bit and > + * current 64 bit systems as PID_MAX_LIMIT is currently 2^22 so that will > + * fit in 7 digits and the id will add an additional byte for the id type of > + * either thread 'T' or CPU 'C', where the Thread ids will have much larger > + * values, so the CPU ids will easily be accomodated. When systems exceed > + * 7 digits that won't break anything, but print statements needing more > + * then 7 digits will not precisely align. > + */ > +#define CALLER_ID_SIZE 7 > + > /* > * Below are options which getopt_long can recognize. From OPT_START options are > * non-printable, just used for implementation. > diff --git a/printk.c b/printk.c > index 61e0b26..5ebda45 100644 > --- a/printk.c > +++ b/printk.c > @@ -113,7 +113,34 @@ dump_record(struct prb_map *m, unsigned long id) > rem = (ulonglong)ts_nsec % (ulonglong)1000000000; > > bufp = buf; > - bufp += sprintf(buf, "[%5lld.%06ld] ", nanos, rem/1000); > + bufp += sprintf(buf, "[%5lld.%06ld]", nanos, rem/1000); > + > + if (OFFSET(printk_info.caller_id) > 0) { > + ssize_t numspaces; > + unsigned int pkc; > + char idtype; > + int digits; > + > + /* Get id type, isolate id value in pkc for print */ > + pkc = UINT(inf + OFFSET(printk_info.caller_id)); > + idtype = (pkc & 0x80000000) ? 'C' : 'T'; > + pkc &= ~0x80000000; > + /* Determine size of padding space if needed */ > + digits = snprintf(NULL, 0, "%u", pkc); > + numspaces = CALLER_ID_SIZE - digits; > + if (numspaces > 0) { > + char spc[16]; > + > + memset(spc, 0, sizeof(spc)); > + memset(spc, ' ', numspaces); > + bufp += sprintf(bufp, "[%s%c%u] ", spc, idtype, pkc); > + } else { > + bufp += sprintf(bufp, "[%c%u] ", idtype, pkc); > + } > + } else { > + bufp = stpcpy(bufp, " "); > + } > + > indent_len = strlen(buf); > > /* How much buffer space is needed in the worst case */ _______________________________________________ kexec mailing list kexec@xxxxxxxxxxxxxxxxxxx http://lists.infradead.org/mailman/listinfo/kexec
