Re: [PATCH] printk: add cpu id information to printk() output
On Fri 2023-09-15 11:53:13, Greg KH wrote:
> On Fri, Sep 15, 2023 at 04:46:02PM +0800, Enlin Mu wrote:
> > John Ogness 于2023年9月15日周五 16:34写道：
> > >
> > > On 2023-09-15, Enlin Mu wrote:
> > > > Sometimes we want to print cpu id of printk() messages to consoles
> > > >
> > > > diff --git a/include/linux/threads.h b/include/linux/threads.h
> > > > index c34173e6c5f1..6700bd9a174f 100644
> > > > --- a/include/linux/threads.h
> > > > +++ b/include/linux/threads.h
> > > > @@ -34,6 +34,9 @@
> > > > #define PID_MAX_LIMIT (CONFIG_BASE_SMALL ? PAGE_SIZE * 8 : \
> > > > (sizeof(long) > 4 ? 4 * 1024 * 1024 : PID_MAX_DEFAULT))
> > > >
> > > > +#define CPU_ID_SHIFT 23
> > > > +#define CPU_ID_MASK 0xff80
> > >
> > > This only supports 256 CPUs. I think it doesn't make sense to try to
> > > squish CPU and Task IDs into 32 bits.
> > Yes, it is not good way,
> > >
> > > What about introducing a caller_id option to always only print the CPU
> > > ID? Or do you really need Task _and_ CPU?
> >Yes, I need it.Because I need to know which CPU is printing the
> > log, so that I can identify the current system operation, such as load
> > situation and CPU busy/idle status
>
> The cpu that is printing the log isn't the one that added the log
> message, so I think you will have incorrect data here, right?
We already store some metadata about the caller:
* All fields are set by the printk code except for @seq, which is
* set by the ringbuffer code.
*/
struct printk_info {
u64 seq;/* sequence number */
u64 ts_nsec;/* timestamp in nanoseconds */
u16 text_len; /* length of text message */
u8 facility; /* syslog facility */
u8 flags:5;/* internal record flags */
u8 level:3;/* syslog level */
u32 caller_id; /* thread id or processor id */
struct dev_printk_info dev_info;
};
The 32-bit caller ID is generated using:
static inline u32 printk_caller_id(void)
{
return in_task() ? task_pid_nr(current) :
0x8000 + smp_processor_id();
}
We could add more metadata and always store the CPU ID and something
like:
[CTXT][ Tpid][ Ccpu]
for example
[TASK][ T234][C4]
[ IRQ][ T4567][ C17]
[SIRQ][T5][C0]
[ NMI][ T356][ C128]
The biggest problem is that it would change the format of the
ringbuffer so that it would require updating external tools,
working with crashdump, especially crash but there are also
alternative python extensions for gdb.
See below POC of the kernel part. It is not even compile tested. The size
of the buffers is updated by a guess. Comments are not updated, ...
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 7d4979d5c3ce..e3e0a9fdc0cf 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -15,7 +15,7 @@ int devkmsg_sysctl_set_loglvl(struct ctl_table *table, int
write,
#ifdef CONFIG_PRINTK
#ifdef CONFIG_PRINTK_CALLER
-#define PRINTK_PREFIX_MAX 48
+#define PRINTK_PREFIX_MAX 64
#else
#define PRINTK_PREFIX_MAX 32
#endif
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 7e0b4dd02398..bb393ccbd5e9 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -621,16 +621,20 @@ static void append_char(char **pp, char *e, char c)
*(*pp)++ = c;
}
+char printk_caller_ctxt_txt[][] = { "TSK", "IRQ", "SIRQ", "NMI"' };
+
static ssize_t info_print_ext_header(char *buf, size_t size,
struct printk_info *info)
{
u64 ts_usec = info->ts_nsec;
- char caller[20];
+ char caller[40];
#ifdef CONFIG_PRINTK_CALLER
- u32 id = info->caller_id;
+ struct printk_caller_info *ci = info->caller_info;
- snprintf(caller, sizeof(caller), ",caller=%c%u",
-id & 0x8000 ? 'C' : 'T', id & ~0x8000);
+ snprintf(caller, sizeof(caller),
+",caller.ctxt=%s,caller.pid=%d,caller.cpu=%d",
+printk_caller_ctxt_txt[ci->ctxt],
+ci->pid,ci->cpu);
#else
caller[0] = '\0';
#endif
@@ -996,11 +1000,16 @@ void log_buf_vmcoreinfo_setup(void)
VMCOREINFO_OFFSET(prb_data_blk_lpos, begin);
VMCOREINFO_OFFSET(prb_data_blk_lpos, next);
+ VMCOREINFO_STRUCT_SIZE(printk_caller_info);
+ VMCOREINFO_OFFSET(printk_caller_info, ctxt);
+ VMCOREINFO_OFFSET(printk_caller_info, cpu);
+ VMCOREINFO_OFFSET(printk_caller_info, pid);
+
VMCOREINFO_STRUCT_SIZE(printk_info);
VMCOREINFO_OFFSET(printk_info, seq);
VMCOREINFO_OFFSET(printk_info, ts_nsec);
VMCOREINFO_OFFSET(printk_info, text_len);
- VMCOREINFO_OFFSET(printk_info, caller_id);
+ VMCOREINFO_OFFSET(printk_info, caller_info);
VMCOREINFO_OFFSET(printk_info, dev_info);
VMCOREINFO_STRUCT_SIZE(dev_printk_info);
@@ -,7 +1120,7 @@ static unsigned int __init a
RE: [PATCH] printk: add cpu id information to printk() output
> + return in_task() ? task_pid_nr(current) | (smp_processor_id() << > CPU_ID_SHIFT) : There are contexts and CONFIG options around pre-emption where smp_processor_id() will throw a warning. Use raw_smp_processor_id(). -Tony
Re: [PATCH] printk: add cpu id information to printk() output
On Fri, Sep 15, 2023 at 04:46:02PM +0800, Enlin Mu wrote: > John Ogness 于2023年9月15日周五 16:34写道： > > > > On 2023-09-15, Enlin Mu wrote: > > > Sometimes we want to print cpu id of printk() messages to consoles > > > > > > diff --git a/include/linux/threads.h b/include/linux/threads.h > > > index c34173e6c5f1..6700bd9a174f 100644 > > > --- a/include/linux/threads.h > > > +++ b/include/linux/threads.h > > > @@ -34,6 +34,9 @@ > > > #define PID_MAX_LIMIT (CONFIG_BASE_SMALL ? PAGE_SIZE * 8 : \ > > > (sizeof(long) > 4 ? 4 * 1024 * 1024 : PID_MAX_DEFAULT)) > > > > > > +#define CPU_ID_SHIFT 23 > > > +#define CPU_ID_MASK 0xff80 > > > > This only supports 256 CPUs. I think it doesn't make sense to try to > > squish CPU and Task IDs into 32 bits. > Yes, it is not good way, > > > > What about introducing a caller_id option to always only print the CPU > > ID? Or do you really need Task _and_ CPU? >Yes, I need it.Because I need to know which CPU is printing the > log, so that I can identify the current system operation, such as load > situation and CPU busy/idle status The cpu that is printing the log isn't the one that added the log message, so I think you will have incorrect data here, right? thanks, greg k-h
Re: [PATCH] printk: add cpu id information to printk() output
On Fri, Sep 15, 2023 at 03:40:34PM +0800, Enlin Mu wrote: > From: Enlin Mu > > Sometimes we want to print cpu id of printk() messages to consoles This is rejected every few years. What has changes from the previous times this was sent? And why can't you use trace_printk()? thanks, greg k-h
Re: [PATCH] printk: add cpu id information to printk() output
John Ogness 于2023年9月15日周五 16:34写道： > > On 2023-09-15, Enlin Mu wrote: > > Sometimes we want to print cpu id of printk() messages to consoles > > > > diff --git a/include/linux/threads.h b/include/linux/threads.h > > index c34173e6c5f1..6700bd9a174f 100644 > > --- a/include/linux/threads.h > > +++ b/include/linux/threads.h > > @@ -34,6 +34,9 @@ > > #define PID_MAX_LIMIT (CONFIG_BASE_SMALL ? PAGE_SIZE * 8 : \ > > (sizeof(long) > 4 ? 4 * 1024 * 1024 : PID_MAX_DEFAULT)) > > > > +#define CPU_ID_SHIFT 23 > > +#define CPU_ID_MASK 0xff80 > > This only supports 256 CPUs. I think it doesn't make sense to try to > squish CPU and Task IDs into 32 bits. Yes, it is not good way, > > What about introducing a caller_id option to always only print the CPU > ID? Or do you really need Task _and_ CPU? Yes, I need it.Because I need to know which CPU is printing the log, so that I can identify the current system operation, such as load situation and CPU busy/idle status > > John Ogness Thanks Enlin
Re: [PATCH] printk: add cpu id information to printk() output
On 2023-09-15, Enlin Mu wrote: > Sometimes we want to print cpu id of printk() messages to consoles > > diff --git a/include/linux/threads.h b/include/linux/threads.h > index c34173e6c5f1..6700bd9a174f 100644 > --- a/include/linux/threads.h > +++ b/include/linux/threads.h > @@ -34,6 +34,9 @@ > #define PID_MAX_LIMIT (CONFIG_BASE_SMALL ? PAGE_SIZE * 8 : \ > (sizeof(long) > 4 ? 4 * 1024 * 1024 : PID_MAX_DEFAULT)) > > +#define CPU_ID_SHIFT 23 > +#define CPU_ID_MASK 0xff80 This only supports 256 CPUs. I think it doesn't make sense to try to squish CPU and Task IDs into 32 bits. What about introducing a caller_id option to always only print the CPU ID? Or do you really need Task _and_ CPU? John Ogness
[PATCH] printk: add cpu id information to printk() output
From: Enlin Mu
Sometimes we want to print cpu id of printk() messages to consoles
Signed-off-by: Enlin Mu
---
include/linux/threads.h | 3 +++
kernel/printk/printk.c | 18 +-
2 files changed, 16 insertions(+), 5 deletions(-)
diff --git a/include/linux/threads.h b/include/linux/threads.h
index c34173e6c5f1..6700bd9a174f 100644
--- a/include/linux/threads.h
+++ b/include/linux/threads.h
@@ -34,6 +34,9 @@
#define PID_MAX_LIMIT (CONFIG_BASE_SMALL ? PAGE_SIZE * 8 : \
(sizeof(long) > 4 ? 4 * 1024 * 1024 : PID_MAX_DEFAULT))
+#define CPU_ID_SHIFT 23
+#define CPU_ID_MASK 0xff80
+
/*
* Define a minimum number of pids per cpu. Heuristically based
* on original pid max of 32k for 32 cpus. Also, increase the
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 7e0b4dd02398..f3f3ca89b251 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -629,8 +629,12 @@ static ssize_t info_print_ext_header(char *buf, size_t
size,
#ifdef CONFIG_PRINTK_CALLER
u32 id = info->caller_id;
- snprintf(caller, sizeof(caller), ",caller=%c%u",
-id & 0x8000 ? 'C' : 'T', id & ~0x8000);
+ if (id&0x8000)
+ snprintf(caller, sizeof(caller), ",caller=C%u",
+ id & ~0x8000);
+ else
+ snprintf(caller, sizeof(caller), ",caller=T%uC%u",
+ id & ~CPU_ID_MASK, id >> CPU_ID_SHIFT);
#else
caller[0] = '\0';
#endif
@@ -1333,8 +1337,12 @@ static size_t print_caller(u32 id, char *buf)
{
char caller[12];
- snprintf(caller, sizeof(caller), "%c%u",
-id & 0x8000 ? 'C' : 'T', id & ~0x8000);
+ if (id & 0x8000)
+ snprintf(caller, sizeof(caller), "C%u",
+ id & ~0x8000);
+ else
+ snprintf(caller, sizeof(caller), "T%uC%u",
+ id & ~CPU_ID_MASK, id >> CPU_ID_SHIFT);
return sprintf(buf, "[%6s]", caller);
}
#else
@@ -2069,7 +2077,7 @@ static inline void printk_delay(int level)
static inline u32 printk_caller_id(void)
{
- return in_task() ? task_pid_nr(current) :
+ return in_task() ? task_pid_nr(current) | (smp_processor_id() <<
CPU_ID_SHIFT) :
0x8000 + smp_processor_id();
}
--
2.25.1
