|
From: | Michael R. Hines |
Subject: | Re: [Qemu-devel] latest master: major slowdown (something spinning?) |
Date: | Fri, 12 Apr 2013 23:19:10 -0400 |
User-agent: | Mozilla/5.0 (X11; Linux i686; rv:17.0) Gecko/20130106 Thunderbird/17.0.2 |
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 |
[Prev in Thread] | Current Thread | [Next in Thread] |