[PATCH] makedumpfile add dmesg PRINTK_CALLER id support

HAGIO KAZUHITO(萩尾 一仁) k-hagio-ab at nec.com
Sun Dec 24 17:31:12 PST 2023


On 2023/12/22 8:46, 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
> Project Owner: Kazuhito Hagio <k-hagio-ab at nec.com>
> Revision: #1 on 2023/12/15 per Kazu ensure spacing of dmesg output
>                             matches dmesg -S and new dmesg caller_id
>                             output format (space after timestamp)
> Revision: #2 on 2023/12/21 per Kazu use NOT_FOUND_STRUCTURE for caller_id
> Revision: #3 on 2023/12/21 streamline code for printing caller_id
> 
> 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.
> 
> 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>

Thank you for the update.

It looks like a few fixes are needed, but I can fix them when merging,
so there is no need to update.  And I will apply this when the upstream
dmesg gets the PRINTK_CALLER support.


BTW, I tried the dmesg of this version [1], its caller width is 7 and
different from makedumpfile's 8 on an environment, is this intended?

# cat /proc/sys/kernel/pid_max
4194304
# ./dmesg

[ 7971.766029] [T109202] XFS (sda2): Ending clean mount
[ 8700.508829] [T1053218] XFS (sda2): Unmounting Filesystem ...

# cat dmesg-makedumpfile

[ 7971.766029] [ T109202] XFS (sda2): Ending clean mount
[ 8700.508829] [T1053218] XFS (sda2): Unmounting Filesystem ...

personally I prefer 8 also for dmesg, because recent kernels have 7
digits (4 million) for PID_MAX_LIMIT [2] plus one for "T"|"C".

[1] https://github.com/util-linux/util-linux/pull/2647/commits/7e485b720638
[2] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/include/linux/threads.h#n34


The following comments are just my memo to be fixed when merging.

> ---
>   makedumpfile.c | 25 +++++++++++++++++++++++++
>   makedumpfile.h | 22 ++++++++++++++++++++++
>   printk.c       | 18 ++++++++++++++++++
>   3 files changed, 65 insertions(+)
> 
> diff --git a/makedumpfile.c b/makedumpfile.c
> index a6ec9d4..eaa8c4d 100644
> --- a/makedumpfile.c
> +++ b/makedumpfile.c
> @@ -28,6 +28,10 @@
>   #include <assert.h>
>   #include <zlib.h>
>   
> +#define PID_CHARS_MAX 16	/* Max Number of PID characters */
> +#define PID_CHARS_DEFAULT 8	/* Default number of PID characters */
> +
> +
>   struct symbol_table	symbol_table;
>   struct size_table	size_table;
>   struct offset_table	offset_table;
> @@ -2118,6 +2122,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 +2138,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");

This should be "OFFSET_INIT(printk_log.caller_id,".

>   	} else {
>   		info->flag_use_printk_ringbuffer = FALSE;
>   		info->flag_use_printk_log = FALSE;
> @@ -2462,6 +2468,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 +2477,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 +2929,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 +2941,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;
> @@ -5604,6 +5614,21 @@ dump_log_entry(char *logptr, int fp, const char *file_name)
>   
>   	bufp = buf;
>   	bufp += sprintf(buf, "[%5lld.%06ld] ", nanos, rem/1000);
> +
> +	if (OFFSET(printk_log.caller_id) != NOT_FOUND_STRUCTURE) {
> +		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(printk_log.caller_id));
> +		idtype = (pkc & cpuid) ? 'C' : 'T';
> +		pkc &= ~cpuid;
> +		sprintf(cidbuf, "%c%u", idtype, pkc);
> +		bufp += sprintf(bufp, "[%*s] ", PID_CHARS_DEFAULT, cidbuf);
> +	}
> +
>   	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

This seems not used, will remove.

> +
>   /*
>    * 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..88ff396 100644
> --- a/printk.c
> +++ b/printk.c
> @@ -1,6 +1,9 @@
>   #include "makedumpfile.h"
>   #include <ctype.h>
>   
> +#define PID_CHARS_MAX 16        /* Max Number of PID characters */
> +#define PID_CHARS_DEFAULT 8     /* Default number of PID characters */
> +
>   /* convenience struct for passing many values to helper functions */
>   struct prb_map {
>   	char		*prb;
> @@ -114,6 +117,21 @@ dump_record(struct prb_map *m, unsigned long id)
>   
>   	bufp = buf;
>   	bufp += sprintf(buf, "[%5lld.%06ld] ", nanos, rem/1000);
> +
> +	if (OFFSET(printk_info.caller_id) > NOT_FOUND_STRUCTURE) {

"!=" is better for the code consistency.

Thanks,
Kazu

> +		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(inf + OFFSET(printk_info.caller_id));
> +		idtype = (pkc & cpuid) ? 'C' : 'T';
> +		pkc &= ~cpuid;
> +		sprintf(cidbuf, "%c%u", idtype, pkc);
> +		bufp += sprintf(bufp, "[%*s] ", PID_CHARS_DEFAULT, cidbuf);
> +	}
> +
>   	indent_len = strlen(buf);
>   
>   	/* How much buffer space is needed in the worst case */


More information about the kexec mailing list