12:31 p.m.
Submission to Project: crash
Component: dmesg
Files: kernel.c printk.c symbols.c help.c defs.h
Code level patch applied against: 8.0.4++ - latest code pulled from
https://github.com/crash-utility/crash.git
crash Issue #164
Patch Version #2: per review from Hagio Kazuhito <k-hagio-ab(a)nec.com>
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 patch applied
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 patch applied
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 (-c) is selected:
crash> log -m -c
...
[ 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: -c
The PRINTK_CALLER id field is printed only if the -c option is selected.
The description of the log -c option that is seen in the help is:
crash> log help
log
dump system message buffer
[-Ttdmasc]
...
...
-c Display the caller id field that identifies either the thread id or
the CPU id (if in CPU context) that called printk(), if available.
Generally available on Linux 5.1 to 5.9 kernels configured with
CONFIG_PRINTK_CALLER or Linux 5.10 and later kernels.
Also seen in the help file :
Display the caller id that identifies the thread id of the task (begins
with 'T') or the processor id (begins with 'C' for in CPU context) that
called printk(), if available.
crash> log -c
...
[ 0.014179] [ T1] Secure boot disabled
[ 0.014179] [ T29] RAMDISK: [mem 0x3cf4f000-0x437bbfff]
[ 0.198789] [ C0] DMAR: DRHD: handling fault status reg 3
...
Signed-off-by: Ivan Delalande <colona(a)arista.com>
Signed-off-by: Edward Chron <echron(a)arista.com>
---
defs.h | 18 ++++++++++++------
help.c | 19 +++++++++++++++++--
kernel.c | 25 ++++++++++++++++++++++++-
printk.c | 34 ++++++++++++++++++++++++++++++++++
symbols.c | 2 ++
6 files changed, 98 insertions(+), 18 deletions(-)
diff --git a/defs.h b/defs.h
index 2a29c07..488214f 100644
--- a/defs.h
+++ b/defs.h
@@ -2228,8 +2228,13 @@ struct offset_table { /* stash of commonly-used
offsets */
long irq_data_irq;
long zspage_huge;
long zram_comp_algs;
+ long log_caller_id;
};
+/* caller_id default and max character sizes based on pid field size */
+#define PID_CHARS_MAX 16 /* Max Number of PID characters */
+#define PID_CHARS_DEFAULT 8 /* Default number of PID characters */
+
struct size_table { /* stash of commonly-used sizes */
long page;
long free_area_struct;
@@ -6044,12 +6049,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 a4319dd..ae02a57 100644
--- a/help.c
+++ b/help.c
@@ -4023,7 +4023,7 @@ NULL
char *help_log[] = {
"log",
"dump system message buffer",
-"[-Ttdmas]",
+"[-Ttdmasc]",
" 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,11 @@ 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.",
-" ",
+" -c Display the caller id field that identifies either the thread id or",
+" the CPU id (if in CPU context) that called printk(), if available.",
+" Generally available on Linux 5.1 to 5.9 kernels configured with",
+" CONFIG_PRINTK_CALLER or Linux 5.10 and later kernels.",
+" ",
"\nEXAMPLES",
" Dump the kernel message buffer:\n",
" %s> log",
@@ -4214,6 +4218,17 @@ char *help_log[] = {
" CPU: 0 ADDR: ffff8ca4fbc1ad00 LEN: 0 MESSAGE_LOST: 0",
" (empty)",
" ...",
+" ",
+" Display the caller id that identifies the thread id of the task (begins",
+" with 'T') or the processor id (begins with 'C' for in CPU
context) that",
+" called printk(), if available.\n",
+" %s> log -c",
+" ...",
+" [ 0.014179] [ T1] Secure boot disabled",
+" [ 0.014179] [ T29] RAMDISK: [mem 0x3cf4f000-0x437bbfff]",
+" [ 0.198789] [ C0] DMAR: DRHD: handling fault status reg 3",
+" ...",
+
NULL
};
diff --git a/kernel.c b/kernel.c
index 6dcf414..bcd10f9 100644
--- a/kernel.c
+++ b/kernel.c
@@ -5089,7 +5089,7 @@ cmd_log(void)
msg_flags = 0;
- while ((c = getopt(argcnt, args, "Ttdmas")) != EOF) {
+ while ((c = getopt(argcnt, args, "Ttdmasc")) != EOF) {
switch(c)
{
case 'T':
@@ -5110,6 +5110,9 @@ cmd_log(void)
case 's':
msg_flags |= SHOW_LOG_SAFE;
break;
+ case 'c':
+ msg_flags |= SHOW_LOG_CALLER;
+ break;
default:
argerrs++;
break;
@@ -5369,6 +5372,24 @@ 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 &&
+ VALID_MEMBER(log_caller_id)) {
+ const unsigned int cpuid = 0x80000000;
+ char cbuf[PID_CHARS_MAX];
+ unsigned int cid;
+
+ /* Get id type, isolate just id value in cid for print */
+ cid = UINT(logptr + OFFSET(log_caller_id));
+ sprintf(cbuf, "%c%d", (cid & cpuid) ? 'C' : 'T', cid
& ~cpuid);
+ sprintf(buf, "[%*s] ", PID_CHARS_DEFAULT, cbuf);
+
+ ilen += strlen(buf);
+ fprintf(fp, "%s", buf);
+ }
+
level = LOG_LEVEL(level);
if (msg_flags & SHOW_LOG_LEVEL) {
@@ -5424,6 +5445,8 @@ dump_variable_length_record_log(int msg_flags)
* from log to printk_log. See 62e32ac3505a0cab.
*/
log_struct_name = "printk_log";
+ MEMBER_OFFSET_INIT(log_caller_id, "printk_log",
+ "caller_id");
} else
log_struct_name = "log";
diff --git a/printk.c b/printk.c
index 8658016..ae3fa4f 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;
@@ -162,6 +163,24 @@ 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 cbuf[PID_CHARS_MAX];
+ unsigned int cid;
+
+ /* Get id type, isolate id value in cid for print */
+ cid = UINT(info + OFFSET(printk_info_caller_id));
+ sprintf(cbuf, "%c%d", (cid & cpuid) ? 'C' : 'T', cid
& ~cpuid);
+ sprintf(buf, "[%*s] ", m->pid_max_chars, cbuf);
+
+ 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 +281,21 @@ dump_lockless_record_log(int msg_flags)
goto out_text_data;
}
+ /* If caller_id was requested, get the pid_max value for print */
+ if (msg_flags & SHOW_LOG_CALLER) {
+ unsigned int pidmax;
+
+ get_symbol_data("pid_max", sizeof(pidmax), &pidmax);
+ if (pidmax <= 99999)
+ m.pid_max_chars = 6;
+ else if (pidmax <= 999999)
+ m.pid_max_chars = 7;
+ else
+ m.pid_max_chars = PID_CHARS_DEFAULT;
+ } 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 88a3fd1..554d109 100644
--- a/symbols.c
+++ b/symbols.c
@@ -11524,6 +11524,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));
--
2.43.0