On 2023/12/14 17:02, HAGIO KAZUHITO(萩尾 一仁) wrote: > 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? ok, I found this: https://github.com/util-linux/util-linux/pull/2647 and thank you for the test output files: https://github.com/makedumpfile/makedumpfile/issues/13 According to the output files, you may have fixed those but some comments below. > 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"); typo: s/printk_info/printk_log/ >> } 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); I think there is no need to remove the last space to be consistent with the dmesg format. >> + >> + if (OFFSET(printk_log.caller_id) > 0) { if (OFFSET(printk_log.caller_id) != NOT_FOUND_STRUCTURE) is better. >> + 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, " "); Also this is not needed? >> + } >> + >> 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); Same as above. >> + >> + if (OFFSET(printk_info.caller_id) > 0) { Same as above. >> + 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, " "); Same as above. Thanks, Kazu >> + } >> + >> 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 _______________________________________________ kexec mailing list kexec@xxxxxxxxxxxxxxxxxxx http://lists.infradead.org/mailman/listinfo/kexec
