Due using virtualization it is common to see
many "too much work for irq*" messages.
There are fixes proposed erlier:
- e7328ae1848966181a7ac47e8ae6cddbd2cf55f3 (serial:
8250, increase PASS_LIMIT)
- f4f653e9875e573860e783fecbebde284a8626f5 (serial:
8250, disable "too much work" messages
First one doesn't help now, last one was reverted
(12de375ec493ab1767d4a07dde823e63ae5edc21) in fact
it doesn't fix anything. So procesing interrupts in
kthread give us an opportunity to perform rescheduling
periodically.
Cc: Jiri Slaby <[email protected]>
Signed-off-by: Denys Zagorui <[email protected]>
---
drivers/tty/serial/8250/8250_core.c | 23 ++++++++++++++++-------
drivers/tty/serial/8250/8250_port.c | 5 ++---
2 files changed, 18 insertions(+), 10 deletions(-)
diff --git a/drivers/tty/serial/8250/8250_core.c b/drivers/tty/serial/8250/8250_core.c
index d29b512a7d9f..0c2f6352523a 100644
--- a/drivers/tty/serial/8250/8250_core.c
+++ b/drivers/tty/serial/8250/8250_core.c
@@ -58,7 +58,7 @@ static struct uart_driver serial8250_reg;
static unsigned int skip_txen_test; /* force skip of txen test at init time */
-#define PASS_LIMIT 512
+#define PASS_LIMIT 32
#include <asm/serial.h>
/*
@@ -135,10 +135,8 @@ static irqreturn_t serial8250_interrupt(int irq, void *dev_id)
l = l->next;
if (l == i->head && pass_counter++ > PASS_LIMIT) {
- /* If we hit this, we're dead. */
- printk_ratelimited(KERN_ERR
- "serial8250: too much work for irq%d\n", irq);
- break;
+ cond_resched();
+ pass_counter = 0;
}
} while (l != end);
@@ -146,9 +144,20 @@ static irqreturn_t serial8250_interrupt(int irq, void *dev_id)
pr_debug("%s(%d): end\n", __func__, irq);
+ enable_irq(i->irq);
+
return IRQ_RETVAL(handled);
}
+static irqreturn_t serial8250_hard_irq(int irq, void *dev_id)
+{
+ struct irq_info *i = dev_id;
+
+ disable_irq_nosync(i->irq);
+
+ return IRQ_WAKE_THREAD;
+}
+
/*
* To support ISA shared interrupts, we need to have one interrupt
* handler that ensures that the IRQ line has been deasserted
@@ -217,8 +226,8 @@ static int serial_link_irq_chain(struct uart_8250_port *up)
i->head = &up->list;
spin_unlock_irq(&i->lock);
irq_flags |= up->port.irqflags;
- ret = request_irq(up->port.irq, serial8250_interrupt,
- irq_flags, up->port.name, i);
+ ret = request_threaded_irq(up->port.irq, serial8250_hard_irq,
+ serial8250_interrupt, irq_flags, up->port.name, i);
if (ret < 0)
serial_do_unlink(i, up);
}
diff --git a/drivers/tty/serial/8250/8250_port.c b/drivers/tty/serial/8250/8250_port.c
index f0cc04f62b67..6d2c7bd1f402 100644
--- a/drivers/tty/serial/8250/8250_port.c
+++ b/drivers/tty/serial/8250/8250_port.c
@@ -1852,13 +1852,12 @@ static bool handle_rx_dma(struct uart_8250_port *up, unsigned int iir)
int serial8250_handle_irq(struct uart_port *port, unsigned int iir)
{
unsigned char status;
- unsigned long flags;
struct uart_8250_port *up = up_to_u8250p(port);
if (iir & UART_IIR_NO_INT)
return 0;
- spin_lock_irqsave(&port->lock, flags);
+ spin_lock(&port->lock);
status = serial_port_in(port, UART_LSR);
@@ -1870,7 +1869,7 @@ int serial8250_handle_irq(struct uart_port *port, unsigned int iir)
if ((!up->dma || up->dma->tx_err) && (status & UART_LSR_THRE))
serial8250_tx_chars(up);
- spin_unlock_irqrestore(&port->lock, flags);
+ spin_unlock(&port->lock);
return 1;
}
EXPORT_SYMBOL_GPL(serial8250_handle_irq);
--
2.11.0
From 1583557576676974602@xxx Thu Nov 09 03:29:49 +0000 2017
X-GM-THRID: 1583483607446527794
X-Gmail-Labels: Inbox,Category Forums,HistoricalUnread
FYI, we noticed the following commit (built with gcc-6):
commit: b5c545ac2fe9cea8e5799955640f79db393c1198 ("serial: 8250: convert to threaded IRQ")
url: https://github.com/0day-ci/linux/commits/Denys-Zagorui/serial-8250-convert-to-threaded-IRQ/20171112-140607
base: https://git.kernel.org/cgit/linux/kernel/git/gregkh/tty.git tty-testing
in testcase: trinity
with following parameters:
runtime: 300s
test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/
on test machine: qemu-system-x86_64 -enable-kvm -cpu kvm64,+ssse3 -m 1G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+-------------------------------------------------+------------+------------+
| | 9ce99a3a92 | b5c545ac2f |
+-------------------------------------------------+------------+------------+
| boot_successes | 4 | 0 |
| boot_failures | 1 | 8 |
| BUG:kernel_hang_in_test_stage | 1 | |
| WARNING:inconsistent_lock_state | 0 | 8 |
| inconsistent{IN-HARDIRQ-W}->{HARDIRQ-ON-W}usage | 0 | 3 |
| inconsistent{HARDIRQ-ON-W}->{IN-HARDIRQ-W}usage | 0 | 5 |
| RIP:__do_softirq | 0 | 1 |
| RIP:lock_acquire | 0 | 1 |
| calltrace:irq_exit | 0 | 3 |
| RIP:e1000_watchdog | 0 | 3 |
| RIP:_raw_spin_unlock_irq | 0 | 1 |
| RIP:__slab_alloc | 0 | 1 |
+-------------------------------------------------+------------+------------+
[ 400.767768] WARNING: inconsistent lock state
[ 400.767770] 4.14.0-rc4-00096-gb5c545ac2 #5 Not tainted
[ 400.767772] --------------------------------
[ 400.768030] inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
[ 400.768287] systemd-journal/2162 [HC1[1]:SC1[1]:HE0:SE0] takes:
[ 400.768289] (&port_lock_key){?.+.}, at: [<ffffffffa06d678b>] serial8250_console_write+0x91/0x1f4
[ 400.768318] {HARDIRQ-ON-W} state was registered at:
[ 400.768320] __lock_acquire+0x3a4/0x822
[ 400.768322] lock_acquire+0x142/0x1dd
[ 400.768323] _raw_spin_lock+0x34/0x6a
[ 400.768906] serial8250_handle_irq+0x25/0xbc
[ 400.768929] serial8250_default_handle_irq+0x28/0x3a
[ 400.768931] serial8250_interrupt+0x3e/0xa8
[ 400.768933] irq_thread_fn+0x1d/0x34
[ 400.768935] irq_thread+0xe6/0x19c
[ 400.768936] kthread+0x172/0x17a
[ 400.768938] ret_from_fork+0x2a/0x40
[ 400.768960] irq event stamp: 181597
[ 400.768963] hardirqs last enabled at (181596): [<ffffffffa0dc382d>] _raw_spin_unlock_irq+0x2c/0x3d
[ 400.768966] hardirqs last disabled at (181597): [<ffffffffa0dc5ab8>] apic_timer_interrupt+0x98/0xb0
[ 400.768969] softirqs last enabled at (181562): [<ffffffffa0dc7fd6>] __do_softirq+0x376/0x45f
[ 400.768971] softirqs last disabled at (181585): [<ffffffffa00a59e5>] irq_exit+0x5d/0xb4
[ 400.768993]
[ 400.768995] other info that might help us debug this:
[ 400.768997] Possible unsafe locking scenario:
[ 400.768998]
[ 400.769000] CPU0
[ 400.769001] ----
[ 400.769003] lock(&port_lock_key);
[ 400.769028] <Interrupt>
[ 400.769029] lock(&port_lock_key);
[ 400.769033]
[ 400.769035] *** DEADLOCK ***
[ 400.769036]
[ 400.769058] 2 locks held by systemd-journal/2162:
[ 400.769059] #0: (&p->lock){+.+.}, at: [<ffffffffa0231d06>] seq_read+0x3c/0x333
[ 400.769067] #1: (console_lock){+.+.}, at: [<ffffffffa00ff67c>] vprintk_emit+0x264/0x2c2
[ 400.769095]
[ 400.769096] stack backtrace:
[ 400.769099] CPU: 0 PID: 2162 Comm: systemd-journal Not tainted 4.14.0-rc4-00096-gb5c545ac2 #5
[ 400.769122] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 400.769124] Call Trace:
[ 400.769125] <IRQ>
[ 400.769127] dump_stack+0x86/0xc0
[ 400.769129] print_usage_bug+0x247/0x256
[ 400.769131] ? check_usage_backwards+0x106/0x106
[ 400.769133] mark_lock+0x345/0x504
[ 400.769155] __lock_acquire+0x343/0x822
[ 400.769157] lock_acquire+0x142/0x1dd
[ 400.769159] ? serial8250_console_write+0x91/0x1f4
[ 400.769161] _raw_spin_lock_irqsave+0x4d/0x88
[ 400.769163] ? serial8250_console_write+0x91/0x1f4
[ 400.769165] serial8250_console_write+0x91/0x1f4
[ 400.769187] ? console_unlock+0x1f7/0x4d6
[ 400.769189] univ8250_console_write+0x21/0x23
[ 400.769191] console_unlock+0x3fe/0x4d6
[ 400.769193] vprintk_emit+0x26d/0x2c2
[ 400.769195] vprintk_default+0x1d/0x1f
[ 400.769196] vprintk_func+0x57/0x59
[ 400.769198] printk+0x43/0x4b
[ 400.769221] hrtimer_interrupt+0x194/0x1a3
[ 400.769223] smp_apic_timer_interrupt+0x12f/0x2a9
[ 400.769225] apic_timer_interrupt+0x9d/0xb0
[ 400.769227] RIP: 0010:_raw_spin_unlock_irq+0x33/0x3d
[ 400.769229] RSP: 0018:ffff8a1a35003e70 EFLAGS: 00000206 ORIG_RAX: ffffffffffffff10
[ 400.769255] RAX: ffff8a1a3df4c040 RBX: ffff8a1a351d2a00 RCX: ffff8a1a35003dd8
[ 400.769257] RDX: 0000000000000002 RSI: ffff8a1a3df4c928 RDI: ffff8a1a3df4c040
[ 400.769260] RBP: ffff8a1a35003e78 R08: 0000006d323b831d R09: 0000000000000000
[ 400.769262] R10: 0000000000000001 R11: 0000000000000000 R12: 00000000ffffffff
[ 400.769285] R13: 00000000ffffffff R14: ffffffffa1405188 R15: 0000000000000001
[ 400.769287] run_timer_softirq+0x80/0x89
[ 400.769289] ? _raw_spin_unlock_irq+0x33/0x3d
[ 400.769291] run_timer_softirq+0x8f/0x98
[ 400.769293] __do_softirq+0x1d1/0x45f
[ 400.769294] irq_exit+0x5d/0xb4
[ 400.769317] smp_apic_timer_interrupt+0x1f0/0x2a9
[ 400.769319] apic_timer_interrupt+0x9d/0xb0
[ 400.769320] </IRQ>
[ 400.769322] RIP: 0010:__slab_alloc+0x73/0x84
[ 400.769324] RSP: 0018:ffffafd24044fd10 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff10
[ 400.769349] RAX: ffff8a1a3df4c040 RBX: 0000000000000282 RCX: ffffafd24044fcb8
[ 400.769352] RDX: ffffffffa0071b03 RSI: ffff8a1a3df4c928 RDI: 0000000000000282
[ 400.769354] RBP: ffffafd24044fd40 R08: 0000006d3168b9e5 R09: 0000000000000001
[ 400.769357] R10: ffffafd24044fd10 R11: ffff8a1a3df4c040 R12: ffff8a1a3be75698
[ 400.769359] R13: 00000000ffffffff R14: 0000000000000000 R15: ffff8a1a34c04300
[ 400.769381] ? save_stack_trace+0x1b/0x1d
[ 400.769383] ? kvmalloc_node+0x4d/0x73
[ 400.769385] __kmalloc_node+0xe9/0x35d
[ 400.769387] ? kvmalloc_node+0x4d/0x73
[ 400.769389] kvmalloc_node+0x4d/0x73
[ 400.769390] seq_buf_alloc+0x16/0x18
[ 400.769392] seq_read+0xc7/0x333
[ 400.769414] ? __seccomp_filter+0x3c/0x3d5
[ 400.769416] __vfs_read+0x26/0x10b
[ 400.769418] vfs_read+0xba/0x146
[ 400.769419] SyS_read+0x51/0x8e
[ 400.769421] do_syscall_64+0x69/0x15f
[ 400.769423] entry_SYSCALL64_slow_path+0x25/0x25
[ 400.769425] RIP: 0033:0x7ff8a51df060
[ 400.769447] RSP: 002b:00007ffc0cee8778 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[ 400.769452] RAX: ffffffffffffffda RBX: 000055f171bc3200 RCX: 00007ff8a51df060
To reproduce:
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
Thanks,
lkp