All of lore.kernel.org
 help / color / mirror / Atom feed
From: "Michael R. Hines" <mrhines@linux.vnet.ibm.com>
To: Paolo Bonzini <pbonzini@redhat.com>
Cc: "qemu-devel@nongnu.org" <qemu-devel@nongnu.org>
Subject: Re: [Qemu-devel] latest master: major slowdown (something spinning?)
Date: Fri, 12 Apr 2013 23:19:10 -0400	[thread overview]
Message-ID: <5168CEAE.6000306@linux.vnet.ibm.com> (raw)
In-Reply-To: <51655F3A.3070703@redhat.com>

[-- 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 --]

      parent reply	other threads:[~2013-04-13  3:19 UTC|newest]

Thread overview: 6+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2013-04-09 17:43 [Qemu-devel] latest master: major slowdown (something spinning?) Michael R. Hines
2013-04-10  7:43 ` Paolo Bonzini
2013-04-10 12:43   ` Michael R. Hines
2013-04-10 12:46     ` Paolo Bonzini
2013-04-10 13:16       ` Michael R. Hines
2013-04-13  3:19       ` Michael R. Hines [this message]

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=5168CEAE.6000306@linux.vnet.ibm.com \
    --to=mrhines@linux.vnet.ibm.com \
    --cc=pbonzini@redhat.com \
    --cc=qemu-devel@nongnu.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.