[PATCH] irq: Guard handle_bad_irq log messages

[PATCH] irq: Guard handle_bad_irq log messages

[Guenter Roeck]

An interrupt storm on a bad interrupt will cause the kernel
log to be clogged.

[   60.089234] ->handle_irq():  ffffffffbe2f803f,
[   60.090455] 0xffffffffbf2af380
[   60.090510] handle_bad_irq+0x0/0x2e5
[   60.090522] ->irq_data.chip(): ffffffffbf2af380,
[   60.090553]    IRQ_NOPROBE set
[   60.090584] ->handle_irq():  ffffffffbe2f803f,
[   60.090590] handle_bad_irq+0x0/0x2e5
[   60.090596] ->irq_data.chip(): ffffffffbf2af380,
[   60.090602] 0xffffffffbf2af380
[   60.090608] ->action():           (null)
[   60.090779] handle_bad_irq+0x0/0x2e5

This was seen when running an upstream kernel on Acer Chromebook R11.
The system was unstable as result.

Guard the log message with __printk_ratelimit to reduce the impact.
This won't prevent the interrupt storm from happening, but at least
the system remains stable.

Link: https://bugzilla.kernel.org/show_bug.cgi?id=197953
Cc: Andy Shevchenko <andriy.shevchenko@linux.intel.com>
Cc: Dmitry Torokhov <dtor@chromium.org>
Cc: Mika Westerberg <mika.westerberg@linux.intel.com>
Signed-off-by: Guenter Roeck <linux@roeck-us.net>
---
 kernel/irq/handle.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/kernel/irq/handle.c b/kernel/irq/handle.c
index 79f987b942b8..ad4d7a995f18 100644
--- a/kernel/irq/handle.c
+++ b/kernel/irq/handle.c
@@ -28,9 +28,11 @@
  */
 void handle_bad_irq(struct irq_desc *desc)
 {
+	static DEFINE_RATELIMIT_STATE(ratelimit, 5 * HZ, 5);
 	unsigned int irq = irq_desc_get_irq(desc);
 
-	print_irq_desc(irq, desc);
+	if (__ratelimit(&ratelimit))
+		print_irq_desc(irq, desc);
 	kstat_incr_irqs_this_cpu(desc);
 	ack_bad_irq(irq);
 }
-- 
2.7.4

Re: [PATCH] irq: Guard handle_bad_irq log messages

[Joe Perches]

On Sat, 2017-12-02 at 08:29 -0800, Guenter Roeck wrote:
> An interrupt storm on a bad interrupt will cause the kernel
> log to be clogged.
> 
> [   60.089234] ->handle_irq():  ffffffffbe2f803f,
> [   60.090455] 0xffffffffbf2af380
> [   60.090510] handle_bad_irq+0x0/0x2e5
> [   60.090522] ->irq_data.chip(): ffffffffbf2af380,
> [   60.090553]    IRQ_NOPROBE set
> [   60.090584] ->handle_irq():  ffffffffbe2f803f,
> [   60.090590] handle_bad_irq+0x0/0x2e5
> [   60.090596] ->irq_data.chip(): ffffffffbf2af380,
> [   60.090602] 0xffffffffbf2af380
> [   60.090608] ->action():           (null)
> [   60.090779] handle_bad_irq+0x0/0x2e5
> 
> This was seen when running an upstream kernel on Acer Chromebook R11.
> The system was unstable as result.
> 
> Guard the log message with __printk_ratelimit to reduce the impact.
> This won't prevent the interrupt storm from happening, but at least
> the system remains stable.

Thanks.

There is also dummychip.c

Perhaps this should be updated in the
static inline in kernel/irq/debug.h instead.

> diff --git a/kernel/irq/handle.c b/kernel/irq/handle.c
[]
> @@ -28,9 +28,11 @@
>   */
>  void handle_bad_irq(struct irq_desc *desc)
>  {
> +	static DEFINE_RATELIMIT_STATE(ratelimit, 5 * HZ, 5);
>  	unsigned int irq = irq_desc_get_irq(desc);
>  
> -	print_irq_desc(irq, desc);
> +	if (__ratelimit(&ratelimit))
> +		print_irq_desc(irq, desc);
>  	kstat_incr_irqs_this_cpu(desc);
>  	ack_bad_irq(irq);
>  }

Re: [PATCH] irq: Guard handle_bad_irq log messages

[Guenter Roeck]

On 12/02/2017 08:52 AM, Joe Perches wrote:
> On Sat, 2017-12-02 at 08:29 -0800, Guenter Roeck wrote:
>> An interrupt storm on a bad interrupt will cause the kernel
>> log to be clogged.
>>
>> [   60.089234] ->handle_irq():  ffffffffbe2f803f,
>> [   60.090455] 0xffffffffbf2af380
>> [   60.090510] handle_bad_irq+0x0/0x2e5
>> [   60.090522] ->irq_data.chip(): ffffffffbf2af380,
>> [   60.090553]    IRQ_NOPROBE set
>> [   60.090584] ->handle_irq():  ffffffffbe2f803f,
>> [   60.090590] handle_bad_irq+0x0/0x2e5
>> [   60.090596] ->irq_data.chip(): ffffffffbf2af380,
>> [   60.090602] 0xffffffffbf2af380
>> [   60.090608] ->action():           (null)
>> [   60.090779] handle_bad_irq+0x0/0x2e5
>>
>> This was seen when running an upstream kernel on Acer Chromebook R11.
>> The system was unstable as result.
>>
>> Guard the log message with __printk_ratelimit to reduce the impact.
>> This won't prevent the interrupt storm from happening, but at least
>> the system remains stable.
> 
> Thanks.
> 
> There is also dummychip.c
> 
> Perhaps this should be updated in the
> static inline in kernel/irq/debug.h instead.
> 

Agreed, makes sense. I'll send an updated patch.

Guenter

>> diff --git a/kernel/irq/handle.c b/kernel/irq/handle.c
> []
>> @@ -28,9 +28,11 @@
>>    */
>>   void handle_bad_irq(struct irq_desc *desc)
>>   {
>> +	static DEFINE_RATELIMIT_STATE(ratelimit, 5 * HZ, 5);
>>   	unsigned int irq = irq_desc_get_irq(desc);
>>   
>> -	print_irq_desc(irq, desc);
>> +	if (__ratelimit(&ratelimit))
>> +		print_irq_desc(irq, desc);
>>   	kstat_incr_irqs_this_cpu(desc);
>>   	ack_bad_irq(irq);
>>   }
>