LinuxLists.cc - VirtIO console hangs

2018-08-28 12:56:34

Subject: VirtIO console hangs

With kernel 4.19.0-rc1 virtio_console hangs very often.
I can always trigger the bug by pasting some characters in the
terminal window, the console will stop receiving keypresses, but I can
still see output from the console.
Stangely, logging in the VM via SSH and sending lot of data to hvc0,
like 'dmesg >/dev/hvc0' will fix the issue until the next paste.

I did a git bisect and I've found that this is the offending commit,
reverting it fixes it.

Cheers,

commit ec97eaad1383ab2500fcf9a07ade6044fbcc67f5
Author: Nicholas Piggin <[email protected]>
Date: Tue May 1 00:55:54 2018 +1000

tty: hvc: hvc_poll() break hv read loop

Avoid looping with the spinlock held while there is read data
being returned from the hv driver. Instead note if the entire
size returned by tty_buffer_request_room was read, and request
another read poll.

This limits the critical section lengths, and provides more
even service to other consoles in case there is a pathological
condition.

Signed-off-by: Nicholas Piggin <[email protected]>
Signed-off-by: Michael Ellerman <[email protected]>
--
Matteo Croce
per aspera ad upstream

2018-08-28 14:37:52

by Nicholas Piggin

[permalink] [raw]

Subject: Re: VirtIO console hangs

On Tue, 28 Aug 2018 12:54:08 +0000
Matteo Croce <[email protected]> wrote:

> With kernel 4.19.0-rc1 virtio_console hangs very often.
> I can always trigger the bug by pasting some characters in the
> terminal window, the console will stop receiving keypresses, but I can
> still see output from the console.
> Stangely, logging in the VM via SSH and sending lot of data to hvc0,
> like 'dmesg >/dev/hvc0' will fix the issue until the next paste.
>
> I did a git bisect and I've found that this is the offending commit,
> reverting it fixes it.
>
> Cheers,
>
> commit ec97eaad1383ab2500fcf9a07ade6044fbcc67f5
> Author: Nicholas Piggin <[email protected]>
> Date: Tue May 1 00:55:54 2018 +1000
>
> tty: hvc: hvc_poll() break hv read loop

Thanks for the report. I can't immediately see what the problem
is. Can you try get a stack trace of where it is stuck?

Perhaps try this patch if you have time (it's a bit of a shot
in the dark).

Thanks,
Nick

diff --git a/drivers/tty/hvc/hvc_console.c b/drivers/tty/hvc/hvc_console.c
index 5414c4a87bea..ac45235832f1 100644
--- a/drivers/tty/hvc/hvc_console.c
+++ b/drivers/tty/hvc/hvc_console.c
@@ -635,6 +635,7 @@ static int __hvc_poll(struct hvc_struct *hp, bool may_sleep)
int read_total = 0;
int written_total = 0;

+again:
spin_lock_irqsave(&hp->lock, flags);

/* Push pending writes */
@@ -721,6 +722,10 @@ static int __hvc_poll(struct hvc_struct *hp, bool may_sleep)
poll_mask |= HVC_POLL_READ;
read_total = n;

