From: Ruifeng Zhang <[email protected]>
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 <[email protected]>
---
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
Hello Ruifeng,
On 2021-05-19, Ruifeng Zhang <[email protected]> wrote:
> From: Ruifeng Zhang <[email protected]>
>
> 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/[email protected]
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 <[email protected]> 于2021年5月19日周三 下午4:25写道：
>
> Hello Ruifeng,
>
> On 2021-05-19, Ruifeng Zhang <[email protected]> wrote:
> > From: Ruifeng Zhang <[email protected]>
> >
> > 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/[email protected]