* [PATCH 0/2] irq: detect slow IRQ handlers
@ 2021-01-12 13:59 Mark Rutland
2021-01-12 13:59 ` [PATCH 1/2] irq: abstract irqaction handler invocation Mark Rutland
` (2 more replies)
0 siblings, 3 replies; 6+ messages in thread
From: Mark Rutland @ 2021-01-12 13:59 UTC (permalink / raw)
To: linux-kernel; +Cc: mark.rutland, maz, paulmck, peterz, tglx
Hi,
While fuzzing arm64 with Syzkaller (under QEMU+KVM) over a number of releases,
I've occasionally seen some ridiculously long stalls (20+ seconds), where it
appears that a CPU is stuck in a hard IRQ context. As this gets detected after
the CPU returns to the interrupted context, it's difficult to identify where
exactly the stall is coming from.
These patches are intended to help tracking this down, with a WARN() if an IRQ
handler takes longer than a given timout (1 second by default), logging the
specific IRQ and handler function. While it's possible to achieve similar with
tracing, it's harder to integrate that into an automated fuzzing setup.
I've been running this for a short while, and haven't yet seen any of the
stalls with this applied, but I've tested with smaller timeout periods in the 1
millisecond range by overloading the host, so I'm confident that the check
works.
Thanks,
Mark.
Mark Rutland (2):
irq: abstract irqaction handler invocation
irq: detect long-running IRQ handlers
kernel/irq/chip.c | 15 +++----------
kernel/irq/handle.c | 4 +---
kernel/irq/internals.h | 57 ++++++++++++++++++++++++++++++++++++++++++++++++++
lib/Kconfig.debug | 15 +++++++++++++
4 files changed, 76 insertions(+), 15 deletions(-)
--
2.11.0
^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCH 1/2] irq: abstract irqaction handler invocation
2021-01-12 13:59 [PATCH 0/2] irq: detect slow IRQ handlers Mark Rutland
@ 2021-01-12 13:59 ` Mark Rutland
2021-01-12 13:59 ` [PATCH 2/2] irq: detect long-running IRQ handlers Mark Rutland
2021-01-13 0:09 ` [PATCH 0/2] irq: detect slow " Paul E. McKenney
2 siblings, 0 replies; 6+ messages in thread
From: Mark Rutland @ 2021-01-12 13:59 UTC (permalink / raw)
To: linux-kernel; +Cc: mark.rutland, maz, paulmck, peterz, tglx
We have a few functions which invoke irqaction handlers, all of which
need to call trace_irq_handler_entry() and trace_irq_handler_exit().
In preparation for adding some additional debug logic to each irqaction
handler invocation, let's factor out this work to a helper.
There should be no functional change as a result of this patch.
Signed-off-by: Mark Rutland <mark.rutland@arm.com>
Cc: Marc Zyngier <maz@kernel.org>
Cc: Paul E. McKenney <paulmck@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
---
kernel/irq/chip.c | 15 +++------------
kernel/irq/handle.c | 4 +---
kernel/irq/internals.h | 28 ++++++++++++++++++++++++++++
3 files changed, 32 insertions(+), 15 deletions(-)
diff --git a/kernel/irq/chip.c b/kernel/irq/chip.c
index 6d89e33fe3aa..ce3f40d881a8 100644
--- a/kernel/irq/chip.c
+++ b/kernel/irq/chip.c
@@ -741,16 +741,13 @@ void handle_fasteoi_nmi(struct irq_desc *desc)
struct irq_chip *chip = irq_desc_get_chip(desc);
struct irqaction *action = desc->action;
unsigned int irq = irq_desc_get_irq(desc);
- irqreturn_t res;
__kstat_incr_irqs_this_cpu(desc);
- trace_irq_handler_entry(irq, action);
/*
* NMIs cannot be shared, there is only one action.
*/
- res = action->handler(irq, action->dev_id);
- trace_irq_handler_exit(irq, action, res);
+ handle_irqaction(irq, action);
if (chip->irq_eoi)
chip->irq_eoi(&desc->irq_data);
@@ -914,7 +911,6 @@ void handle_percpu_devid_irq(struct irq_desc *desc)
struct irq_chip *chip = irq_desc_get_chip(desc);
struct irqaction *action = desc->action;
unsigned int irq = irq_desc_get_irq(desc);
- irqreturn_t res;
/*
* PER CPU interrupts are not serialized. Do not touch
@@ -926,9 +922,7 @@ void handle_percpu_devid_irq(struct irq_desc *desc)
chip->irq_ack(&desc->irq_data);
if (likely(action)) {
- trace_irq_handler_entry(irq, action);
- res = action->handler(irq, raw_cpu_ptr(action->percpu_dev_id));
- trace_irq_handler_exit(irq, action, res);
+ handle_irqaction_percpu_devid(irq, action);
} else {
unsigned int cpu = smp_processor_id();
bool enabled = cpumask_test_cpu(cpu, desc->percpu_enabled);
@@ -957,13 +951,10 @@ void handle_percpu_devid_fasteoi_nmi(struct irq_desc *desc)
struct irq_chip *chip = irq_desc_get_chip(desc);
struct irqaction *action = desc->action;
unsigned int irq = irq_desc_get_irq(desc);
- irqreturn_t res;
__kstat_incr_irqs_this_cpu(desc);
- trace_irq_handler_entry(irq, action);
- res = action->handler(irq, raw_cpu_ptr(action->percpu_dev_id));
- trace_irq_handler_exit(irq, action, res);
+ handle_irqaction_percpu_devid(irq, action);
if (chip->irq_eoi)
chip->irq_eoi(&desc->irq_data);
diff --git a/kernel/irq/handle.c b/kernel/irq/handle.c
index 762a928e18f9..65994befd280 100644
--- a/kernel/irq/handle.c
+++ b/kernel/irq/handle.c
@@ -152,9 +152,7 @@ irqreturn_t __handle_irq_event_percpu(struct irq_desc *desc, unsigned int *flags
!(action->flags & (IRQF_NO_THREAD | IRQF_PERCPU | IRQF_ONESHOT)))
lockdep_hardirq_threaded();
- trace_irq_handler_entry(irq, action);
- res = action->handler(irq, action->dev_id);
- trace_irq_handler_exit(irq, action, res);
+ res = handle_irqaction(irq, action);
if (WARN_ONCE(!irqs_disabled(),"irq %u handler %pS enabled interrupts\n",
irq, action->handler))
diff --git a/kernel/irq/internals.h b/kernel/irq/internals.h
index 54363527feea..70a4694cc891 100644
--- a/kernel/irq/internals.h
+++ b/kernel/irq/internals.h
@@ -11,6 +11,8 @@
#include <linux/pm_runtime.h>
#include <linux/sched/clock.h>
+#include <trace/events/irq.h>
+
#ifdef CONFIG_SPARSE_IRQ
# define IRQ_BITMAP_BITS (NR_IRQS + 8196)
#else
@@ -107,6 +109,32 @@ irqreturn_t __handle_irq_event_percpu(struct irq_desc *desc, unsigned int *flags
irqreturn_t handle_irq_event_percpu(struct irq_desc *desc);
irqreturn_t handle_irq_event(struct irq_desc *desc);
+static inline irqreturn_t __handle_irqaction(unsigned int irq,
+ struct irqaction *action,
+ void *dev_id)
+{
+ irqreturn_t res;
+
+ trace_irq_handler_entry(irq, action);
+ res = action->handler(irq, dev_id);
+ trace_irq_handler_exit(irq, action, res);
+
+ return res;
+}
+
+static inline irqreturn_t handle_irqaction(unsigned int irq,
+ struct irqaction *action)
+{
+ return __handle_irqaction(irq, action, action->dev_id);
+}
+
+static inline irqreturn_t handle_irqaction_percpu_devid(unsigned int irq,
+ struct irqaction *action)
+{
+ return __handle_irqaction(irq, action,
+ raw_cpu_ptr(action->percpu_dev_id));
+}
+
/* Resending of interrupts :*/
int check_irq_resend(struct irq_desc *desc, bool inject);
bool irq_wait_for_poll(struct irq_desc *desc);
--
2.11.0
^ permalink raw reply related [flat|nested] 6+ messages in thread
* [PATCH 2/2] irq: detect long-running IRQ handlers
2021-01-12 13:59 [PATCH 0/2] irq: detect slow IRQ handlers Mark Rutland
2021-01-12 13:59 ` [PATCH 1/2] irq: abstract irqaction handler invocation Mark Rutland
@ 2021-01-12 13:59 ` Mark Rutland
2021-01-13 0:09 ` [PATCH 0/2] irq: detect slow " Paul E. McKenney
2 siblings, 0 replies; 6+ messages in thread
From: Mark Rutland @ 2021-01-12 13:59 UTC (permalink / raw)
To: linux-kernel; +Cc: mark.rutland, maz, paulmck, peterz, tglx
If a hard IRQ handler takes a long time to handle an IRQ, it may cause a
soft lockup or RCU stall, but as this will be detected once the handler
has returned it can be difficult to attribute the delay to the specific
IRQ handler.
It's possible to trace IRQ handlers to diagnose this, but that's not a
great fit for automated testing environments (e.g. fuzzers), where
something like the existing lockup/stall detectors works well.
This patch adds a new stall detector for IRQ handlers, which reports
when handlers took longer than a given timeout value (defaulting to 1
second). This won't detect hung IRQ handlers (which requires an NMI, and
should already be caught by hung task detection on systems with NMIs),
but helps on platforms without NMI or where a periodic watchdog is
undesireable.
Signed-off-by: Mark Rutland <mark.rutland@arm.com>
Cc: Marc Zyngier <maz@kernel.org>
Cc: Paul E. McKenney <paulmck@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
---
kernel/irq/internals.h | 35 ++++++++++++++++++++++++++++++++---
lib/Kconfig.debug | 15 +++++++++++++++
2 files changed, 47 insertions(+), 3 deletions(-)
diff --git a/kernel/irq/internals.h b/kernel/irq/internals.h
index 70a4694cc891..191b6a9d30e2 100644
--- a/kernel/irq/internals.h
+++ b/kernel/irq/internals.h
@@ -6,6 +6,7 @@
* kernel/irq/. Do not even think about using any information outside
* of this file for your non core code.
*/
+#include <linux/bug.h>
#include <linux/irqdesc.h>
#include <linux/kernel_stat.h>
#include <linux/pm_runtime.h>
@@ -122,17 +123,45 @@ static inline irqreturn_t __handle_irqaction(unsigned int irq,
return res;
}
+#ifdef CONFIG_DETECT_SLOW_IRQ_HANDLER
+static inline irqreturn_t __handle_check_irqaction(unsigned int irq,
+ struct irqaction *action,
+ void *dev_id)
+{
+ u64 timeout = CONFIG_IRQ_HANDLER_TIMEOUT_NS;
+ u64 start, end, duration;
+ int res;
+
+ start = local_clock();
+ res = __handle_irqaction(irq, action, dev_id);
+ end = local_clock();
+
+ duration = end - start;
+ WARN(duration > timeout, "IRQ %d handler %ps took %llu ns\n",
+ irq, action->handler, duration);
+
+ return res;
+}
+#else
+static inline irqreturn_t __handle_check_irqaction(unsigned int irq,
+ struct irqaction *action,
+ void *dev_id)
+{
+ return __handle_irqaction(irq, action, dev_id);
+}
+#endif
+
static inline irqreturn_t handle_irqaction(unsigned int irq,
struct irqaction *action)
{
- return __handle_irqaction(irq, action, action->dev_id);
+ return __handle_check_irqaction(irq, action, action->dev_id);
}
static inline irqreturn_t handle_irqaction_percpu_devid(unsigned int irq,
struct irqaction *action)
{
- return __handle_irqaction(irq, action,
- raw_cpu_ptr(action->percpu_dev_id));
+ return __handle_check_irqaction(irq, action,
+ raw_cpu_ptr(action->percpu_dev_id));
}
/* Resending of interrupts :*/
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 5ea0c1773b0a..ea5289518dd6 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -1097,6 +1097,21 @@ config WQ_WATCHDOG
state. This can be configured through kernel parameter
"workqueue.watchdog_thresh" and its sysfs counterpart.
+config DETECT_SLOW_IRQ_HANDLER
+ bool "Detect long-running IRQ handlers"
+ help
+ Say Y here to enable detection of long-running IRQ handlers. When a
+ (hard) IRQ handler returns after a given timeout value (1s by
+ default) a warning will be printed with the name of the handler.
+
+ This can help to identify specific IRQ handlers which are
+ contributing to stalls.
+
+config IRQ_HANDLER_TIMEOUT_NS
+ int "Timeout for long-running IRQ handlers (in nanoseconds)"
+ depends on DETECT_SLOW_IRQ_HANDLER
+ default 1000000000
+
config TEST_LOCKUP
tristate "Test module to generate lockups"
depends on m
--
2.11.0
^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [PATCH 0/2] irq: detect slow IRQ handlers
2021-01-12 13:59 [PATCH 0/2] irq: detect slow IRQ handlers Mark Rutland
2021-01-12 13:59 ` [PATCH 1/2] irq: abstract irqaction handler invocation Mark Rutland
2021-01-12 13:59 ` [PATCH 2/2] irq: detect long-running IRQ handlers Mark Rutland
@ 2021-01-13 0:09 ` Paul E. McKenney
2021-01-13 12:39 ` Mark Rutland
2 siblings, 1 reply; 6+ messages in thread
From: Paul E. McKenney @ 2021-01-13 0:09 UTC (permalink / raw)
To: Mark Rutland; +Cc: linux-kernel, maz, peterz, tglx
On Tue, Jan 12, 2021 at 01:59:48PM +0000, Mark Rutland wrote:
> Hi,
>
> While fuzzing arm64 with Syzkaller (under QEMU+KVM) over a number of releases,
> I've occasionally seen some ridiculously long stalls (20+ seconds), where it
> appears that a CPU is stuck in a hard IRQ context. As this gets detected after
> the CPU returns to the interrupted context, it's difficult to identify where
> exactly the stall is coming from.
>
> These patches are intended to help tracking this down, with a WARN() if an IRQ
> handler takes longer than a given timout (1 second by default), logging the
> specific IRQ and handler function. While it's possible to achieve similar with
> tracing, it's harder to integrate that into an automated fuzzing setup.
>
> I've been running this for a short while, and haven't yet seen any of the
> stalls with this applied, but I've tested with smaller timeout periods in the 1
> millisecond range by overloading the host, so I'm confident that the check
> works.
>
> Thanks,
> Mark.
Nice!
Acked-by: Paul E. McKenney <paulmck@kernel.org>
I added the patch below to add a three-second delay to the scheduling
clock interrupt handler. This executed, but did not cause your warning
to be emitted, probably because rcutorture runs under qemu/KVM. So no
Tested-by, not yet, anyway.
Thanx, Paul
------------------------------------------------------------------------
diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
index e04e336..dac8c7a 100644
--- a/kernel/rcu/tree.c
+++ b/kernel/rcu/tree.c
@@ -2606,6 +2606,8 @@ static void rcu_do_batch(struct rcu_data *rdp)
*/
void rcu_sched_clock_irq(int user)
{
+ static atomic_t invctr;
+
trace_rcu_utilization(TPS("Start scheduler-tick"));
lockdep_assert_irqs_disabled();
raw_cpu_inc(rcu_data.ticks_this_gp);
@@ -2623,6 +2625,14 @@ void rcu_sched_clock_irq(int user)
invoke_rcu_core();
lockdep_assert_irqs_disabled();
+ if (atomic_inc_return(&invctr) % 0x3ffff == 0) {
+ int i;
+
+ pr_alert("%s: 3-second delay.\n", __func__);
+ for (i = 0; i < 3000; i++)
+ udelay(1000);
+ }
+
trace_rcu_utilization(TPS("End scheduler-tick"));
}
^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [PATCH 0/2] irq: detect slow IRQ handlers
2021-01-13 0:09 ` [PATCH 0/2] irq: detect slow " Paul E. McKenney
@ 2021-01-13 12:39 ` Mark Rutland
2021-01-13 17:18 ` Paul E. McKenney
0 siblings, 1 reply; 6+ messages in thread
From: Mark Rutland @ 2021-01-13 12:39 UTC (permalink / raw)
To: Paul E. McKenney; +Cc: linux-kernel, maz, peterz, tglx
On Tue, Jan 12, 2021 at 04:09:53PM -0800, Paul E. McKenney wrote:
> On Tue, Jan 12, 2021 at 01:59:48PM +0000, Mark Rutland wrote:
> > Hi,
> >
> > While fuzzing arm64 with Syzkaller (under QEMU+KVM) over a number of releases,
> > I've occasionally seen some ridiculously long stalls (20+ seconds), where it
> > appears that a CPU is stuck in a hard IRQ context. As this gets detected after
> > the CPU returns to the interrupted context, it's difficult to identify where
> > exactly the stall is coming from.
> >
> > These patches are intended to help tracking this down, with a WARN() if an IRQ
> > handler takes longer than a given timout (1 second by default), logging the
> > specific IRQ and handler function. While it's possible to achieve similar with
> > tracing, it's harder to integrate that into an automated fuzzing setup.
> >
> > I've been running this for a short while, and haven't yet seen any of the
> > stalls with this applied, but I've tested with smaller timeout periods in the 1
> > millisecond range by overloading the host, so I'm confident that the check
> > works.
> >
> > Thanks,
> > Mark.
>
> Nice!
>
> Acked-by: Paul E. McKenney <paulmck@kernel.org>
>
> I added the patch below to add a three-second delay to the scheduling
> clock interrupt handler. This executed, but did not cause your warning
> to be emitted, probably because rcutorture runs under qemu/KVM. So no
> Tested-by, not yet, anyway.
I think this is because on x86, APIC timer interrupts are handled in
arch code without going through the usual IRQ management infrastructure.
A dump_stack() in rcu_sched_clock_irq() shows:
[ 75.131594] rcu: rcu_sched_clock_irq: 3-second delay.
[ 75.132557] CPU: 2 PID: 135 Comm: sh Not tainted 5.11.0-rc3+ #12
[ 75.133610] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
[ 75.135639] Call Trace:
[ 75.136100] dump_stack+0x57/0x6a
[ 75.136713] rcu_sched_clock_irq+0x76d/0x880
[ 75.137493] update_process_times+0x77/0xb0
[ 75.138254] tick_sched_handle.isra.17+0x2b/0x40
[ 75.139105] tick_sched_timer+0x36/0x70
[ 75.139803] ? tick_sched_handle.isra.17+0x40/0x40
[ 75.140665] __hrtimer_run_queues+0xf8/0x230
[ 75.141441] hrtimer_interrupt+0xfc/0x240
[ 75.142169] ? asm_sysvec_apic_timer_interrupt+0xa/0x20
[ 75.143117] __sysvec_apic_timer_interrupt+0x58/0xf0
[ 75.144017] sysvec_apic_timer_interrupt+0x27/0x80
[ 75.144892] asm_sysvec_apic_timer_interrupt+0x12/0x20
Here __sysvec_apic_timer_interrupt() calls local_apic_timer_interrupt()
which calls the clock_event_device::event_handler() directly. Since that
never goes via an irqaction handler, the code I add is never invoked in
this path. I believe this is true for a number of IRQs on x86 (e.g.
IPIs). A slow handler for a peripheral interrupt should still be caught,
though.
On arm64, timer interrupts (and IIUC IPIs too) go though the usual IRQ
management code, and so delays there get caught:
[ 311.703932] rcu: rcu_sched_clock_irq: 3-second delay.
[ 311.705012] CPU: 3 PID: 199 Comm: bash Not tainted 5.11.0-rc3-00003-gbe60490b2295-dirty #13
[ 311.706694] Hardware name: linux,dummy-virt (DT)
[ 311.707688] Call trace:
[ 311.708233] dump_backtrace+0x0/0x1a0
[ 311.709053] show_stack+0x18/0x70
[ 311.709774] dump_stack+0xd0/0x12c
[ 311.710468] rcu_sched_clock_irq+0x7d4/0xcf0
[ 311.711356] update_process_times+0x9c/0xec
[ 311.712288] tick_sched_handle+0x34/0x60
[ 311.713191] tick_sched_timer+0x4c/0xa4
[ 311.714043] __hrtimer_run_queues+0x140/0x1e0
[ 311.715012] hrtimer_interrupt+0xe8/0x290
[ 311.715943] arch_timer_handler_virt+0x38/0x4c
[ 311.716951] handle_percpu_devid_irq+0x94/0x190
[ 311.717953] __handle_domain_irq+0x7c/0xe0
[ 311.718890] gic_handle_irq+0xc0/0x140
[ 311.719729] el0_irq_naked+0x4c/0x54
[ 314.720833] ------------[ cut here ]------------
[ 314.721950] IRQ 11 handler arch_timer_handler_virt took 3016901740 ns
[ 314.723421] WARNING: CPU: 3 PID: 199 at kernel/irq/internals.h:140 handle_percpu_devid_irq+0x158/0x190
I think our options are:
1) Live with it, and don't check these special cases.
2) Rework the special cases to go though the regular irqaction
processing.
3) Open-code checks in each special case.
4) Add a helper/wrapper function that can be called in each special
case, and update each one accordingly.
... and I reckon some mixture of #3 and #4 is plausible. We could add a
__handle_check_irq_function() or similar and use that to wrap the call
to local_apic_timer_interrupt() from sysvec_apic_timer_interrupt(), but
I'm not sure exactly what that needs to look like to cover any other
special cases.
Thanks,
Mark.
>
> Thanx, Paul
>
> ------------------------------------------------------------------------
>
> diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> index e04e336..dac8c7a 100644
> --- a/kernel/rcu/tree.c
> +++ b/kernel/rcu/tree.c
> @@ -2606,6 +2606,8 @@ static void rcu_do_batch(struct rcu_data *rdp)
> */
> void rcu_sched_clock_irq(int user)
> {
> + static atomic_t invctr;
> +
> trace_rcu_utilization(TPS("Start scheduler-tick"));
> lockdep_assert_irqs_disabled();
> raw_cpu_inc(rcu_data.ticks_this_gp);
> @@ -2623,6 +2625,14 @@ void rcu_sched_clock_irq(int user)
> invoke_rcu_core();
> lockdep_assert_irqs_disabled();
>
> + if (atomic_inc_return(&invctr) % 0x3ffff == 0) {
> + int i;
> +
> + pr_alert("%s: 3-second delay.\n", __func__);
> + for (i = 0; i < 3000; i++)
> + udelay(1000);
> + }
> +
> trace_rcu_utilization(TPS("End scheduler-tick"));
> }
>
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH 0/2] irq: detect slow IRQ handlers
2021-01-13 12:39 ` Mark Rutland
@ 2021-01-13 17:18 ` Paul E. McKenney
0 siblings, 0 replies; 6+ messages in thread
From: Paul E. McKenney @ 2021-01-13 17:18 UTC (permalink / raw)
To: Mark Rutland; +Cc: linux-kernel, maz, peterz, tglx
On Wed, Jan 13, 2021 at 12:39:15PM +0000, Mark Rutland wrote:
> On Tue, Jan 12, 2021 at 04:09:53PM -0800, Paul E. McKenney wrote:
> > On Tue, Jan 12, 2021 at 01:59:48PM +0000, Mark Rutland wrote:
> > > Hi,
> > >
> > > While fuzzing arm64 with Syzkaller (under QEMU+KVM) over a number of releases,
> > > I've occasionally seen some ridiculously long stalls (20+ seconds), where it
> > > appears that a CPU is stuck in a hard IRQ context. As this gets detected after
> > > the CPU returns to the interrupted context, it's difficult to identify where
> > > exactly the stall is coming from.
> > >
> > > These patches are intended to help tracking this down, with a WARN() if an IRQ
> > > handler takes longer than a given timout (1 second by default), logging the
> > > specific IRQ and handler function. While it's possible to achieve similar with
> > > tracing, it's harder to integrate that into an automated fuzzing setup.
> > >
> > > I've been running this for a short while, and haven't yet seen any of the
> > > stalls with this applied, but I've tested with smaller timeout periods in the 1
> > > millisecond range by overloading the host, so I'm confident that the check
> > > works.
> > >
> > > Thanks,
> > > Mark.
> >
> > Nice!
> >
> > Acked-by: Paul E. McKenney <paulmck@kernel.org>
> >
> > I added the patch below to add a three-second delay to the scheduling
> > clock interrupt handler. This executed, but did not cause your warning
> > to be emitted, probably because rcutorture runs under qemu/KVM. So no
> > Tested-by, not yet, anyway.
>
> I think this is because on x86, APIC timer interrupts are handled in
> arch code without going through the usual IRQ management infrastructure.
> A dump_stack() in rcu_sched_clock_irq() shows:
>
> [ 75.131594] rcu: rcu_sched_clock_irq: 3-second delay.
> [ 75.132557] CPU: 2 PID: 135 Comm: sh Not tainted 5.11.0-rc3+ #12
> [ 75.133610] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
> [ 75.135639] Call Trace:
> [ 75.136100] dump_stack+0x57/0x6a
> [ 75.136713] rcu_sched_clock_irq+0x76d/0x880
> [ 75.137493] update_process_times+0x77/0xb0
> [ 75.138254] tick_sched_handle.isra.17+0x2b/0x40
> [ 75.139105] tick_sched_timer+0x36/0x70
> [ 75.139803] ? tick_sched_handle.isra.17+0x40/0x40
> [ 75.140665] __hrtimer_run_queues+0xf8/0x230
> [ 75.141441] hrtimer_interrupt+0xfc/0x240
> [ 75.142169] ? asm_sysvec_apic_timer_interrupt+0xa/0x20
> [ 75.143117] __sysvec_apic_timer_interrupt+0x58/0xf0
> [ 75.144017] sysvec_apic_timer_interrupt+0x27/0x80
> [ 75.144892] asm_sysvec_apic_timer_interrupt+0x12/0x20
>
> Here __sysvec_apic_timer_interrupt() calls local_apic_timer_interrupt()
> which calls the clock_event_device::event_handler() directly. Since that
> never goes via an irqaction handler, the code I add is never invoked in
> this path. I believe this is true for a number of IRQs on x86 (e.g.
> IPIs). A slow handler for a peripheral interrupt should still be caught,
> though.
This seems to me to be the most important case. IPIs are already covered
by CONFIG_CSD_LOCK_WAIT_DEBUG=y already, which prints out additional
IPI-specific information.
> On arm64, timer interrupts (and IIUC IPIs too) go though the usual IRQ
> management code, and so delays there get caught:
>
> [ 311.703932] rcu: rcu_sched_clock_irq: 3-second delay.
> [ 311.705012] CPU: 3 PID: 199 Comm: bash Not tainted 5.11.0-rc3-00003-gbe60490b2295-dirty #13
> [ 311.706694] Hardware name: linux,dummy-virt (DT)
> [ 311.707688] Call trace:
> [ 311.708233] dump_backtrace+0x0/0x1a0
> [ 311.709053] show_stack+0x18/0x70
> [ 311.709774] dump_stack+0xd0/0x12c
> [ 311.710468] rcu_sched_clock_irq+0x7d4/0xcf0
> [ 311.711356] update_process_times+0x9c/0xec
> [ 311.712288] tick_sched_handle+0x34/0x60
> [ 311.713191] tick_sched_timer+0x4c/0xa4
> [ 311.714043] __hrtimer_run_queues+0x140/0x1e0
> [ 311.715012] hrtimer_interrupt+0xe8/0x290
> [ 311.715943] arch_timer_handler_virt+0x38/0x4c
> [ 311.716951] handle_percpu_devid_irq+0x94/0x190
> [ 311.717953] __handle_domain_irq+0x7c/0xe0
> [ 311.718890] gic_handle_irq+0xc0/0x140
> [ 311.719729] el0_irq_naked+0x4c/0x54
> [ 314.720833] ------------[ cut here ]------------
> [ 314.721950] IRQ 11 handler arch_timer_handler_virt took 3016901740 ns
> [ 314.723421] WARNING: CPU: 3 PID: 199 at kernel/irq/internals.h:140 handle_percpu_devid_irq+0x158/0x190
And that is in fact the trace in my case. ;-)
> I think our options are:
>
> 1) Live with it, and don't check these special cases.
>
> 2) Rework the special cases to go though the regular irqaction
> processing.
>
> 3) Open-code checks in each special case.
>
> 4) Add a helper/wrapper function that can be called in each special
> case, and update each one accordingly.
>
> ... and I reckon some mixture of #3 and #4 is plausible. We could add a
> __handle_check_irq_function() or similar and use that to wrap the call
> to local_apic_timer_interrupt() from sysvec_apic_timer_interrupt(), but
> I'm not sure exactly what that needs to look like to cover any other
> special cases.
I believe that what you have is a good starting point.
Thanx, Paul
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2021-01-13 17:19 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-01-12 13:59 [PATCH 0/2] irq: detect slow IRQ handlers Mark Rutland
2021-01-12 13:59 ` [PATCH 1/2] irq: abstract irqaction handler invocation Mark Rutland
2021-01-12 13:59 ` [PATCH 2/2] irq: detect long-running IRQ handlers Mark Rutland
2021-01-13 0:09 ` [PATCH 0/2] irq: detect slow " Paul E. McKenney
2021-01-13 12:39 ` Mark Rutland
2021-01-13 17:18 ` Paul E. McKenney
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).