+ spin_unlock_irqrestore(&hp->lock, flags);
+ cond_resched();
+ goto again;
+
out:
/* Wakeup write queue if necessary */
if (hp->do_wakeup) {

2018-08-28 15:02:17

by Matteo Croce

[permalink] [raw]

Subject: Re: VirtIO console hangs

On Tue, Aug 28, 2018 at 2:35 PM Nicholas Piggin <[email protected]> wrote:
>
> On Tue, 28 Aug 2018 12:54:08 +0000
> Matteo Croce <[email protected]> wrote:
>
> > With kernel 4.19.0-rc1 virtio_console hangs very often.
> > I can always trigger the bug by pasting some characters in the
> > terminal window, the console will stop receiving keypresses, but I can
> > still see output from the console.
> > Stangely, logging in the VM via SSH and sending lot of data to hvc0,
> > like 'dmesg >/dev/hvc0' will fix the issue until the next paste.
> >
> > I did a git bisect and I've found that this is the offending commit,
> > reverting it fixes it.
> >
> > Cheers,
> >
> > commit ec97eaad1383ab2500fcf9a07ade6044fbcc67f5
> > Author: Nicholas Piggin <[email protected]>
> > Date: Tue May 1 00:55:54 2018 +1000
> >
> > tty: hvc: hvc_poll() break hv read loop
>
> Thanks for the report. I can't immediately see what the problem
> is. Can you try get a stack trace of where it is stuck?
>

I tried but didn't get one.

> Perhaps try this patch if you have time (it's a bit of a shot
> in the dark).
>

Yes it seems to fix. Thanks!

--
Matteo Croce
per aspera ad upstream

2018-08-28 15:35:06

by Nicholas Piggin

[permalink] [raw]

Subject: Re: VirtIO console hangs

2018-08-31 03:51:34

by Nicholas Piggin

[permalink] [raw]

Subject: Re: VirtIO console hangs

On Tue, 28 Aug 2018 15:00:14 +0000
Matteo Croce <[email protected]> wrote:

> On Tue, Aug 28, 2018 at 2:35 PM Nicholas Piggin <[email protected]> wrote:
> >
> > On Tue, 28 Aug 2018 12:54:08 +0000
> > Matteo Croce <[email protected]> wrote:
> >
> > > With kernel 4.19.0-rc1 virtio_console hangs very often.
> > > I can always trigger the bug by pasting some characters in the
> > > terminal window, the console will stop receiving keypresses, but I can
> > > still see output from the console.
> > > Stangely, logging in the VM via SSH and sending lot of data to hvc0,
> > > like 'dmesg >/dev/hvc0' will fix the issue until the next paste.
> > >
> > > I did a git bisect and I've found that this is the offending commit,
> > > reverting it fixes it.
> > >
> > > Cheers,
> > >
> > > commit ec97eaad1383ab2500fcf9a07ade6044fbcc67f5
> > > Author: Nicholas Piggin <[email protected]>
> > > Date: Tue May 1 00:55:54 2018 +1000
> > >
> > > tty: hvc: hvc_poll() break hv read loop
> >
> > Thanks for the report. I can't immediately see what the problem
> > is. Can you try get a stack trace of where it is stuck?
> >
>
> I tried but didn't get one.
>
> > Perhaps try this patch if you have time (it's a bit of a shot
> > in the dark).
> >
>
> Yes it seems to fix. Thanks!

Okay sorry for the delay, I can reproduce it here and found a better
fix, if I could trouble you to test again.

[PATCH] tty: hvc: hvc_poll() fix read loop hang

Patch ec97eaad1383 ("tty: hvc: hvc_poll() break hv read loop") causes
the virtio console to hang if you paste a bunch of characters to it.

The reason is that get_chars must return 0 before we can be sure the
driver will kick or poll input again, but this patch only scheduled a
poll if get_chars had returned a full count. Change this to poll on
> 0 count.

Fixes: ec97eaad1383 ("tty: hvc: hvc_poll() break hv read loop")
Reported-by: Matteo Croce <[email protected]>
Signed-off-by: Nicholas Piggin <[email protected]>
---
drivers/tty/hvc/hvc_console.c | 14 ++++++--------
1 file changed, 6 insertions(+), 8 deletions(-)

diff --git a/drivers/tty/hvc/hvc_console.c
b/drivers/tty/hvc/hvc_console.c index 5414c4a87bea..219369aebb1f 100644
--- a/drivers/tty/hvc/hvc_console.c
+++ b/drivers/tty/hvc/hvc_console.c
@@ -717,10 +717,13 @@ static int __hvc_poll(struct hvc_struct *hp, bool
may_sleep) #endif /* CONFIG_MAGIC_SYSRQ */
tty_insert_flip_char(&hp->port, buf[i], 0);
}
- if (n == count)
- poll_mask |= HVC_POLL_READ;
read_total = n;

