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
>