On (01/20/18 10:49), Steven Rostedt wrote:
[..]
> > printks from console_unlock()->call_console_drivers() are redirected
> > to printk_safe buffer. we need irq_work on that CPU to flush its
> > printk_safe buffer.
>
> So is the issue that we keep triggering this irq work then? Then this
> solution does seem to be one that would work. Because after x amount of
> recursive printks (printk called by printk) it would just stop printing
> them, and end the irq work.
>
> Perhaps what Tejun is seeing is:
>
> printk()
> net_console()
> printk() --> redirected to irq work
>
> <irq work>
> printk
> net_console()
> printk() --> redirected to another irq work
>
> and so on and so on.
it's a bit trickier than that, I think.
we have printk recursion from console drivers. it's redirected to
printk_safe and we queue an IRQ work to flush the buffer
printk
console_unlock
call_console_drivers
net_console
printk
printk_save -> irq_work queue
now console_unlock() enables local IRQs, we have the printk_safe
flush. but printk_safe flush does not call into the console_unlock(),
it uses printk_deferred() version of printk
IRQ work
prink_safe_flush
printk_deferred -> irq_work queue
so we schedule another IRQ work (deferred printk work), which eventually
tries to lock console_sem
IRQ work
wake_up_klogd_work_func()
if (console_trylock())
console_unlock()
if it succeeds then it goes to console_unlock(), where console driver
can cause another printk recursion. but, once again, it will be
redirected to printk_safe buffer first. if it fails then we have either
the original CPU to print out those irq_work messages, which is sort
of bad, or another CPU which already acquired the console_sem and will
print out.
> This solution would need to be tweaked to add a timer to allow only so
> many nested printks in a given time. Otherwise it too would be an issue:
[..]
> > how are we going to distinguish between lockdep splats, for instance,
> > or WARNs from call_console_drivers() -> foo_write(), which are valuable,
> > and kmalloc() print outs, which might be less valuable? are we going to
>
> The problem is that printk causing more printks is extremely dangerous,
> and ANY printk that is caused by a printk is of equal value, whether it
> is a console driver running out of memory or a lockdep splat. And
> the chances of having two hit at the same time is extremely low.
so.... fix the console drivers ;)
just kidding. ok...
the problem is that we flush printk_safe right when console_unlock() printing
loop enables local IRQs via printk_safe_exit_irqrestore() [given that IRQs
were enabled in the first place when the CPU went to console_unlock()].
this forces that CPU to loop in console_unlock() as long as we have
printk-s coming from call_console_drivers(). but we probably can postpone
printk_safe flush. basically, we can declare a new rule - we don't flush
printk_safe buffer as long as console_sem is locked. because this is how
that printing CPU stuck in the console_unlock() printing loop. printk_safe
buffer is very important when it comes to storing a non-repetitive stuff, like
a lockdep splat, which is a single shot event. but the more repetitive the
message is, like millions of similar kmalloc() dump_stack()-s over and over
again, the less value in it. we should have printk_safe buffer big enough for
important info, like a lockdep splat, but millions of similar kmalloc()
messages are pretty invaluable - one is already enough, we can drop the rest.
and we should not flush new messages while there is a CPU looping in
console_unlock(), because it already has messages to print, which were
log_store()-ed the normal way.
this is where the "postpone thing" jumps in. so how do we postpone printk_safe
flush.
we can't console_trylock()/console_unlock() in printk_safe flush code.
but there is a `console_locked' flag and is_console_locked() function which
tell us if the console_sem is locked. as long as we are in console_unlock()
printing loop that flag is set, even if we enabled local IRQs and printk_safe
flush work arrived. so now printk_safe flush does extra check and does
not flush printk_safe buffer content as long as someone is currently
printing or soon will start printing. but we need to take extra step and
to re-queue flush on CPUs that did postpone it [console_unlock() can
reschedule]. so now we flush only when printing CPU printed all pending
logbuf messages, hit the "console_seq == log_next_seq" and up()
console_sem. this sets a boundary -- no matter how many times during the
current printing loop we called console drivers and how many times those
drivers caused printk recursion, we will flush only SAFE_LOG_BUF_LEN chars.
IOW, what we have now, looks like this:
a) printk_safe is for important stuff, we don't guarantee that a flood
of messages will be preserved.
b) we extend the previously existing "will flush messages later on from
a safer context" and now we also consider console_unlock() printing loop
as unsafe context. so the unsafe context it's not only the one that can
deadlock, but also the one that can lockup CPU in a printing loop because
of recursive printk messages.
so this
printk
console_unlock
{
for (;;) {
call_console_drivers
net_console
printk
printk_save -> irq_work queue
IRQ work
prink_safe_flush
printk_deferred -> log_store()
iret
}
up();
}
// which can never break out, because we can always append new messages
// from prink_safe_flush.
becomes this
printk
console_unlock
{
for (;;) {
call_console_drivers
net_console
printk
printk_save -> irq_work queue
}
up();
IRQ work
prink_safe_flush
printk_deferred -> log_store()
iret
}
something completely untested, sketchy and ugly.
---
kernel/printk/internal.h | 2 ++
kernel/printk/printk.c | 1 +
kernel/printk/printk_safe.c | 37 +++++++++++++++++++++++++++++++++++--
3 files changed, 38 insertions(+), 2 deletions(-)
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 2a7d04049af4..e85517818a49 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -30,6 +30,8 @@ __printf(1, 0) int vprintk_func(const char *fmt, va_list
args);
void __printk_safe_enter(void);
void __printk_safe_exit(void);
+void printk_safe_requeue_flushing(void);
+
#define printk_safe_enter_irqsave(flags) \
do { \
local_irq_save(flags); \
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 9cb943c90d98..7aca23e8d7b2 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2428,6 +2428,7 @@ void console_unlock(void)
raw_spin_lock(&logbuf_lock);
retry = console_seq != log_next_seq;
raw_spin_unlock(&logbuf_lock);
+ printk_safe_requeue_flushing();
printk_safe_exit_irqrestore(flags);
if (retry && console_trylock())
diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
index 3e3c2004bb23..45d5b292d7e1 100644
--- a/kernel/printk/printk_safe.c
+++ b/kernel/printk/printk_safe.c
@@ -22,6 +22,7 @@
#include <linux/cpumask.h>
#include <linux/irq_work.h>
#include <linux/printk.h>
+#include <linux/console.h>
#include "internal.h"
@@ -51,6 +52,7 @@ struct printk_safe_seq_buf {
atomic_t message_lost;
struct irq_work work; /* IRQ work that flushes the buffer */
unsigned char buffer[SAFE_LOG_BUF_LEN];
+ bool need_requeue;
};
static DEFINE_PER_CPU(struct printk_safe_seq_buf, safe_print_seq);
@@ -196,6 +198,7 @@ static void __printk_safe_flush(struct irq_work *work)
size_t len;
int i;
+ s->need_requeue = false;
/*
* The lock has two functions. First, one reader has to flush all
* available message to make the lockless synchronization with
@@ -243,6 +246,36 @@ static void __printk_safe_flush(struct irq_work *work)
raw_spin_unlock_irqrestore(&read_lock, flags);
}
+/* NMI buffers are always flushed */
+static void flush_nmi_buffer(struct irq_work *work)
+{
+ __printk_safe_flush(work);
+}
+
+/* printk_safe buffers flushing, on the contrary, can be postponed */
+static void flush_printk_safe_buffer(struct irq_work *work)
+{
+ struct printk_safe_seq_buf *s =
+ container_of(work, struct printk_safe_seq_buf, work);
+
+ if (is_console_locked()) {
+ s->need_requeue = true;
+ return;
+ }
+
+ __printk_safe_flush(work);
+}
+
+void printk_safe_requeue_flushing(void)
+{
+ int cpu;
+
+ for_each_possible_cpu(cpu) {
+ if (per_cpu(safe_print_seq, cpu).need_requeue)
+ queue_flush_work(&per_cpu(safe_print_seq, cpu));
+ }
+}
+
/**
* printk_safe_flush - flush all per-cpu nmi buffers.
*
@@ -387,11 +420,11 @@ void __init printk_safe_init(void)
struct printk_safe_seq_buf *s;
s = &per_cpu(safe_print_seq, cpu);
- init_irq_work(&s->work, __printk_safe_flush);
+ init_irq_work(&s->work, flush_printk_safe_buffer);
#ifdef CONFIG_PRINTK_NMI
s = &per_cpu(nmi_print_seq, cpu);
- init_irq_work(&s->work, __printk_safe_flush);
+ init_irq_work(&s->work, flush_nmi_buffer);
#endif
}
---
> > lose all of them now? then we can do a much simpler thing - steal one
> > bit from `printk_context' and use if for a new PRINTK_NOOP_CONTEXT, which
> > will be set around call_console_drivers(). vprintk_func() would redirect
> > printks to vprintk_noop(fmt, args), which will do nothing.
>
> Not sure what you mean here. Have some pseudo code to demonstrate with?
sure, I meant that if we want to disable printk recursion from
call_console_drivers(), then we can add another printk_safe section, say
printk_noop_begin()/printk_noop_end(), which would set a PRINTK_NOOP
bit of `printk_context', so when we have printk() under PRINTK_NOOP
then vprintk_func() goes to a special vprintk_noop(fmt, args), which
simply drops the message [does not store any in the per-cpu printk
safe buffer, so we don't flush it and don't add new messages to the
logbuf]. and we annotate call_console_drivers() as a pintk_noop
function. but that a no-brainer and I'd prefer to have another solution.
-ss
