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

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

[Ruifeng Zhang]

From: Ruifeng Zhang <ruifeng.zhang1@unisoc.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@unisoc.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

Re: [PATCH v1 1/1] printk: always output coreid in caller information

[John Ogness]

Hello Ruifeng,

On 2021-05-19, Ruifeng Zhang <ruifeng.zhang0110@gmail.com> wrote:
> From: Ruifeng Zhang <ruifeng.zhang1@unisoc.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

The primary purpose of @caller_id is so that the printk-subsystem can
coordinate LOG_CONT messages.

Your patch is about logging/printing additional context attributes of
the printk-caller. This is something we have discussed before [0]. I
think this should be addressed at some point. But we need to come up
with a solution that is flexible and generic. We should not be touching
these core structures every time some new attribute needs to be printed.

Also, this patch is controversial for other reasons:

- it adds bitwise logic, when it could more easily just add a new field
  (for example, caller_cpu)

- it increases the size of all records by 4 bytes

- it changes the internal structure in a way that breaks existing crash
  tools

- for non-task contexts, the increased size is wasted

John Ogness

[0] https://lore.kernel.org/lkml/20200904082438.20707-1-changki.kim@samsung.com

Re: [PATCH v1 1/1] printk: always output coreid in caller information

[Ruifeng Zhang]

Dear John,

Thanks for your review and reply.

I am glad to know the Linux Community had been discussing this requirements.

My patch really has some problems you proposed.

I will pay attention to the modification about extra message output in printk.

Thanks.

Best regards,
Ruifeng

John Ogness <john.ogness@linutronix.de> 于2021年5月19日周三 下午4:25写道：
>
> Hello Ruifeng,
>
> On 2021-05-19, Ruifeng Zhang <ruifeng.zhang0110@gmail.com> wrote:
> > From: Ruifeng Zhang <ruifeng.zhang1@unisoc.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
>
> The primary purpose of @caller_id is so that the printk-subsystem can
> coordinate LOG_CONT messages.
>
> Your patch is about logging/printing additional context attributes of
> the printk-caller. This is something we have discussed before [0]. I
> think this should be addressed at some point. But we need to come up
> with a solution that is flexible and generic. We should not be touching
> these core structures every time some new attribute needs to be printed.
>
> Also, this patch is controversial for other reasons:
>
> - it adds bitwise logic, when it could more easily just add a new field
>   (for example, caller_cpu)
>
> - it increases the size of all records by 4 bytes
>
> - it changes the internal structure in a way that breaks existing crash
>   tools
>
> - for non-task contexts, the increased size is wasted
>
> John Ogness
>
> [0] https://lore.kernel.org/lkml/20200904082438.20707-1-changki.kim@samsung.com