[PATCH] makedumpfile add dmesg PRINTK_CALLER id support

HAGIO KAZUHITO(萩尾 一仁) k-hagio-ab at nec.com
Wed Dec 20 23:11:26 PST 2023


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 at 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 at arista.com>
>> Signed-off-by: Edward Chron <echron at arista.com>
>> ---
>>    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 at lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/kexec


More information about the kexec mailing list