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

[Michael R. Hines]

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