linux-kernel - [PATCH v1 1/1] printk: always output coreid in caller information

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Message-Id: <20210519063355.5147-1-ruifeng.zhang0110@gmail.com>
Date:   Wed, 19 May 2021 14:33:55 +0800
From:   Ruifeng Zhang <ruifeng.zhang0110@...il.com>
To:     pmladek@...e.com, senozhatsky@...omium.org, rostedt@...dmis.org,
        john.ogness@...utronix.de
Cc:     linux-kernel@...r.kernel.org, ruifeng.zhang1@...soc.com,
        nianfu.bai@...soc.com, orson.zhai@...soc.com
Subject: [PATCH v1 1/1] printk: always output coreid in caller information

From: Ruifeng Zhang <ruifeng.zhang1@...soc.com>

Sometimes we want to know which cpu the process is running
on when the log output, rather than the thread id.  So add
the processor id output always in the caller information.

caller_id bitmap:
[63:32] thread_id
[31]    flags of in thread context
[30:0]  processor id

About the output format, reserve 5 bits for thread id and
2 bits for processor id.

e.g.
Before:
[    0.000000][    T0] Booting Linux on physical CPU 0x0
[    0.109338][    T1] smp: Bringing up secondary CPUs ...
[    0.115831][    T0] CPU1: thread 0, cpu 1, socket 0, mpidr 81000100
[    0.117051][    T0] CPU2: thread 0, cpu 2, socket 0, mpidr 81000200
[    0.118207][    T0] CPU3: thread 0, cpu 3, socket 0, mpidr 81000300
[  114.112319][T25122] binder:

After:
[    0.000000][     T0:C0] Booting Linux on physical CPU 0x0
[    0.114549][     T1:C0] smp: Bringing up secondary CPUs ...
[    0.121377][     T0:C1] CPU1: thread 0, cpu 1, socket 0, mpidr 81000100
[    0.122606][     T0:C2] CPU2: thread 0, cpu 2, socket 0, mpidr 81000200
[    0.123758][     T0:C3] CPU3: thread 0, cpu 3, socket 0, mpidr 81000300
[   43.260158][        C1] Irq_monitor:Irq
[  112.862589][ T21442:C5] binder:

Signed-off-by: Ruifeng Zhang <ruifeng.zhang1@...soc.com>
---
 kernel/printk/printk.c            | 36 +++++++++++++++++++++----------
 kernel/printk/printk_ringbuffer.h |  2 +-
 2 files changed, 26 insertions(+), 12 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 421c35571797..8ef4acefce19 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -331,7 +331,7 @@ static int console_msg_format = MSG_FORMAT_DEFAULT;
  *   record.info.facility           = 0 (LOG_KERN)
  *   record.info.flags              = 0
  *   record.info.level              = 3 (LOG_ERR)
- *   record.info.caller_id          = 299 (task 299)
+ *   record.info.caller_id          = 1286342705152 ([63:32]=299 [31]=1 [30:0]=0)
  *   record.info.dev_info.subsystem = "pci" (terminated)
  *   record.info.dev_info.device    = "+pci:0000:00:01.0" (terminated)
  *
@@ -559,10 +559,15 @@ static ssize_t info_print_ext_header(char *buf, size_t size,
 	u64 ts_usec = info->ts_nsec;
 	char caller[20];
 #ifdef CONFIG_PRINTK_CALLER
-	u32 id = info->caller_id;
+	u64 id = info->caller_id;
 
-	snprintf(caller, sizeof(caller), ",caller=%c%u",
-		 id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
+	if (id & 0x80000000)
+		snprintf(caller, sizeof(caller), ",caller=T%u:C%u",
+			 (u32)(id >> 32),
+			 (u32)(id & ~0x80000000));
+	else
+		snprintf(caller, sizeof(caller), ",caller=C%u",
+			 (u32)(id & ~0x80000000));
 #else
 	caller[0] = '\0';
 #endif
@@ -1273,9 +1278,15 @@ static size_t print_caller(u32 id, char *buf)
 {
 	char caller[12];
 
-	snprintf(caller, sizeof(caller), "%c%u",
-		 id & 0x80000000 ? 'C' : 'T', id & ~0x80000000);
-	return sprintf(buf, "[%6s]", caller);
+	if (id & 0x80000000)
+		snprintf(caller, sizeof(caller), "T%u:C%u",
+			 (u32)(id >> 32),
+			 (u32)(id & ~0x80000000));
+	else
+		snprintf(caller, sizeof(caller), "C%u",
+			 (u32)(id & ~0x80000000));
+
+	return sprintf(buf, "[%10s]", caller);
 }
 #else
 #define print_caller(id, buf) 0
@@ -1954,10 +1965,13 @@ static inline void printk_delay(void)
 	}
 }
 
-static inline u32 printk_caller_id(void)
+static inline u64 printk_caller_id(void)
 {
-	return in_task() ? task_pid_nr(current) :
-		0x80000000 + raw_smp_processor_id();
+	if (in_task())
+		return (u64)task_pid_nr(current) << 32 |
+			0x80000000 + raw_smp_processor_id();
+	else
+		return raw_smp_processor_id();
 }
 
 /**
@@ -2036,7 +2050,7 @@ int vprintk_store(int facility, int level,
 		  const struct dev_printk_info *dev_info,
 		  const char *fmt, va_list args)
 {
-	const u32 caller_id = printk_caller_id();
+	const u64 caller_id = printk_caller_id();
 	struct prb_reserved_entry e;
 	enum log_flags lflags = 0;
 	struct printk_record r;
diff --git a/kernel/printk/printk_ringbuffer.h b/kernel/printk/printk_ringbuffer.h
index 73cc80e01cef..c0a3146c7ac2 100644
--- a/kernel/printk/printk_ringbuffer.h
+++ b/kernel/printk/printk_ringbuffer.h
@@ -19,7 +19,7 @@ struct printk_info {
 	u8	facility;	/* syslog facility */
 	u8	flags:5;	/* internal record flags */
 	u8	level:3;	/* syslog level */
-	u32	caller_id;	/* thread id or processor id */
+	u64	caller_id;      /* thread id or processor id */
 
 	struct dev_printk_info	dev_info;
 };
-- 
2.17.1