[Qemu-devel] latest master: major slowdown (something spinning?)

[Qemu-devel] latest master: major slowdown (something spinning?)

[Michael R. Hines]

[-- Attachment #1: Type: text/plain, Size: 906 bytes --]

*Here's the commit that causes the problem:*

$ git checkout d185c094b404b4ff392b77d1244c0233da7d53bd
qemu-char: eliminate busy waiting on can_read returning zero

*Symptoms:*

When the VM boots everything crawls and the host CPU is at 100%,
messages are printing extremely slowly on the VM console
and the VM is not making any boot progress......... printing kernel
messages once a second or so.......

Something in QEMU appears to be spinning.

Here's my command line:

qemu-system-x86_64 -enable-kvm -m 2048 -smp 
2,sockets=1,cores=1,threads=1 -nodefconfig -rtc base=utc -no-shutdown 
disk.img -serial pty -monitor unix:/tmp/devguest,server,nowait -netdev 
type=tap,vhost=on,id=hostnet0,script=kvmifup.sh,downscript=kvmifdown.sh 
-device virtio-net-pci,netdev=hostnet0,mac=12:34:36:00:00:02 -usb 
-device usb-tablet,id=input0  -device 
virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x5

- Michael Hines

[-- Attachment #2: Type: text/html, Size: 1260 bytes --]

Re: [Qemu-devel] latest master: major slowdown (something spinning?)

[Paolo Bonzini]

Il 09/04/2013 19:43, Michael R. Hines ha scritto:
> *Here's the commit that causes the problem:*
> 
> $ git checkout d185c094b404b4ff392b77d1244c0233da7d53bd
> qemu-char: eliminate busy waiting on can_read returning zero

Can you stil reproduce it after

commit 1e885b25275fb6763eb947b1e53b2d6911b967a8
Author: Paolo Bonzini <pbonzini@redhat.com>
Date:   Mon Apr 8 15:03:15 2013 +0200

    qemu-char: really fix behavior on can_read = 0

?

Paolo

> *Symptoms:*
> 
> When the VM boots everything crawls and the host CPU is at 100%,
> messages are printing extremely slowly on the VM console
> and the VM is not making any boot progress......... printing kernel
> messages once a second or so.......
> 
> Something in QEMU appears to be spinning.
> 
> Here's my command line:
> 
> qemu-system-x86_64 -enable-kvm -m 2048 -smp
> 2,sockets=1,cores=1,threads=1 -nodefconfig -rtc base=utc -no-shutdown
> disk.img -serial pty -monitor unix:/tmp/devguest,server,nowait -netdev
> type=tap,vhost=on,id=hostnet0,script=kvmifup.sh,downscript=kvmifdown.sh
> -device virtio-net-pci,netdev=hostnet0,mac=12:34:36:00:00:02 -usb
> -device usb-tablet,id=input0  -device
> virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x5
> 
> - Michael Hines

Re: [Qemu-devel] latest master: major slowdown (something spinning?)

[Michael R. Hines]

Yes, it still happens at that commit string.

Is there a specific test or trace I can provide to help track it down?

- Michael

On 04/10/2013 03:43 AM, Paolo Bonzini wrote:
> Il 09/04/2013 19:43, Michael R. Hines ha scritto:
>> *Here's the commit that causes the problem:*
>>
>> $ git checkout d185c094b404b4ff392b77d1244c0233da7d53bd
>> qemu-char: eliminate busy waiting on can_read returning zero
> Can you stil reproduce it after
>
> commit 1e885b25275fb6763eb947b1e53b2d6911b967a8
> Author: Paolo Bonzini <pbonzini@redhat.com>
> Date:   Mon Apr 8 15:03:15 2013 +0200
>
>      qemu-char: really fix behavior on can_read = 0
>
> ?
>
> Paolo
>
>> *Symptoms:*
>>
>> When the VM boots everything crawls and the host CPU is at 100%,
>> messages are printing extremely slowly on the VM console
>> and the VM is not making any boot progress......... printing kernel
>> messages once a second or so.......
>>
>> Something in QEMU appears to be spinning.
>>
>> Here's my command line:
>>
>> qemu-system-x86_64 -enable-kvm -m 2048 -smp
>> 2,sockets=1,cores=1,threads=1 -nodefconfig -rtc base=utc -no-shutdown
>> disk.img -serial pty -monitor unix:/tmp/devguest,server,nowait -netdev
>> type=tap,vhost=on,id=hostnet0,script=kvmifup.sh,downscript=kvmifdown.sh
>> -device virtio-net-pci,netdev=hostnet0,mac=12:34:36:00:00:02 -usb
>> -device usb-tablet,id=input0  -device
>> virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x5
>>
>> - Michael Hines
>

Re: [Qemu-devel] latest master: major slowdown (something spinning?)

[Paolo Bonzini]

Il 10/04/2013 14:43, Michael R. Hines ha scritto:
> Yes, it still happens at that commit string.
> 
> Is there a specific test or trace I can provide to help track it down?

You can try:

1) first, please post the exact QEMU command line your using;

2) put "strace -e poll" in front and post the final lines.  Also post
the output of "ls -l /proc/<pid>/fd" where <pid> is QEMU's pid.

