lkml.org 
[lkml]   [2018]   [Apr]   [24]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [RFC][PATCH] printk: do not call console drivers from printk_safe context
On (04/24/18 10:51), Steven Rostedt wrote:
[..]
> > console_lock_spinning_enable();
> >
> > + __printk_safe_exit();
> > stop_critical_timings(); /* don't trace print latency */
> > call_console_drivers(ext_text, ext_len, text, len);
> > start_critical_timings();
> > + __printk_safe_enter();
> >
>
> OK, I'm still confused (It's been that kind of week)

No worries, I'm here to help.
The email is, once again, a bit long, but hey at least I'm using
capitals now ;)

> So, if we do this, and the consoles do a printk(), doesn't that fill
> the logbuf?

Yes. It's been this way for many years, and, in fact, even with
printk_safe() we still add concole_drivers->printk() messages to
the logbuf ASAP, which mostly happens while the printing CPU is
still in console_unlock() loop [see #flushing below].

> And then the loop this is in will just continue to perform that loop?

Yes. And it's the same even with printk_safe(). Except that
printk_safe() costs us 2 extra IRQ works on that CPU.

In short, what printk_safe() does:

a) protects us from deadlocking on logbuf spin_lock

E.g.
vprintk_emit()
{
raw_spin_lock(&logbuf_lock);
vscnprintf(text, sizeof(textbuf), fmt, args)
: WARN_ONCE(1, "Unsupported flags modifier....)
: printk()
: vprintk_emit()
: raw_spin_lock(&logbuf_lock); <<<<<<<
raw_spin_unlock(&logbuf_lock);
}

b) protects us from deadlocking on console_sem (for example, console_sem
->lock spin_lock)

E.g.
console_unlock()
{
for (;;) {
if (console_seq == log_next_seq)
break;
}

up()
: raw_spin_lock_irqsave(&sem->lock, flags);
: printk()
: vprintk_emit()
: if (console_trylock_spinning())
: console_trylock()
: down_trylock()
: raw_spin_lock_irqsave(&sem->lock, flags); <<<<<<<
}


c) protects us from deadlocking on console_sem_owner spin_lock
Basically, the same as (a) - deadlock on spin_lock, but at the moment
I'd say a rather theoretical case.

d) protects us from deadlocking on _some_ external locks. For example,
scheduler ->pi_lock lock


> That is, we have:
>
> for (;;) {
> if (console_seq == log_next_seq)
> break;
> console_seq++;
> call_console_drives() {
> printk() {
> log_next_seq++;
> }
> }
> }
>
> That looks like an infinite loop to me.

Correct, this is how it works. And I think we need to preserve that
"console drivers can add messages to the logbuf" and to avoid any
interference [and by interference I mean a deliberate message loss]
with the messages. I have provided some links [in another email] to
support that claim, let me know.


I'd love to see real backtraces/logs when we actually have that
infinite loop.

> Whereas the printk_safe keeps from adding to the logbuf?

#flushing

printk_safe() does not keep console drivers from adding new messages
to the logbuf. We flush [move messages to the logbuf] printk_safe()
per-CPU buffer the moment we enable local IRQ on that CPU: which is,
basically, right after call_console_drivers():

for (;;) {
printk_safe_enter_irqsave(flags);
raw_spin_lock(&logbuf_lock);

if (console_seq == log_next_seq)
break;
console_seq++;
raw_spin_unlock(&logbuf_lock);

call_console_drives() {
printk()
printk_safe_log_store() ::
irq_work_queue() ::
}

printk_safe_exit_irqrestore(flags); ::

<< IRQ >>
printk_safe_flush_buffer()
printk_deferred()
log_store() << log_next_seq++
irq_work_queue()
}

In it's current form printk_safe() is redundant here.

-ss

\
 
 \ /
  Last update: 2018-04-25 04:00    [W:0.088 / U:0.056 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site