console_trylock, called from within printk, can be called from pretty
much anywhere. Including try_to_wake_up. Note that this isn't common,
usually the box is in pretty bad shape at that point already. But it
really doesn't help when then lockdep jumps in and spams the logs,
potentially obscuring the real backtrace we're really interested in.
One case I've seen (slightly simplified backtrace):
Call Trace:
<IRQ>
console_trylock+0xe/0x60
vprintk_emit+0xf1/0x320
printk+0x4d/0x69
__warn_printk+0x46/0x90
native_smp_send_reschedule+0x2f/0x40
check_preempt_curr+0x81/0xa0
ttwu_do_wakeup+0x14/0x220
try_to_wake_up+0x218/0x5f0
pollwake+0x6f/0x90
credit_entropy_bits+0x204/0x310
add_interrupt_randomness+0x18f/0x210
handle_irq+0x67/0x160
do_IRQ+0x5e/0x130
common_interrupt+0xf/0xf
</IRQ>
This alone isn't a problem, but the spinlock in the semaphore is also
still held while waking up waiters (up() -> __up() -> try_to_wake_up()
callchain), which then closes the runqueue vs. semaphore.lock loop,
and upsets lockdep, which issues a circular locking splat to dmesg.
Worse it upsets developers, since we don't want to spam dmesg with
clutter when the machine is dying already.
This is fix attempt number 3, we've already tried to:
- make the console_trylock trylock also the spinlock. This works in
the limited case of the console_lock use-case, but doesn't fix the
same semaphore.lock acquisition in the up() path in console_unlock,
which we can't avoid with a trylock.
- move the wake_up_process in up() out from under the semaphore.lock
spinlock critical section. Again this works for the limited case of
the console_lock, and does fully break the cycle for this lock.
Unfortunately there's still plenty of scheduler related locks that
wake_up_process needs, so the loop is still there, just with a few
less locks involved.
Hence now third attempt, trying to fix this by using printk_deferred()
instead of the normal printk that WARN() uses.
native_smp_send_reschedule is only called from scheduler related code,
which has to use printk_deferred due to this locking recursion, so
this seems consistent.
It has the unfortunate downside that we're losing the backtrace though
(I didn't find a printk_deferred version of WARN, and I'm not sure
it's a bright idea to dump that much using printk_deferred.)
Keeping all the people from the console_lock/printk related attempts
on cc as fyi.
Note: We can only hit this in our CI, with a very low reproduction
rate. And right now the lockdep splat and a few other things crowd out
what actually happens in the little bit of dmesg we recover, so no
idea yet why exactly we're hitting that WARN().
Signed-off-by: Daniel Vetter <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Will Deacon <[email protected]>
Cc: Petr Mladek <[email protected]>
Cc: Sergey Senozhatsky <[email protected]>
Cc: Steven Rostedt <[email protected]>
Cc: Daniel Vetter <[email protected]>
Cc: John Ogness <[email protected]>
Cc: [email protected]
Cc: Nicolai Stange <[email protected]>
Cc: Thomas Gleixner <[email protected]>
---
arch/x86/kernel/smp.c | 3 ++-
1 file changed, 2 insertions(+), 1 deletion(-)
diff --git a/arch/x86/kernel/smp.c b/arch/x86/kernel/smp.c
index 04adc8d60aed..f19782786669 100644
--- a/arch/x86/kernel/smp.c
+++ b/arch/x86/kernel/smp.c
@@ -125,7 +125,8 @@ static bool smp_no_nmi_ipi = false;
static void native_smp_send_reschedule(int cpu)
{
if (unlikely(cpu_is_offline(cpu))) {
- WARN(1, "sched: Unexpected reschedule of offline CPU#%d!\n", cpu);
+ printk_deferred(KERN_WARNING
+ "sched: Unexpected reschedule of offline CPU#%d!\n", cpu);
return;
}
apic->send_IPI(cpu, RESCHEDULE_VECTOR);
--
2.20.1
On (05/07/19 19:33), Daniel Vetter wrote:
[..]
> - make the console_trylock trylock also the spinlock. This works in
> the limited case of the console_lock use-case, but doesn't fix the
> same semaphore.lock acquisition in the up() path in console_unlock,
> which we can't avoid with a trylock.
>
> - move the wake_up_process in up() out from under the semaphore.lock
> spinlock critical section. Again this works for the limited case of
> the console_lock, and does fully break the cycle for this lock.
> Unfortunately there's still plenty of scheduler related locks that
> wake_up_process needs, so the loop is still there, just with a few
> less locks involved.
>
> Hence now third attempt, trying to fix this by using printk_deferred()
> instead of the normal printk that WARN() uses.
> native_smp_send_reschedule is only called from scheduler related code,
> which has to use printk_deferred due to this locking recursion, so
> this seems consistent.
>
> It has the unfortunate downside that we're losing the backtrace though
> (I didn't find a printk_deferred version of WARN, and I'm not sure
> it's a bright idea to dump that much using printk_deferred.)
I'm catching up with the emails now (was offline for almost 2 weeks),
so I haven't seen [yet] all of the previous patches/discussions.
[..]
> static void native_smp_send_reschedule(int cpu)
> {
> if (unlikely(cpu_is_offline(cpu))) {
> - WARN(1, "sched: Unexpected reschedule of offline CPU#%d!\n", cpu);
> + printk_deferred(KERN_WARNING
> + "sched: Unexpected reschedule of offline CPU#%d!\n", cpu);
> return;
> }
> apic->send_IPI(cpu, RESCHEDULE_VECTOR);
Hmm,
One thing to notice here is that the CPU in question is offline-ed,
and printk_deferred() is a per-CPU type of deferred printk(). So the
following thing
__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
might not print anything at all. In this particular case we always
need another CPU to do console_unlock(), since this_cpu() is not
really expected to do wake_up_klogd_work_func()->console_unlock().
-ss
On (05/08/19 16:44), Sergey Senozhatsky wrote:
> [..]
> > static void native_smp_send_reschedule(int cpu)
> > {
> > if (unlikely(cpu_is_offline(cpu))) {
> > - WARN(1, "sched: Unexpected reschedule of offline CPU#%d!\n", cpu);
> > + printk_deferred(KERN_WARNING
> > + "sched: Unexpected reschedule of offline CPU#%d!\n", cpu);
> > return;
> > }
> > apic->send_IPI(cpu, RESCHEDULE_VECTOR);
>
> Hmm,
> One thing to notice here is that the CPU in question is offline-ed,
> and printk_deferred() is a per-CPU type of deferred printk(). So the
> following thing
>
> __this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
> irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
>
> might not print anything at all. In this particular case we always
> need another CPU to do console_unlock(), since this_cpu() is not
> really expected to do wake_up_klogd_work_func()->console_unlock().
D'oh... It's remote CPU which is offline, not this_cpu().
Sorry, my bad!
Any printk-related patch in this area will make PeterZ really-really
angry :)
printk_deferred(), just like prinkt_safe(), depends on IRQ work;
printk_safe(), however, can redirect multiple lines, unlike
printk_deferred(). So if you want to keep the backtrace, you may
do something like
if (unlikely(cpu_is_offline(cpu))) {
printk_safe_enter(...);
WARN(1, "sched: Unexpected reschedule of offline CPU#%d!\n",
cpu);
printk_safe_exit(...);
return;
}
I think, in this case John's reworked-printk can do better than
printk_safe/printk_deferred.
-ss
On Wed, May 8, 2019 at 9:53 AM Sergey Senozhatsky
<[email protected]> wrote:
>
> On (05/08/19 16:44), Sergey Senozhatsky wrote:
> > [..]
> > > static void native_smp_send_reschedule(int cpu)
> > > {
> > > if (unlikely(cpu_is_offline(cpu))) {
> > > - WARN(1, "sched: Unexpected reschedule of offline CPU#%d!\n", cpu);
> > > + printk_deferred(KERN_WARNING
> > > + "sched: Unexpected reschedule of offline CPU#%d!\n", cpu);
> > > return;
> > > }
> > > apic->send_IPI(cpu, RESCHEDULE_VECTOR);
> >
> > Hmm,
> > One thing to notice here is that the CPU in question is offline-ed,
> > and printk_deferred() is a per-CPU type of deferred printk(). So the
> > following thing
> >
> > __this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
> > irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> >
> > might not print anything at all. In this particular case we always
> > need another CPU to do console_unlock(), since this_cpu() is not
> > really expected to do wake_up_klogd_work_func()->console_unlock().
>
> D'oh... It's remote CPU which is offline, not this_cpu().
> Sorry, my bad!
Well I started reading, then freaked out about the WARN_ON in
irq_work_queue_on until I realized that's not the one we're calling
either :-)
> Any printk-related patch in this area will make PeterZ really-really
> angry :)
Hm any more context for someone with no clue about this? Just that the
dependencies are already terribly complex and it's not going to get
better, or something more specific?
> printk_deferred(), just like prinkt_safe(), depends on IRQ work;
> printk_safe(), however, can redirect multiple lines, unlike
> printk_deferred(). So if you want to keep the backtrace, you may
> do something like
>
> if (unlikely(cpu_is_offline(cpu))) {
> printk_safe_enter(...);
> WARN(1, "sched: Unexpected reschedule of offline CPU#%d!\n",
> cpu);
> printk_safe_exit(...);
> return;
> }
>
> I think, in this case John's reworked-printk can do better than
> printk_safe/printk_deferred.
Hm I think this is what Petr was suggesting, but somehow I didn't find
the printk_safe_* functions and didn't connect the dots. Needs the
_irqsave variants I guess, I'll respin a v2 of this.
-Daniel
--
Daniel Vetter
Software Engineer, Intel Corporation
+41 (0) 79 365 57 48 - http://blog.ffwll.ch
On Wed, May 8, 2019 at 9:53 AM Sergey Senozhatsky
<[email protected]> wrote:
>
> On (05/08/19 16:44), Sergey Senozhatsky wrote:
> > [..]
> > > static void native_smp_send_reschedule(int cpu)
> > > {
> > > if (unlikely(cpu_is_offline(cpu))) {
> > > - WARN(1, "sched: Unexpected reschedule of offline CPU#%d!\n", cpu);
> > > + printk_deferred(KERN_WARNING
> > > + "sched: Unexpected reschedule of offline CPU#%d!\n", cpu);
> > > return;
> > > }
> > > apic->send_IPI(cpu, RESCHEDULE_VECTOR);
> >
> > Hmm,
> > One thing to notice here is that the CPU in question is offline-ed,
> > and printk_deferred() is a per-CPU type of deferred printk(). So the
> > following thing
> >
> > __this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
> > irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> >
> > might not print anything at all. In this particular case we always
> > need another CPU to do console_unlock(), since this_cpu() is not
> > really expected to do wake_up_klogd_work_func()->console_unlock().
>
> D'oh... It's remote CPU which is offline, not this_cpu().
> Sorry, my bad!
>
> Any printk-related patch in this area will make PeterZ really-really
> angry :)
>
> printk_deferred(), just like prinkt_safe(), depends on IRQ work;
> printk_safe(), however, can redirect multiple lines, unlike
> printk_deferred(). So if you want to keep the backtrace, you may
> do something like
>
> if (unlikely(cpu_is_offline(cpu))) {
> printk_safe_enter(...);
> WARN(1, "sched: Unexpected reschedule of offline CPU#%d!\n",
> cpu);
> printk_safe_exit(...);
> return;
> }
>
> I think, in this case John's reworked-printk can do better than
> printk_safe/printk_deferred.
[coffee slowly kicking in it seems]
Locking at __up_console_sem in printk.c, we already do this. I get a
bit a feeling that the 2nd attempt in this saga (pulling the
wake_up_process out from under semaphore.lock spinlock of the
console_lock) is all we really need, since the more direct recursion
that Petr pointed out is already handled with printk_safe_enter/exit
around the up().
https://patchwork.kernel.org/patch/10930673/ for reference that
approach, in case it's lost in your inbox.
Cheers, Daniel
--
Daniel Vetter
Software Engineer, Intel Corporation
+41 (0) 79 365 57 48 - http://blog.ffwll.ch
On Wed, May 8, 2019 at 9:44 AM Sergey Senozhatsky
<[email protected]> wrote:
>
> On (05/07/19 19:33), Daniel Vetter wrote:
> [..]
> > - make the console_trylock trylock also the spinlock. This works in
> > the limited case of the console_lock use-case, but doesn't fix the
> > same semaphore.lock acquisition in the up() path in console_unlock,
> > which we can't avoid with a trylock.
> >
> > - move the wake_up_process in up() out from under the semaphore.lock
> > spinlock critical section. Again this works for the limited case of
> > the console_lock, and does fully break the cycle for this lock.
> > Unfortunately there's still plenty of scheduler related locks that
> > wake_up_process needs, so the loop is still there, just with a few
> > less locks involved.
> >
> > Hence now third attempt, trying to fix this by using printk_deferred()
> > instead of the normal printk that WARN() uses.
> > native_smp_send_reschedule is only called from scheduler related code,
> > which has to use printk_deferred due to this locking recursion, so
> > this seems consistent.
> >
> > It has the unfortunate downside that we're losing the backtrace though
> > (I didn't find a printk_deferred version of WARN, and I'm not sure
> > it's a bright idea to dump that much using printk_deferred.)
>
> I'm catching up with the emails now (was offline for almost 2 weeks),
> so I haven't seen [yet] all of the previous patches/discussions.
>
> [..]
> > static void native_smp_send_reschedule(int cpu)
> > {
> > if (unlikely(cpu_is_offline(cpu))) {
> > - WARN(1, "sched: Unexpected reschedule of offline CPU#%d!\n", cpu);
> > + printk_deferred(KERN_WARNING
> > + "sched: Unexpected reschedule of offline CPU#%d!\n", cpu);
> > return;
> > }
> > apic->send_IPI(cpu, RESCHEDULE_VECTOR);
>
> Hmm,
> One thing to notice here is that the CPU in question is offline-ed,
> and printk_deferred() is a per-CPU type of deferred printk(). So the
> following thing
>
> __this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
> irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
>
> might not print anything at all. In this particular case we always
> need another CPU to do console_unlock(), since this_cpu() is not
> really expected to do wake_up_klogd_work_func()->console_unlock().
Hm right, I was happy enough when Petr pointed out the printk_deferred
infrastructure that I didn't look too deeply into how it works. From a
quick loo
--
Daniel Vetter
Software Engineer, Intel Corporation
+41 (0) 79 365 57 48 - http://blog.ffwll.ch
On (05/08/19 10:06), Daniel Vetter wrote:
[..]
> > Any printk-related patch in this area will make PeterZ really-really
> > angry :)
>
> Hm any more context for someone with no clue about this? Just that the
> dependencies are already terribly complex and it's not going to get
> better, or something more specific?
The main problem is that it's a deferred error-reporting, so such
a report has chances to never be reported. It's not like 'normal'
printk() is always guaranteed to immediately start printing; sometimes
it will, sometimes it won't, and sometimes it never will, for instance
when console_sem was locked by offline-ed CPU.
An example of PeterZ's opinion on printk_deferred()
/* message ID: [email protected] */
| No, printk_deferred() is a disease, it needs to be eradicated, not
| spread around.
> > printk_deferred(), just like prinkt_safe(), depends on IRQ work;
> > printk_safe(), however, can redirect multiple lines, unlike
> > printk_deferred(). So if you want to keep the backtrace, you may
> > do something like
> >
> > if (unlikely(cpu_is_offline(cpu))) {
> > printk_safe_enter(...);
> > WARN(1, "sched: Unexpected reschedule of offline CPU#%d!\n",
> > cpu);
> > printk_safe_exit(...);
> > return;
> > }
> >
> > I think, in this case John's reworked-printk can do better than
> > printk_safe/printk_deferred.
>
> Hm I think this is what Petr was suggesting, but somehow I didn't find
> the printk_safe_* functions and didn't connect the dots.
These are in kernel/printk/printk_safe.c as of now.
> Needs the _irqsave variants I guess, I'll respin a v2 of this.
Let's wait a bit before respin.
-ss