3) if the output of "strace -e poll" hangs, instead, run it under gdb
and post a backtrace.  Perhaps continue the process a few times and
check if the backtrace remains the same or changes.

Paolo

Re: [Qemu-devel] latest master: major slowdown (something spinning?)

[Michael R. Hines]

Will do, in the meantime, QEMU just printed out this error message:

main-loop: WARNING: I/O thread spun for 1000 iterations

Will get the traces later for you....

- Michael

On 04/10/2013 08:46 AM, Paolo Bonzini wrote:
> Il 10/04/2013 14:43, Michael R. Hines ha scritto:
>> Yes, it still happens at that commit string.
>>
>> Is there a specific test or trace I can provide to help track it down?
> You can try:
>
> 1) first, please post the exact QEMU command line your using;
>
> 2) put "strace -e poll" in front and post the final lines.  Also post
> the output of "ls -l /proc/<pid>/fd" where <pid> is QEMU's pid.
>
> 3) if the output of "strace -e poll" hangs, instead, run it under gdb
> and post a backtrace.  Perhaps continue the process a few times and
> check if the backtrace remains the same or changes.
>
> Paolo
>

Re: [Qemu-devel] latest master: major slowdown (something spinning?)

[Michael R. Hines]

[-- Attachment #1: Type: text/plain, Size: 10040 bytes --]

OK, I pinned down the spinning to a specific device: A serial PTY device.

Here's a very easy way to reproduce: qemu-system-x86_64 disk.qed -serial pty


(VM is running RHEL 6.1)

If I add '-serial pty' to my command line, it spins until it prints:
main-loop: WARNING: I/O thread spun for 1000 iterations

But if I delete the device from the command-line, the VM boots up perfectly.

I've also attached the strace output and ls -l output.

$ ls -l /proc/16474/fd
total 0
lrwx------ 1 root root 64 Apr 12 23:15 0 -> /dev/pts/0
lrwx------ 1 root root 64 Apr 12 23:15 1 -> /dev/pts/0
lr-x------ 1 root root 64 Apr 12 23:15 10 -> 
/home/mrhines/qemu/pc-bios/bios.bin
lrwx------ 1 root root 64 Apr 12 23:15 11 -> socket:[1477237]
lrwx------ 1 root root 64 Apr 12 23:15 12 -> socket:[1477238]
lrwx------ 1 root root 64 Apr 12 23:15 2 -> /dev/pts/0
lrwx------ 1 root root 64 Apr 12 23:15 3 -> anon_inode:[signalfd]
lrwx------ 1 root root 64 Apr 12 23:15 4 -> anon_inode:[eventfd]
lrwx------ 1 root root 64 Apr 12 23:15 5 -> anon_inode:[eventfd]
lrwx------ 1 root root 64 Apr 12 23:15 6 -> disk.qed
lrwx------ 1 root root 64 Apr 12 23:15 7 -> anon_inode:[eventfd]
lr-x------ 1 root root 64 Apr 12 23:15 8 -> 
/home/kvm_repo/cloudbench_root.qed
lrwx------ 1 root root 64 Apr 12 23:15 9 -> /dev/ptmx
klinux9:/home/mrhines #

And QEMU seems to be doing a lot of polling:

poll([{fd=12, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=12, 
revents=POLLOUT}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=4, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 0 (Timeout)
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 943) = 1 ([{fd=3, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=4, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 2 ([{fd=3, 
revents=POLLIN}, {fd=5, revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=4, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 0 (Timeout)
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 922) = 1 ([{fd=3, 
revents=POLLIN}])
poll([{fd=12, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=12, 
revents=POLLOUT}])
poll([{fd=12, events=POLLIN}], 1, -1)   = 1 ([{fd=12, revents=POLLIN}])
poll([{fd=12, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=12, 
revents=POLLOUT}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=4, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 2 ([{fd=3, 
revents=POLLIN}, {fd=5, revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 2 ([{fd=5, 
revents=POLLIN}, {fd=4, revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 2 ([{fd=3, 
revents=POLLIN}, {fd=5, revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=4, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 0 (Timeout)
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 214) = 1 ([{fd=3, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=4, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 2 ([{fd=3, 
revents=POLLIN}, {fd=5, revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=4, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 0 (Timeout)
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 208) = 1 ([{fd=3, 
revents=POLLIN}])
poll([{fd=12, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=12, 
revents=POLLOUT}])
poll([{fd=12, events=POLLIN}], 1, -1)   = 1 ([{fd=12, revents=POLLIN}])
poll([{fd=12, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=12, 
revents=POLLOUT}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=4, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 0 (Timeout)
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 173) = 1 ([{fd=3, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=4, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 2 ([{fd=3, 
revents=POLLIN}, {fd=5, revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 2 ([{fd=5, 
revents=POLLIN}, {fd=4, revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 0 (Timeout)
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 153) = 1 ([{fd=3, 
revents=POLLIN}])
poll([{fd=12, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=12, 
revents=POLLOUT}])
poll([{fd=12, events=POLLIN}], 1, -1)   = 1 ([{fd=12, revents=POLLIN}])
poll([{fd=12, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=12, 
revents=POLLOUT}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=4, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}, {fd=9, events=POLLIN}], 5, 
0) = 3 ([{fd=3, revents=POLLIN}, {fd=5, revents=POLLIN}, {fd=9, 
revents=POLLHUP}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 2 ([{fd=5, 
revents=POLLIN}, {fd=4, revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 1 ([{fd=5, 
revents=POLLIN}])
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}, {fd=5, events=POLLIN}, 
{fd=7, events=POLLIN}, {fd=4, events=POLLIN}], 4, 0) = 0 (Timeout)



- Michael

On 04/10/2013 08:46 AM, Paolo Bonzini wrote:
> Il 10/04/2013 14:43, Michael R. Hines ha scritto:
>> Yes, it still happens at that commit string.
>>
>> Is there a specific test or trace I can provide to help track it down?
> You can try:
>
> 1) first, please post the exact QEMU command line your using;
>
> 2) put "strace -e poll" in front and post the final lines.  Also post
> the output of "ls -l /proc/<pid>/fd" where <pid> is QEMU's pid.
>
> 3) if the output of "strace -e poll" hangs, instead, run it under gdb
> and post a backtrace.  Perhaps continue the process a few times and
> check if the backtrace remains the same or changes.
>
> Paolo
>


[-- Attachment #2: Type: text/html, Size: 15134 bytes --]