+ /* Activity is occurring, so reset the polling backoff value to
+ a minimum for performance. */
+ timeout = MIN_TIMEOUT;
+ poll_mask |= HVC_POLL_READ;
+
out:
/* Wakeup write queue if necessary */
if (hp->do_wakeup) {
@@ -730,13 +733,8 @@ static int __hvc_poll(struct hvc_struct *hp, bool
may_sleep) bail:
spin_unlock_irqrestore(&hp->lock, flags);

- if (read_total) {
- /* Activity is occurring, so reset the polling backoff
value to
- a minimum for performance. */
- timeout = MIN_TIMEOUT;
-
+ if (read_total)
tty_flip_buffer_push(&hp->port);
- }
tty_kref_put(tty);

return poll_mask;
--
2.18.0

2018-08-31 15:19:42

by Matteo Croce

[permalink] [raw]

Subject: Re: VirtIO console hangs

On Fri, Aug 31, 2018 at 3:49 AM Nicholas Piggin <[email protected]> wrote:
>
> On Tue, 28 Aug 2018 15:00:14 +0000
> Matteo Croce <[email protected]> wrote:
>
> > On Tue, Aug 28, 2018 at 2:35 PM Nicholas Piggin <[email protected]> wrote:
> > >
> > > On Tue, 28 Aug 2018 12:54:08 +0000
> > > Matteo Croce <[email protected]> wrote:
> > >
> > > > With kernel 4.19.0-rc1 virtio_console hangs very often.
> > > > I can always trigger the bug by pasting some characters in the
> > > > terminal window, the console will stop receiving keypresses, but I can
> > > > still see output from the console.
> > > > Stangely, logging in the VM via SSH and sending lot of data to hvc0,
> > > > like 'dmesg >/dev/hvc0' will fix the issue until the next paste.
> > > >
> > > > I did a git bisect and I've found that this is the offending commit,
> > > > reverting it fixes it.
> > > >
> > > > Cheers,
> > > >
> > > > commit ec97eaad1383ab2500fcf9a07ade6044fbcc67f5
> > > > Author: Nicholas Piggin <[email protected]>
> > > > Date: Tue May 1 00:55:54 2018 +1000
> > > >
> > > > tty: hvc: hvc_poll() break hv read loop
> > >
> > > Thanks for the report. I can't immediately see what the problem
> > > is. Can you try get a stack trace of where it is stuck?
> > >
> >
> > I tried but didn't get one.
> >
> > > Perhaps try this patch if you have time (it's a bit of a shot
> > > in the dark).
> > >
> >
> > Yes it seems to fix. Thanks!
>
> Okay sorry for the delay, I can reproduce it here and found a better
> fix, if I could trouble you to test again.
>
> [PATCH] tty: hvc: hvc_poll() fix read loop hang
>

Hi Nicholas,

the patch works, but now pasting text inside the terminal is extremely
slow, it feels worse than a 9600 baud serial line.

Btw, I had to apply the patch by hand as it was corrupted, some lines
were collapsed into one.

Cheers,
--
Matteo Croce
per aspera ad upstream

2018-08-31 22:53:21

by Nicholas Piggin

[permalink] [raw]

Subject: Re: VirtIO console hangs

2018-08-31 22:59:05

by Nicholas Piggin

[permalink] [raw]

Subject: Re: VirtIO console hangs

2018-09-05 03:56:22

by Nicholas Piggin

[permalink] [raw]

Subject: Re: VirtIO console hangs

On Fri, 31 Aug 2018 15:17:44 +0000
Matteo Croce <[email protected]> wrote:

> On Fri, Aug 31, 2018 at 3:49 AM Nicholas Piggin <[email protected]> wrote:
> >
> > On Tue, 28 Aug 2018 15:00:14 +0000
> > Matteo Croce <[email protected]> wrote:
> >
> > > On Tue, Aug 28, 2018 at 2:35 PM Nicholas Piggin <[email protected]> wrote:
> > > >
> > > > On Tue, 28 Aug 2018 12:54:08 +0000
> > > > Matteo Croce <[email protected]> wrote:
> > > >
> > > > > With kernel 4.19.0-rc1 virtio_console hangs very often.
> > > > > I can always trigger the bug by pasting some characters in the
> > > > > terminal window, the console will stop receiving keypresses, but I can
> > > > > still see output from the console.
> > > > > Stangely, logging in the VM via SSH and sending lot of data to hvc0,
> > > > > like 'dmesg >/dev/hvc0' will fix the issue until the next paste.
> > > > >
> > > > > I did a git bisect and I've found that this is the offending commit,
> > > > > reverting it fixes it.
> > > > >
> > > > > Cheers,
> > > > >
> > > > > commit ec97eaad1383ab2500fcf9a07ade6044fbcc67f5
> > > > > Author: Nicholas Piggin <[email protected]>
> > > > > Date: Tue May 1 00:55:54 2018 +1000
> > > > >
> > > > > tty: hvc: hvc_poll() break hv read loop
> > > >
> > > > Thanks for the report. I can't immediately see what the problem
> > > > is. Can you try get a stack trace of where it is stuck?
> > > >
> > >
> > > I tried but didn't get one.
> > >
> > > > Perhaps try this patch if you have time (it's a bit of a shot
> > > > in the dark).
> > > >
> > >
> > > Yes it seems to fix. Thanks!
> >
> > Okay sorry for the delay, I can reproduce it here and found a better
> > fix, if I could trouble you to test again.
> >
> > [PATCH] tty: hvc: hvc_poll() fix read loop hang
> >
>
> Hi Nicholas,
>
> the patch works, but now pasting text inside the terminal is extremely
> slow, it feels worse than a 9600 baud serial line.
>
> Btw, I had to apply the patch by hand as it was corrupted, some lines
> were collapsed into one.

Not sure why that happened, I seem to be able to send myself
uncorrupted patches...

Can you try this patch for performance? Hopefully it applies.
--

diff --git a/drivers/tty/hvc/hvc_console.c b/drivers/tty/hvc/hvc_console.c
index 5414c4a87bea..f5fc3ba49130 100644
--- a/drivers/tty/hvc/hvc_console.c
+++ b/drivers/tty/hvc/hvc_console.c
@@ -49,6 +49,8 @@
#define N_OUTBUF 16
#define N_INBUF 16

+#define HVC_ATOMIC_READ_MAX 128
+
#define __ALIGNED__ __attribute__((__aligned__(sizeof(long))))

static struct tty_driver *hvc_driver;
@@ -522,6 +524,8 @@ static int hvc_write(struct tty_struct *tty, const unsigned char *buf, int count
return -EIO;

while (count > 0) {
+ int ret;
+
spin_lock_irqsave(&hp->lock, flags);

rsize = hp->outbuf_size - hp->n_outbuf;
@@ -537,10 +541,13 @@ static int hvc_write(struct tty_struct *tty, const unsigned char *buf, int count
}

if (hp->n_outbuf > 0)
- hvc_push(hp);
+ ret = hvc_push(hp);

spin_unlock_irqrestore(&hp->lock, flags);

+ if (!ret)
+ break;
+
if (count) {
if (hp->n_outbuf > 0)
hvc_flush(hp);
@@ -669,8 +676,8 @@ static int __hvc_poll(struct hvc_struct *hp, bool may_sleep)
if (!hp->irq_requested)
poll_mask |= HVC_POLL_READ;

+ read_again:
/* Read data if any */
-
count = tty_buffer_request_room(&hp->port, N_INBUF);

/* If flip is full, just reschedule a later read */
@@ -717,9 +724,23 @@ static int __hvc_poll(struct hvc_struct *hp, bool may_sleep)
#endif /* CONFIG_MAGIC_SYSRQ */
tty_insert_flip_char(&hp->port, buf[i], 0);
}
- if (n == count)
- poll_mask |= HVC_POLL_READ;
- read_total = n;
+ read_total += n;
+
+ if (may_sleep) {
+ /* Keep going until the flip is full */
+ spin_unlock_irqrestore(&hp->lock, flags);
+ cond_resched();
+ spin_lock_irqsave(&hp->lock, flags);
+ goto read_again;
+ } else if (read_total < HVC_ATOMIC_READ_MAX) {
+ /* Break and defer if it's a large read in atomic */
+ goto read_again;
+ }
+
+ /*
+ * Latency break, schedule another poll immediately.
+ */
+ poll_mask |= HVC_POLL_READ;

out:
/* Wakeup write queue if necessary */

2018-09-05 09:18:36

by Matteo Croce

[permalink] [raw]

Subject: Re: VirtIO console hangs

On Wed, Sep 5, 2018 at 3:54 AM Nicholas Piggin <[email protected]> wrote:
>
> On Fri, 31 Aug 2018 15:17:44 +0000
> Matteo Croce <[email protected]> wrote:
>
> > On Fri, Aug 31, 2018 at 3:49 AM Nicholas Piggin <[email protected]> wrote:
> > >
> > > On Tue, 28 Aug 2018 15:00:14 +0000
> > > Matteo Croce <[email protected]> wrote:
> > >
> > > > On Tue, Aug 28, 2018 at 2:35 PM Nicholas Piggin <[email protected]> wrote:
> > > > >
> > > > > On Tue, 28 Aug 2018 12:54:08 +0000
> > > > > Matteo Croce <[email protected]> wrote:
> > > > >
> > > > > > With kernel 4.19.0-rc1 virtio_console hangs very often.
> > > > > > I can always trigger the bug by pasting some characters in the
> > > > > > terminal window, the console will stop receiving keypresses, but I can
> > > > > > still see output from the console.
> > > > > > Stangely, logging in the VM via SSH and sending lot of data to hvc0,
> > > > > > like 'dmesg >/dev/hvc0' will fix the issue until the next paste.
> > > > > >
> > > > > > I did a git bisect and I've found that this is the offending commit,
> > > > > > reverting it fixes it.
> > > > > >
> > > > > > Cheers,
> > > > > >
> > > > > > commit ec97eaad1383ab2500fcf9a07ade6044fbcc67f5
> > > > > > Author: Nicholas Piggin <[email protected]>
> > > > > > Date: Tue May 1 00:55:54 2018 +1000
> > > > > >
> > > > > > tty: hvc: hvc_poll() break hv read loop
> > > > >
> > > > > Thanks for the report. I can't immediately see what the problem
> > > > > is. Can you try get a stack trace of where it is stuck?
> > > > >
> > > >
> > > > I tried but didn't get one.
> > > >
> > > > > Perhaps try this patch if you have time (it's a bit of a shot
> > > > > in the dark).
> > > > >
> > > >
> > > > Yes it seems to fix. Thanks!
> > >
> > > Okay sorry for the delay, I can reproduce it here and found a better
> > > fix, if I could trouble you to test again.
> > >
> > > [PATCH] tty: hvc: hvc_poll() fix read loop hang
> > >
> >
> > Hi Nicholas,
> >
> > the patch works, but now pasting text inside the terminal is extremely
> > slow, it feels worse than a 9600 baud serial line.
> >
> > Btw, I had to apply the patch by hand as it was corrupted, some lines
> > were collapsed into one.
>
> Not sure why that happened, I seem to be able to send myself
> uncorrupted patches...
>
> Can you try this patch for performance? Hopefully it applies.

Hi Nicholas,

This one works really well, as in kernel 4.17.
Feel free to add me in Tested-by or Reported-by (or both).

Cheers,
--
Matteo Croce
per aspera ad upstream