Hi,
I'm debugging a problem with a softirq that gets stuck for a long time,
so I wrote this patch to help find out what's going wrong.
I actually think it can be useful in general as well, see for example
http://www.kerneloops.org/search.php?search=__do_softirq&btnG=Function+Search
..and these cases are virtually impossible to debug since we don't know
anything about *what* it was that got stuck. (The NMI watchdog could
help, though.)
The patch is #ifdef-ugly, I know... Suggestions are welcome.
Vegard
From: Vegard Nossum <[email protected]>
Date: Sun, 22 Jun 2008 14:12:31 +0200
Subject: [PATCH] softirq softlockup debugging
>From the Kconfig: If a softlockup happens in a softirq, the softlockup
stack trace is utterly unhelpful; it will only show the stack up to
__do_softirq(), since this is where interrupts are reenabled.
This patch adds a line to the output of the softlockup report which
contains the address of the function that was last scheduled to run in
a softirq.
Signed-off-by: Vegard Nossum <[email protected]>
---
include/linux/interrupt.h | 3 +++
kernel/softirq.c | 13 +++++++++++++
kernel/softlockup.c | 6 ++++++
lib/Kconfig.debug | 10 ++++++++++
4 files changed, 32 insertions(+), 0 deletions(-)
diff --git a/include/linux/interrupt.h b/include/linux/interrupt.h
index f1fc747..97d47cf 100644
--- a/include/linux/interrupt.h
+++ b/include/linux/interrupt.h
@@ -296,6 +296,9 @@ extern void softirq_init(void);
extern void raise_softirq_irqoff(unsigned int nr);
extern void raise_softirq(unsigned int nr);
+#ifdef CONFIG_SOFTLOCKUP_SOFTIRQ_DEBUG
+extern void *get_last_softirq_action(int cpu);
+#endif
/* Tasklets --- multithreaded analogue of BHs.
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 36e0617..b49899a 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -196,6 +196,15 @@ void local_bh_enable_ip(unsigned long ip)
}
EXPORT_SYMBOL(local_bh_enable_ip);
+#ifdef CONFIG_SOFTLOCKUP_SOFTIRQ_DEBUG
+static DEFINE_PER_CPU(void *, last_softirq_action);
+
+void *get_last_softirq_action(int cpu)
+{
+ return per_cpu(last_softirq_action, cpu);
+}
+#endif
+
/*
* We restart softirq processing MAX_SOFTIRQ_RESTART times,
* and we fall back to softirqd after that.
@@ -231,6 +240,10 @@ restart:
do {
if (pending & 1) {
+#ifdef CONFIG_SOFTLOCKUP_SOFTIRQ_DEBUG
+ per_cpu(last_softirq_action, cpu) = h->action;
+#endif
+
h->action(h);
rcu_bh_qsctr_inc(cpu);
}
diff --git a/kernel/softlockup.c b/kernel/softlockup.c
index c828c23..2bf4fa1 100644
--- a/kernel/softlockup.c
+++ b/kernel/softlockup.c
@@ -10,8 +10,10 @@
#include <linux/cpu.h>
#include <linux/nmi.h>
#include <linux/init.h>
+#include <linux/interrupt.h>
#include <linux/delay.h>
#include <linux/freezer.h>
+#include <linux/kallsyms.h>
#include <linux/kthread.h>
#include <linux/notifier.h>
#include <linux/module.h>
@@ -120,6 +122,10 @@ void softlockup_tick(void)
printk(KERN_ERR "BUG: soft lockup - CPU#%d stuck for %lus! [%s:%d]\n",
this_cpu, now - touch_timestamp,
current->comm, task_pid_nr(current));
+#ifdef CONFIG_SOFTLOCKUP_SOFTIRQ_DEBUG
+ print_symbol(KERN_ERR "Last softirq was %s\n",
+ (unsigned long) get_last_softirq_action(this_cpu));
+#endif
if (regs)
show_regs(regs);
else
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index d2099f4..19a7dfc 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -159,6 +159,16 @@ config DETECT_SOFTLOCKUP
can be detected via the NMI-watchdog, on platforms that
support it.)
+config SOFTLOCKUP_SOFTIRQ_DEBUG
+ bool "Debug softirq lockups"
+ depends on DETECT_SOFTLOCKUP
+ default n
+ help
+ If a softlockup happens in a softirq, the softlockup
+ stack trace is utterly unhelpful; it will only show the
+ stack up to __do_softirq(), since this is where interrupts
+ are reenabled.
+
config SCHED_DEBUG
bool "Collect scheduler debugging info"
depends on DEBUG_KERNEL && PROC_FS
--
1.5.4.1
Vegard Nossum wrote:
Hi
I like the general idea a lot; some comments below on the patch
>
> diff --git a/include/linux/interrupt.h b/include/linux/interrupt.h
> index f1fc747..97d47cf 100644
> --- a/include/linux/interrupt.h
> +++ b/include/linux/interrupt.h
> @@ -296,6 +296,9 @@ extern void softirq_init(void);
> extern void raise_softirq_irqoff(unsigned int nr);
> extern void raise_softirq(unsigned int nr);
>
> +#ifdef CONFIG_SOFTLOCKUP_SOFTIRQ_DEBUG
> +extern void *get_last_softirq_action(int cpu);
> +#endif
you don't need to ifdef prototypes....
(there's only one exception: if the prototype uses types that are ifdef'd themselves, but that's not here)
In general... I don't like that this is a config option. I mean... is there a really strong
reason why this shouldn't just always be there?
On Sun, Jun 22, 2008 at 11:18 PM, Arjan van de Ven
<[email protected]> wrote:
> Vegard Nossum wrote:
>
> Hi
>
> I like the general idea a lot; some comments below on the patch
Thanks.
>> diff --git a/include/linux/interrupt.h b/include/linux/interrupt.h
>> index f1fc747..97d47cf 100644
>> --- a/include/linux/interrupt.h
>> +++ b/include/linux/interrupt.h
>> @@ -296,6 +296,9 @@ extern void softirq_init(void);
>> extern void raise_softirq_irqoff(unsigned int nr);
>> extern void raise_softirq(unsigned int nr);
>> +#ifdef CONFIG_SOFTLOCKUP_SOFTIRQ_DEBUG
>> +extern void *get_last_softirq_action(int cpu);
>> +#endif
>
> you don't need to ifdef prototypes....
> (there's only one exception: if the prototype uses types that are ifdef'd
> themselves, but that's not here)
>
>
> In general... I don't like that this is a config option. I mean... is there
> a really strong
> reason why this shouldn't just always be there?
I thought it would be unacceptable to always have it there given the
performance hit. It's just bound to show up in some benchmark that
some guy runs in the next couple of releases, isn't it? :-D
(Or maybe it isn't that bad. I honestly have no idea. It should be
just a single "store", but if I understood correctly, this loop is
also frequently run.)
Also, as spotted by Johannes Weiner, this is only an issue for
handlers where interrupts are disabled inside the handler (because the
handler itself is run with irqs enabled). Still, it would be nice to
be able to catch those few warnings of this kind that showed up in
kerneloops.org and for which we have no idea what happened or whether
it has been fixed.
Do you think I should resubmit without the CONFIG? (Does anybody else
have an opinion?)
Thank you so much for looking :-)
Vegard
--
"The animistic metaphor of the bug that maliciously sneaked in while
the programmer was not looking is intellectually dishonest as it
disguises that the error is the programmer's own creation."
-- E. W. Dijkstra, EWD1036
Hi Vegard,
Vegard Nossum <[email protected]> writes:
> Hi,
>
> I'm debugging a problem with a softirq that gets stuck for a long time,
> so I wrote this patch to help find out what's going wrong.
>
> I actually think it can be useful in general as well, see for example
> http://www.kerneloops.org/search.php?search=__do_softirq&btnG=Function+Search
>
> ..and these cases are virtually impossible to debug since we don't know
> anything about *what* it was that got stuck. (The NMI watchdog could
> help, though.)
>
> The patch is #ifdef-ugly, I know... Suggestions are welcome.
>
>
> Vegard
>
>
> From: Vegard Nossum <[email protected]>
> Date: Sun, 22 Jun 2008 14:12:31 +0200
> Subject: [PATCH] softirq softlockup debugging
>
>>From the Kconfig: If a softlockup happens in a softirq, the softlockup
> stack trace is utterly unhelpful; it will only show the stack up to
> __do_softirq(), since this is where interrupts are reenabled.
After more staring at the code in question, I think that the approach is
not correct (or I didn't understand it, which is not unlikely).
I hunted down the address of the traces from kerneloops.org
(__do_softirq+0x6d) on a kernel image with a fedora config and it's at
the local_irq_enable() right after the restart:label in __do_softirq().
So if the softirq handler had disabled interrupts, the softlockup would
have been detected still within the handler (when it reenables irqs and
the timer irq runs) and the stackframe should be there.
do_softirq()
local_irq_save() 1)
local_softirq_pending()
__do_softirq()
restart: 2)
local_irq_enable() 3)
run a handler
local_irq_disable() 4)
jnz restart
So the lockup must be caused somewhere
between 1) and 3)
or
between 4) and 3) [when we jump back]
These functions are in the path and possible candidates for causing it:
- local_softirq_pending()
- account_system_vtime()
- __local_bh_disable()
- trace_softirq_enter()
- smp_processor_id()
- set_softirq_pending()
What do you think? You said you actually used your patch already for
debugging lockups in softirq handlers, so it confuses me why the
stackframe of the handler was no longer present.
Hannes
On 6/24/08, Johannes Weiner <[email protected]> wrote:
> After more staring at the code in question, I think that the approach is
> not correct (or I didn't understand it, which is not unlikely).
>
> I hunted down the address of the traces from kerneloops.org
> (__do_softirq+0x6d) on a kernel image with a fedora config and it's at
> the local_irq_enable() right after the restart:label in __do_softirq().
>
Are you quite sure? I didn't use the fedora image, but I compiled with
the fedora config and got a function size for __do_softirq that was
exactly equal to some of the reports. And there, the EIP pointed to
the second "pop" instruction after calling... oh, true.
local_irq_enable(). And those pops come from calling into paravirt
ops.
Right, I fully agree.
> So if the softirq handler had disabled interrupts, the softlockup would
> have been detected still within the handler (when it reenables irqs and
> the timer irq runs) and the stackframe should be there.
>
> do_softirq()
> local_irq_save() 1)
> local_softirq_pending()
> __do_softirq()
> restart: 2)
> local_irq_enable() 3)
> run a handler
> local_irq_disable() 4)
> jnz restart
>
> So the lockup must be caused somewhere
> between 1) and 3)
> or
> between 4) and 3) [when we jump back]
>
> These functions are in the path and possible candidates for causing it:
>
> - local_softirq_pending()
> - account_system_vtime()
> - __local_bh_disable()
> - trace_softirq_enter()
> - smp_processor_id()
> - set_softirq_pending()
>
> What do you think? You said you actually used your patch already for
> debugging lockups in softirq handlers, so it confuses me why the
> stackframe of the handler was no longer present.
What didn't make sense to me when first looking at the oops reports
was that there was nowhere inside __do_softirq() that could actually
lock up. As far as I can see, there is no infinite (or very
long-running) loop in there, so I concluded (probably wrongly) that it
must be the handler; it was the only logical explanation I could find.
I believe that the functions you listed all run in constant time, but
maybe we should check it.
It also seems that the timer interrupt (where softlockup detection
kicks in) has a small delay after irqs are re-enabled before it
actually interrupts the CPU. Can you post a disassembly of
__do_softirq() where you pinpoint the exact instruction that was
interrupted, e.g. in this case __do_softirq+0x6d? Again, for me, this
was a pop %ebx or so, which doesn't change interruptibility, so maybe
I simply had the wrong disassembly.
(Actually, I didn't use the patch for debugging yet; I ran with the
patch applied, but I was unable to reproduce the lockup. But KOSAKI
Motohiro found some theoretical ABBA deadlock in cpusets vs. cpu
hotplug that could be the reason for it.)
Thanks for the analysis; I am very curious to see which code that
locks up and how I failed to notice where it was.
Vegard
--
"The animistic metaphor of the bug that maliciously sneaked in while
the programmer was not looking is intellectually dishonest as it
disguises that the error is the programmer's own creation."
-- E. W. Dijkstra, EWD1036
* Vegard Nossum <[email protected]> wrote:
> Hi,
>
> I'm debugging a problem with a softirq that gets stuck for a long
> time, so I wrote this patch to help find out what's going wrong.
>
> I actually think it can be useful in general as well, see for example
> http://www.kerneloops.org/search.php?search=__do_softirq&btnG=Function+Search
>
> ..and these cases are virtually impossible to debug since we don't
> know anything about *what* it was that got stuck. (The NMI watchdog
> could help, though.)
>
> The patch is #ifdef-ugly, I know... Suggestions are welcome.
i've applied it to tip/core/softlockup to give it some testing. (It
needed a manual merge due to changes pending in that topic already)
Ingo
Hi,
"Vegard Nossum" <[email protected]> writes:
> On 6/24/08, Johannes Weiner <[email protected]> wrote:
>> After more staring at the code in question, I think that the approach is
>> not correct (or I didn't understand it, which is not unlikely).
>>
>> I hunted down the address of the traces from kerneloops.org
>> (__do_softirq+0x6d) on a kernel image with a fedora config and it's at
>> the local_irq_enable() right after the restart:label in __do_softirq().
>>
>
> Are you quite sure? I didn't use the fedora image, but I compiled with
> the fedora config and got a function size for __do_softirq that was
> exactly equal to some of the reports. And there, the EIP pointed to
> the second "pop" instruction after calling... oh, true.
> local_irq_enable(). And those pops come from calling into paravirt
> ops.
>
> Right, I fully agree.
>
>> So if the softirq handler had disabled interrupts, the softlockup would
>> have been detected still within the handler (when it reenables irqs and
>> the timer irq runs) and the stackframe should be there.
>>
>> do_softirq()
>> local_irq_save() 1)
>> local_softirq_pending()
>> __do_softirq()
>> restart: 2)
>> local_irq_enable() 3)
>> run a handler
>> local_irq_disable() 4)
>> jnz restart
>>
>> So the lockup must be caused somewhere
>> between 1) and 3)
>> or
>> between 4) and 3) [when we jump back]
>>
>> These functions are in the path and possible candidates for causing it:
>>
>> - local_softirq_pending()
>> - account_system_vtime()
>> - __local_bh_disable()
>> - trace_softirq_enter()
>> - smp_processor_id()
>> - set_softirq_pending()
>>
>> What do you think? You said you actually used your patch already for
>> debugging lockups in softirq handlers, so it confuses me why the
>> stackframe of the handler was no longer present.
>
> What didn't make sense to me when first looking at the oops reports
> was that there was nowhere inside __do_softirq() that could actually
> lock up. As far as I can see, there is no infinite (or very
> long-running) loop in there, so I concluded (probably wrongly) that it
> must be the handler; it was the only logical explanation I could find.
> I believe that the functions you listed all run in constant time, but
> maybe we should check it.
>
> It also seems that the timer interrupt (where softlockup detection
> kicks in) has a small delay after irqs are re-enabled before it
> actually interrupts the CPU. Can you post a disassembly of
> __do_softirq() where you pinpoint the exact instruction that was
> interrupted, e.g. in this case __do_softirq+0x6d? Again, for me, this
> was a pop %ebx or so, which doesn't change interruptibility, so maybe
> I simply had the wrong disassembly.
gdb associated the line to be the asm statement in
include/asm-x86/paravirt.h::raw_local_irq_enable().
And looking by hand with objdump got the second pop, too, just like you,
IIRC (dropped the object file, will have another look at it later).
Hannes