RE: [RFC 2/2] printk: Add more information about the printk caller
> +static size_t info_print_caller_id(char *buf, size_t size,
> +const struct printk_caller *caller) {
> + enum printk_caller_ctx ctx;
> +
> + ctx = printk_to_caller_ctx(caller->cpu_ctx);
> +
> + if (ctx == printk_ctx_task)
> + return snprintf(buf, size, "T%u", caller->pid);
> +
> + return snprintf(buf, size, "C%u",
> +printk_to_caller_cpu(caller->cpu_ctx));
> +}
> +
When I apply and test this patch, there is no change of print format
compared with previous PRINTK_CALLER.
The patch that I made is always to print the CPU ID and process name
together.
Re: [RFC 2/2] printk: Add more information about the printk caller
On Fri 2020-09-25 09:54:00, Sergey Senozhatsky wrote: > On (20/09/24 15:38), Petr Mladek wrote: > [..] > > > > G, I wonder why I thought that in_irq() covered also the situation > > when IRQ was disabled. It was likely my wish because disabled > > interrupts are problem for printk() because the console might > > cause a softlockup. > > preempt_disable() can also trigger softlockup. > > > in_irq() actually behaves like in_serving_softirq(). > > > > I am confused and puzzled now. I wonder what contexts are actually > > interesting for developers. It goes back to the ideas from Sergey > > about preemption disabled, ... > > Are we talking about context tracking for LOG_CONT or context on > the serial console and /dev/kmsg? OK, it is clear that LOG_CONT need to know when a different code is called suddenly. I mean task code vs. an interrupt handler. But it was actually also the original purpose of the caller_id. AFAIK, people wanted to sort related messages when they were mixed with ones from other CPUs. > If the latter, then my 5 cents, is that something like preemptible(), > which checks > > (preempt_count() == 0 && !irqs_disabled()) > > does not look completely unreasonable. > > We had a rather OK context tracking in printk() before, but for a > completely different purpose: > >console_may_schedule = !oops_in_progress && >preemptible() && >!rcu_preempt_depth(); > > We know that printk() can cause RCU stalls [0]. Tracking this part > of the context state is sort of meaningful. > > Let's look at this from this POV - why do we add in_irq()/etc tracking > info? Perhaps because we want to connect the dots between printk() caller > state and watchdog reports. Do we cover all watchdogs? No, I don't think > so. RCU stalls, local_irq_disable(), preempt_disable() are not covered. I agree that it would be handy to see this context as well. It might make it easier when hunting down various lockups and stall. But I have some concerns. First, the information is not always reliable (PREEMPT_NONE). I wonder if it might cause more harm than good. People might get confused or they might want to fix it by some crazy printk code. Second, the information might not be detailed enough. Many lockups depends on the fact that a particular lock is held. Backtraces are likely more important. Or people would need to distinguish many contexts. It would require another complex code. I am not sure that this is woth it. After all, it might be enough to distinguish the 4 basic contexts just to allow sorting mixed messages. Best Regards, Petr
Re: [RFC 2/2] printk: Add more information about the printk caller
On (20/09/24 15:38), Petr Mladek wrote: [..] > > G, I wonder why I thought that in_irq() covered also the situation > when IRQ was disabled. It was likely my wish because disabled > interrupts are problem for printk() because the console might > cause a softlockup. preempt_disable() can also trigger softlockup. > in_irq() actually behaves like in_serving_softirq(). > > I am confused and puzzled now. I wonder what contexts are actually > interesting for developers. It goes back to the ideas from Sergey > about preemption disabled, ... Are we talking about context tracking for LOG_CONT or context on the serial console and /dev/kmsg? If the latter, then my 5 cents, is that something like preemptible(), which checks (preempt_count() == 0 && !irqs_disabled()) does not look completely unreasonable. We had a rather OK context tracking in printk() before, but for a completely different purpose: console_may_schedule = !oops_in_progress && preemptible() && !rcu_preempt_depth(); We know that printk() can cause RCU stalls [0]. Tracking this part of the context state is sort of meaningful. Let's look at this from this POV - why do we add in_irq()/etc tracking info? Perhaps because we want to connect the dots between printk() caller state and watchdog reports. Do we cover all watchdogs? No, I don't think so. RCU stalls, local_irq_disable(), preempt_disable() are not covered. Do we have any technical reasons not to add those missing bits? [0] https://lkml.org/lkml/2018/1/9/485 -ss
Re: [RFC 2/2] printk: Add more information about the printk caller
On Thu 2020-09-24 14:53:01, Petr Mladek wrote:
> On Thu 2020-09-24 06:24:14, Ahmed S. Darwish wrote:
> > On Wed, Sep 23, 2020 at 03:56:17PM +0200, Petr Mladek wrote:
> > ...
> > >
> > > -static inline u32 printk_caller_id(void)
> > > +static enum printk_caller_ctx get_printk_caller_ctx(void)
> > > +{
> > > + if (in_nmi())
> > > + return printk_ctx_nmi;
> > > +
> > > + if (in_irq())
> > > + return printk_ctx_hardirq;
> > > +
> > > + if (in_softirq())
> > > + return printk_ctx_softirq;
> > > +
> > > + return printk_ctx_task;
> > > +}
> > > +
> >
> > in_softirq() here will be true for both softirq contexts *and*
> > BH-disabled regions. Did you mean in_serving_softirq() instead?
>
> Good question!
>
> I am not sure if people would want to distinguish these two
> situations.
>
> Otherwise, I think that is_softirq() more close to the meaning of
> in_irq(). They both describe a context where a new interrupt has
> to wait until the handling gets enabled again.
G, I wonder why I thought that in_irq() covered also the situation
when IRQ was disabled. It was likely my wish because disabled
interrupts are problem for printk() because the console might
cause a softlockup.
in_irq() actually behaves like in_serving_softirq().
I am confused and puzzled now. I wonder what contexts are actually
interesting for developers. It goes back to the ideas from Sergey
about preemption disabled, ...
/me feels shameful and is going to hide under a stone.
Best Regards,
Petr
Re: [RFC 2/2] printk: Add more information about the printk caller
On Thu 2020-09-24 10:29:31, John Ogness wrote: > On 2020-09-24, Sergey Senozhatsky wrote: > > A question. Suppose we have a task which does > > > > CPU0 > > > > pr_err(...); > > > > preempt_disable(); > > pr_err(...); > > preempt_enable(); > > > > pr_err(...); > > > > rcu_read_lock(); > > pr_info(...); > > rcu_read_unlock(); > > > > Should we distinguish those as 3 different contexts? > > > > - normal printk > > - printk under disabled preemption (affects scheduling) > > - printk under RCU read side lock (affects RCU grace periods) > > The internal purpose of the printk_info's @caller_id is to support > _some_ sanity with LOG_CONT. True LOG_CONT sanity will not be available > until we provide a context API like we previously talked about [0]. But > for now it is good enough (even if it is not good). > > We can also store various flags and counters to describe the current > context. But these would only exist to provide the user with information > rather than because printk itself needs it. I only mention this so that > we don't get things mixed up. We can add as much information as want, > but LOG_CONT will only be interested in a subset of that. Yeah, we need to keep this in mind, so that some "tiny" changes in the context would not prevent concatenating related pieces of the message. Best Regards, Petr
Re: [RFC 2/2] printk: Add more information about the printk caller
On Thu 2020-09-24 11:17:56, Sergey Senozhatsky wrote:
> On (20/09/23 15:56), Petr Mladek wrote:
> [..]
> > /*
> > * To reduce unnecessarily reopening, first check if the descriptor
> > -* state and caller ID are correct.
> > +* state and caller infromation are correct.
> > */
> > - d_state = desc_read(desc_ring, id, , NULL, );
> > - if (d_state != desc_committed || cid != caller_id)
> > + d_state = desc_read(desc_ring, id, , NULL, );
> > + if (d_state != desc_committed ||
> > + cal.pid != caller->pid ||
> > + cal.cpu_ctx != caller->cpu_ctx) {
>
> You probably might want to factor out ctx check into a static
> inline helper. Since you use this check in several places, and
> we may check more context fields in the future.
Makes sense.
> [..]
> > +/* Information about the process and context that adds the message */
> > +struct printk_caller {
> > + pid_t pid; /* thread id */
> > + u32 cpu_ctx;/* processor id and interrupt context */
> > +};
>
> A question. Suppose we have a task which does
>
> CPU0
>
> pr_err(...);
>
> preempt_disable();
> pr_err(...);
> preempt_enable();
>
> pr_err(...);
>
> rcu_read_lock();
> pr_info(...);
> rcu_read_unlock();
>
> Should we distinguish those as 3 different contexts?
>
> - normal printk
> - printk under disabled preemption (affects scheduling)
> - printk under RCU read side lock (affects RCU grace periods)
Good question. Well, these contexts could not get detected in
PREEMPT_NONE or PREEMPT_VOLUNTARY. Also I wonder where it would
stop. There are several RCU flavors.
I would not distinguish them unless there is a real demand.
Best Regards,
Petr
Re: [RFC 2/2] printk: Add more information about the printk caller
On Thu 2020-09-24 06:24:14, Ahmed S. Darwish wrote:
> On Wed, Sep 23, 2020 at 03:56:17PM +0200, Petr Mladek wrote:
> ...
> >
> > -static inline u32 printk_caller_id(void)
> > +static enum printk_caller_ctx get_printk_caller_ctx(void)
> > +{
> > + if (in_nmi())
> > + return printk_ctx_nmi;
> > +
> > + if (in_irq())
> > + return printk_ctx_hardirq;
> > +
> > + if (in_softirq())
> > + return printk_ctx_softirq;
> > +
> > + return printk_ctx_task;
> > +}
> > +
>
> in_softirq() here will be true for both softirq contexts *and*
> BH-disabled regions. Did you mean in_serving_softirq() instead?
Good question!
I am not sure if people would want to distinguish these two
situations.
Otherwise, I think that is_softirq() more close to the meaning of
in_irq(). They both describe a context where a new interrupt has
to wait until the handling gets enabled again.
Best Regards,
Petr
Re: [RFC 2/2] printk: Add more information about the printk caller
On Thu 2020-09-24 10:40:10, Sergey Senozhatsky wrote:
> On (20/09/23 15:56), Petr Mladek wrote:
> > The information about the printk caller has been added by the commit
> > 15ff2069cb7f967da ("printk: Add caller information to printk() output.").
> > The main motivation was to reconstruct original messages when they
> > longer output from different CPUs got mixed.
> >
> > But there are more usecases. The number of CPUs and tasks running on
> > a single system is growing. It brings bigger challenges when debugging
> > problems. The context in which kernel reports its state is sometimes
> > pretty useful.
> >
> > In particular, people suggest to remember the task id, cpu id, more details
> > about the interrupt context, and even the task name [0][1].
> >
> > Prepare for extending the caller information by replacing caller_id
> > with struct printk_caller. And always store task id, cpu id, and
> > exact interrupt context.
>
> Wild idea:
>
> Currently, we have two sides to the problem, I think. There are tasks
> that store messages, but then there are tasks that print those messages
> on the consoles. And those tasks and contexts are not always the same.
> What I found helpful in the past was not only the caller_id, but the
> emitter_id (especially preemption count and irqs state of the context
> that prints messages on the slow consoles).
Yeah, it might be useful. But it should get discussed in a separate thread.
The information about the emitter do not need to get stored into the
metadata. It is mostly need only for debugging printk-related
problems. It should become less important if we succeed with
introducing the printk kthreads.
Best Regards,
Petr
Re: [RFC 2/2] printk: Add more information about the printk caller
On 2020-09-24, Sergey Senozhatsky wrote: > A question. Suppose we have a task which does > > CPU0 > > pr_err(...); > > preempt_disable(); > pr_err(...); > preempt_enable(); > > pr_err(...); > > rcu_read_lock(); > pr_info(...); > rcu_read_unlock(); > > Should we distinguish those as 3 different contexts? > > - normal printk > - printk under disabled preemption (affects scheduling) > - printk under RCU read side lock (affects RCU grace periods) The internal purpose of the printk_info's @caller_id is to support _some_ sanity with LOG_CONT. True LOG_CONT sanity will not be available until we provide a context API like we previously talked about [0]. But for now it is good enough (even if it is not good). We can also store various flags and counters to describe the current context. But these would only exist to provide the user with information rather than because printk itself needs it. I only mention this so that we don't get things mixed up. We can add as much information as want, but LOG_CONT will only be interested in a subset of that. John Ogness
Re: [RFC 2/2] printk: Add more information about the printk caller
On Wed, Sep 23, 2020 at 03:56:17PM +0200, Petr Mladek wrote:
...
>
> -static inline u32 printk_caller_id(void)
> +static enum printk_caller_ctx get_printk_caller_ctx(void)
> +{
> + if (in_nmi())
> + return printk_ctx_nmi;
> +
> + if (in_irq())
> + return printk_ctx_hardirq;
> +
> + if (in_softirq())
> + return printk_ctx_softirq;
> +
> + return printk_ctx_task;
> +}
> +
in_softirq() here will be true for both softirq contexts *and*
BH-disabled regions. Did you mean in_serving_softirq() instead?
Thanks,
--
Ahmed S. Darwish
Linutronix GmbH
Re: [RFC 2/2] printk: Add more information about the printk caller
On (20/09/23 15:56), Petr Mladek wrote:
[..]
> /*
>* To reduce unnecessarily reopening, first check if the descriptor
> - * state and caller ID are correct.
> + * state and caller infromation are correct.
>*/
> - d_state = desc_read(desc_ring, id, , NULL, );
> - if (d_state != desc_committed || cid != caller_id)
> + d_state = desc_read(desc_ring, id, , NULL, );
> + if (d_state != desc_committed ||
> + cal.pid != caller->pid ||
> + cal.cpu_ctx != caller->cpu_ctx) {
You probably might want to factor out ctx check into a static
inline helper. Since you use this check in several places, and
we may check more context fields in the future.
[..]
> +/* Information about the process and context that adds the message */
> +struct printk_caller {
> + pid_t pid; /* thread id */
> + u32 cpu_ctx;/* processor id and interrupt context */
> +};
A question. Suppose we have a task which does
CPU0
pr_err(...);
preempt_disable();
pr_err(...);
preempt_enable();
pr_err(...);
rcu_read_lock();
pr_info(...);
rcu_read_unlock();
Should we distinguish those as 3 different contexts?
- normal printk
- printk under disabled preemption (affects scheduling)
- printk under RCU read side lock (affects RCU grace periods)
-ss
Re: [RFC 2/2] printk: Add more information about the printk caller
On (20/09/23 15:56), Petr Mladek wrote:
> The information about the printk caller has been added by the commit
> 15ff2069cb7f967da ("printk: Add caller information to printk() output.").
> The main motivation was to reconstruct original messages when they
> longer output from different CPUs got mixed.
>
> But there are more usecases. The number of CPUs and tasks running on
> a single system is growing. It brings bigger challenges when debugging
> problems. The context in which kernel reports its state is sometimes
> pretty useful.
>
> In particular, people suggest to remember the task id, cpu id, more details
> about the interrupt context, and even the task name [0][1].
>
> Prepare for extending the caller information by replacing caller_id
> with struct printk_caller. And always store task id, cpu id, and
> exact interrupt context.
Wild idea:
Currently, we have two sides to the problem, I think. There are tasks
that store messages, but then there are tasks that print those messages
on the consoles. And those tasks and contexts are not always the same.
What I found helpful in the past was not only the caller_id, but the
emitter_id (especially preemption count and irqs state of the context
that prints messages on the slow consoles).
-ss
[RFC 2/2] printk: Add more information about the printk caller
The information about the printk caller has been added by the commit
15ff2069cb7f967da ("printk: Add caller information to printk() output.").
The main motivation was to reconstruct original messages when they
longer output from different CPUs got mixed.
But there are more usecases. The number of CPUs and tasks running on
a single system is growing. It brings bigger challenges when debugging
problems. The context in which kernel reports its state is sometimes
pretty useful.
In particular, people suggest to remember the task id, cpu id, more details
about the interrupt context, and even the task name [0][1].
Prepare for extending the caller information by replacing caller_id
with struct printk_caller. And always store task id, cpu id, and
exact interrupt context.
The output to console and /dev/kmsg stays the same for now. I will
get improved by followup patches.
[0]
https://lore.kernel.org/r/CAHk-=wibpwj9m1jqwejuq+ipmg9thalany-uaruakhuezfh...@mail.gmail.com
[1] https://lore.kernel.org/r/20200904082438.20707-1-changki@samsung.com
Signed-off-by: Petr Mladek
---
kernel/printk/printk.c| 107 +++---
kernel/printk/printk_ringbuffer.c | 43 ++--
kernel/printk/printk_ringbuffer.h | 39 ++-
3 files changed, 131 insertions(+), 58 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0ed8901916f4..2f904bb744a6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -333,7 +333,8 @@ 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.pid = 299 (task 299)
+ * record.info.cpu_ctx= 0x8003 (in hardirq context on cpu 3)
* record.info.dev_info.subsystem = "pci" (terminated)
* record.info.dev_info.device= "+pci::00:01.0" (terminated)
*
@@ -494,8 +495,9 @@ static void truncate_msg(u16 *text_len, u16 *trunc_msg_len)
}
/* insert record into the buffer, discard old ones, update heads */
-static int log_store(u32 caller_id, int facility, int level,
-enum log_flags flags, struct ktime_timestamps *ts,
+static int log_store(const struct printk_caller *caller,
+int facility, int level, enum log_flags flags,
+struct ktime_timestamps *ts,
const struct dev_printk_info *dev_info,
const char *text, u16 text_len)
{
@@ -526,7 +528,7 @@ static int log_store(u32 caller_id, int facility, int level,
r.info->ts = *ts;
else
ktime_get_fast_timestamps(>ts);
- r.info->caller_id = caller_id;
+ r.info->caller = *caller;
if (dev_info)
memcpy(>dev_info, dev_info, sizeof(r.info->dev_info));
@@ -588,26 +590,40 @@ static void append_char(char **pp, char *e, char c)
*(*pp)++ = c;
}
+static size_t info_print_caller_id(char *buf, size_t size,
+ const struct printk_caller *caller)
+{
+ enum printk_caller_ctx ctx;
+
+ ctx = printk_to_caller_ctx(caller->cpu_ctx);
+
+ if (ctx == printk_ctx_task)
+ return snprintf(buf, size, "T%u", caller->pid);
+
+ return snprintf(buf, size, "C%u",
printk_to_caller_cpu(caller->cpu_ctx));
+}
+
static ssize_t info_print_ext_header(char *buf, size_t size,
struct printk_info *info)
{
u64 ts_mono_usec = info->ts.mono;
- char caller[20];
-#ifdef CONFIG_PRINTK_CALLER
- u32 id = info->caller_id;
-
- snprintf(caller, sizeof(caller), ",caller=%c%u",
-id & 0x8000 ? 'C' : 'T', id & ~0x8000);
-#else
- caller[0] = '\0';
-#endif
+ char caller_id[12];
+ size_t len;
do_div(ts_mono_usec, 1000);
- return scnprintf(buf, size, "%u,%llu,%llu,%c%s;",
-(info->facility << 3) | info->level, info->seq,
-ts_mono_usec, info->flags & LOG_CONT ? 'c' : '-',
-caller);
+ len = scnprintf(buf, size, "%u,%llu,%llu,%c",
+ (info->facility << 3) | info->level, info->seq,
+ ts_mono_usec, info->flags & LOG_CONT ? 'c' : '-');
+
+ if (IS_ENABLED(CONFIG_PRINTK_CALLER)) {
+ info_print_caller_id(caller_id, sizeof(caller_id),
>caller);
+ len += scnprintf(buf + len, size - len, ",caller=%s",
caller_id);
+ }
+
+ len += scnprintf(buf + len, size - len, ";");
+
+ return len;
}
static ssize_t msg_add_ext_text(char *buf, size_t size,
@@ -987,7 +1003,7 @@ void log_buf_vmcoreinfo_setup(void)
VMCOREINFO_OFFSET(printk_info, seq);
VMCOREINFO_OFFSET(printk_info, ts);
VMCOREINFO_OFFSET(printk_info, text_len);
-
