Bug? 100% load on core after physically removing USB storage from host

Bug? 100% load on core after physically removing USB storage from host

[Emmanuel Noobadmin]

After removing a USB flash drive using virtual machine manager, I
notice that the core assigned to the VM guest goes up to 100% load.
Within the guest itself, there is no significant activity.

This also prompted me to look at the other physical machine from which
I used the USB flash drive to transfer files. And it was also
exhibiting the same problem.

Installed versions are
qemu-kvm-0.12.1.2-2.209.el6_2.5.x86_64
on CentOS 6.2, 2.6.32-220.17.1.el6.x86_64 (Intel C204 PCH)

qemu-kvm-0.12.1.2-2.209.el6_2.4.x86_64
on SLES 6, 2.6.32-220.7.1.el.x86_64  (Intel 82801JI ICH10)

There are no error messages in the log files and things seem to be
working except for the fully loaded core.

After some testing, the only steps needed are
1. VMM add physical host usb device -> select storage to guest
2. VMM remove hardware
3. Physically remove the USB storage from the host, thread/core
assigned to guest goes 100%

Repeating the same steps without restarting the guest causes cpu
utilization to drop back to normal for about a second or so before
going back up again.

Problem goes away if I restart the guest. As both machines are based
off RHEL, I checked Redhat bugtrack but don't seem to be anything
related except one related to hotplug/unplugging a USB controller more
than 1000 times.

Is this is a bug or there is actually something else I am supposed to
do before removing a physical device from a guest?

Also is there anyway I get the core/thread back to normal without
restarting the guest?

Re: Bug? 100% load on core after physically removing USB storage from host

[Stefan Hajnoczi]

On Tue, Jun 12, 2012 at 6:02 AM, Emmanuel Noobadmin
<centos.admin@gmail.com> wrote:
> After removing a USB flash drive using virtual machine manager, I
> notice that the core assigned to the VM guest goes up to 100% load.
> Within the guest itself, there is no significant activity.
>
> This also prompted me to look at the other physical machine from which
> I used the USB flash drive to transfer files. And it was also
> exhibiting the same problem.
>
> Installed versions are
> qemu-kvm-0.12.1.2-2.209.el6_2.5.x86_64
> on CentOS 6.2, 2.6.32-220.17.1.el6.x86_64 (Intel C204 PCH)
>
> qemu-kvm-0.12.1.2-2.209.el6_2.4.x86_64
> on SLES 6, 2.6.32-220.7.1.el.x86_64  (Intel 82801JI ICH10)
>
> There are no error messages in the log files and things seem to be
> working except for the fully loaded core.
>
> After some testing, the only steps needed are
> 1. VMM add physical host usb device -> select storage to guest
> 2. VMM remove hardware
> 3. Physically remove the USB storage from the host, thread/core
> assigned to guest goes 100%

Two clarifications:

1. Can you confirm that the 100% CPU utilization only happens in Step
#3?  For example, if it happened in Step #2 that would suggest the
guest is entering a loop.  Step #3 suggests the host is entering a
loop.

2. Please run top(1) on the host during high CPU utilization to
confirm which process is causing high CPU utilization.

CCed Gerd who is USB maintainer.

Stefan

Re: Bug? 100% load on core after physically removing USB storage from host

[Emmanuel Noobadmin]

On 6/12/12, Stefan Hajnoczi <stefanha@gmail.com> wrote:
>> After some testing, the only steps needed are
>> 1. VMM add physical host usb device -> select storage to guest
>> 2. VMM remove hardware
>> 3. Physically remove the USB storage from the host, thread/core
>> assigned to guest goes 100%
>
> Two clarifications:
>
> 1. Can you confirm that the 100% CPU utilization only happens in Step
> #3?  For example, if it happened in Step #2 that would suggest the
> guest is entering a loop.  Step #3 suggests the host is entering a
> loop.

Yes, it's confirmed that #3 has to be done. I've top running in both
guest and host when replicating this. If left physically attached to
the host machine, nothing unusual happens. The change in load level is
almost immediate upon physical removal.

Within the guest, the loads are basically 0, single core very lightly
loaded guest. In the host, top shows 100% cpu utilization on the
relevant qemu-kvm process. Unfortunately, I did not think to use the
(1) key to display the individual physical core so can't say if it was
really just loading on that core.

The only thing possibly relevant data is that on the SLES set, I had
the VM pinned to a specific core, the VMM gui shows a load graph of
only 25%. On the Centos 6.2 set, it was not pinned specifically and
the load graph goes to 100%. But in both cases, top output shows 100%
for the process.


> 2. Please run top(1) on the host during high CPU utilization to
> confirm which process is causing high CPU utilization.

Not physically at the machines now so I can only verify this tomorrow.

Re: Bug? 100% load on core after physically removing USB storage from host

[Emmanuel Noobadmin]

On 6/12/12, Stefan Hajnoczi <stefanha@gmail.com> wrote:

Further tests done on the following set only
>> qemu-kvm-0.12.1.2-2.209.el6_2.4.x86_64
>> on SLES 6, 2.6.32-220.7.1.el.x86_64  (Intel 82801JI ICH10)

>> 1. VMM add physical host usb device -> select storage to guest
>> 2. VMM remove hardware
>> 3. Physically remove the USB storage from the host, thread/core
>> assigned to guest goes 100%
>
> Two clarifications:
>
> 1. Can you confirm that the 100% CPU utilization only happens in Step
> #3?  For example, if it happened in Step #2 that would suggest the
> guest is entering a loop.  Step #3 suggests the host is entering a
> loop.

Verified Step #3 triggers the issue.

> 2. Please run top(1) on the host during high CPU utilization to
> confirm which process is causing high CPU utilization.

Verified is the VM's process. If unpinned, the utilization floats
around the cores, if pinned, the 100% load stays with the physical
core. Load on the core stabilizes at around 32% usr 67% sys if the VM
is active. Pausing the VM makes it go to around 80+ sys.


Other info
selinux: no difference between enforcing/permissive

Does NOT happen if Step #2 is not done. i.e. simply yanking the USB
drive physically gives no problem. The PCI-USB device must be removed
from the guest in order for this to trigger.

Re: Bug? 100% load on core after physically removing USB storage from host

[Stefan Hajnoczi]

On Wed, Jun 13, 2012 at 8:23 AM, Emmanuel Noobadmin
<centos.admin@gmail.com> wrote:
> On 6/12/12, Stefan Hajnoczi <stefanha@gmail.com> wrote:
>
> Further tests done on the following set only
>>> qemu-kvm-0.12.1.2-2.209.el6_2.4.x86_64
>>> on SLES 6, 2.6.32-220.7.1.el.x86_64  (Intel 82801JI ICH10)
>
>>> 1. VMM add physical host usb device -> select storage to guest
>>> 2. VMM remove hardware
>>> 3. Physically remove the USB storage from the host, thread/core
>>> assigned to guest goes 100%
>>
>> Two clarifications:
>>
>> 1. Can you confirm that the 100% CPU utilization only happens in Step
>> #3?  For example, if it happened in Step #2 that would suggest the
>> guest is entering a loop.  Step #3 suggests the host is entering a
>> loop.
>
> Verified Step #3 triggers the issue.
>
>> 2. Please run top(1) on the host during high CPU utilization to
>> confirm which process is causing high CPU utilization.
>
> Verified is the VM's process. If unpinned, the utilization floats
> around the cores, if pinned, the 100% load stays with the physical
> core. Load on the core stabilizes at around 32% usr 67% sys if the VM
> is active. Pausing the VM makes it go to around 80+ sys.

Since system time is a large chunk you could use strace -f -p $(pgrep
qemu-kvm) or other system call tracing tools to see what the qemu-kvm
process is doing.

You didn't say that the guest is frozen, so QEMU is probably not in an
infinite loop.  Instead it may be that we have a USB device file
descriptor in select(2) and continually read -ENODEV or similar from
it.  So the guest can make progress but you see high %sys CPU load on
the host.  strace(1) can confirm what's going on.

Stefan

RE: Bug? 100% load on core after physically removing USB storage from host

[Veruca Salt]

> >>> qemu-kvm-0.12.1.2-2.209.el6_2.4.x86_64

We had the same problem with 0.13
We were using it on Sandy Bridge motherboards when it happened. It was an issue then, but we hanged to 1.0 a long time ago.
Why are you using 0.12 years after it was replaced?
> More majordomo info at http://vger.kernel.org/majordomo-info.html
 		 	   		  

Re: Bug? 100% load on core after physically removing USB storage from host

[Emmanuel Noobadmin]

On 6/13/12, Stefan Hajnoczi <stefanha@gmail.com> wrote:
>Since system time is a large chunk you could use strace -f -p $(pgrep
>qemu-kvm) or other system call tracing tools to see what the qemu-kvm
>process is doing.

The command you gave didn't work so I replace $(pgrep) with PID of the
process running the VM after checking that -p was the PID option.

strace -f -p 19424 produces the following repeating lines

[pid 19424] ioctl(0, USBDEVFS_REAPURBNDELAY, 0x7fff8fc43d48) = -1
ENOTTY (Inappropriate ioctl for device)
[pid 19424] timer_gettime(0x2, {it_interval={0, 0}, it_value={0, 0}}) = 0
[pid 19424] timer_settime(0x2, 0, {it_interval={0, 0}, it_value={0,
250000}}, NULL) = 0
[pid 19424] timer_gettime(0x2, {it_interval={0, 0}, it_value={0, 196501}}) = 0
[pid 19424] select(27, [7 10 15 18 20 21 22 23 24 25 26], [16], [],
{1, 0}) = 3 (in [7 18], out [16], left {0, 999995})
[pid 19424] read(18, "\1\0\0\0\0\0\0\0", 4096) = 8
[pid 19424] read(18, 0x7fff8fc42d50, 4096) = -1 EAGAIN (Resource
temporarily unavailable)
[pid 19424] ioctl(0, USBDEVFS_REAPURBNDELAY, 0x7fff8fc43d48) = -1
ENOTTY (Inappropriate ioctl for device)
[pid 19424] read(7, "\0", 512)          = 1
[pid 19424] read(7, 0x7fff8fc43b50, 512) = -1 EAGAIN (Resource
temporarily unavailable)
[pid 19424] select(27, [7 10 15 18 20 21 22 23 24 25 26], [16], [],
{1, 0}) = 2 (in [20], out [16], left {0, 999994})
[pid 19424] read(20,
"\16\0\0\0\0\0\0\0\376\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0"...,
128) = 128
[pid 19424] rt_sigaction(SIGALRM, NULL, {0x7f5d28f6faa0, ~[KILL STOP
RTMIN RT_1], SA_RESTORER, 0x7f5d288d94a0}, 8) = 0
[pid 19424] write(8, "\0", 1)           = 1
[pid 19424] write(19, "\1\0\0\0\0\0\0\0", 8) = 8
[pid 19424] read(20, 0x7fff8fc43cc0, 128) = -1 EAGAIN (Resource
temporarily unavailable)
[pid 19424] ioctl(0, USBDEVFS_REAPURBNDELAY, 0x7fff8fc43d48) = -1
ENOTTY (Inappropriate ioctl for device)

Re: Bug? 100% load on core after physically removing USB storage from host

[Emmanuel Noobadmin]

On 6/14/12, Veruca Salt <verucasaltuk@hotmail.co.uk> wrote:
>> >>> qemu-kvm-0.12.1.2-2.209.el6_2.4.x86_64
>
> We had the same problem with 0.13
> We were using it on Sandy Bridge motherboards when it happened. It was an
> issue then, but we hanged to 1.0 a long time ago.
> Why are you using 0.12 years after it was replaced?

It's the default on the EL6 based distributions I think, and I don't
really want to change from the defaults unless I really have and 0.12
worked fine so far. This bug is a minor inconvenience but nothing
show-stopping yet.

Plus I'm not a full time server admin and diverging from the standard
stack tends to backfire on me later especially if I overlook noting
down some minor but crucial detail :D

RE: Bug? 100% load on core after physically removing USB storage from host

[Veruca Salt]

----------------------------------------
> Date: Sat, 16 Jun 2012 13:19:53 +0800
> Subject: Re: Bug? 100% load on core after physically removing USB storage from host
> From: centos.admin@gmail.com
> To: verucasaltuk@hotmail.co.uk
> CC: stefanha@gmail.com; kvm@vger.kernel.org; kraxel@redhat.com
>
> On 6/14/12, Veruca Salt <verucasaltuk@hotmail.co.uk> wrote:
> >> >>> qemu-kvm-0.12.1.2-2.209.el6_2.4.x86_64
> >
> > We had the same problem with 0.13
> > We were using it on Sandy Bridge motherboards when it happened. It was an
> > issue then, but we hanged to 1.0 a long time ago.
> > Why are you using 0.12 years after it was replaced?
>
> It's the default on the EL6 based distributions I think, and I don't
> really want to change from the defaults unless I really have and 0.12
> worked fine so far. This bug is a minor inconvenience but nothing
> show-stopping yet.
>
> Plus I'm not a full time server admin and diverging from the standard
> stack tends to backfire on me later especially if I overlook noting
> down some minor but crucial detail :D

Ah, I see. I don't know how to help; we are using custom hosts, so upgrading is the first thing we try rather than the last.
 		 	   		  

Re: Bug? 100% load on core after physically removing USB storage from host

[Stefan Hajnoczi]

On Sat, Jun 16, 2012 at 6:16 AM, Emmanuel Noobadmin
<centos.admin@gmail.com> wrote:
> On 6/13/12, Stefan Hajnoczi <stefanha@gmail.com> wrote:
>>Since system time is a large chunk you could use strace -f -p $(pgrep
>>qemu-kvm) or other system call tracing tools to see what the qemu-kvm
>>process is doing.
>
> The command you gave didn't work so I replace $(pgrep) with PID of the
> process running the VM after checking that -p was the PID option.
>
> strace -f -p 19424 produces the following repeating lines
>
> [pid 19424] ioctl(0, USBDEVFS_REAPURBNDELAY, 0x7fff8fc43d48) = -1
> ENOTTY (Inappropriate ioctl for device)

This looks suspicious: QEMU is calling ioctl() on standard input (fd
0) with a USB operation code.  The USB layer probably set the
USBHostDevice->fd field to 0 or freed USBHostDevice but left the
async_complete() select(2) handler registered on file descriptor 16.

I believe the call is coming from hw/usb/host-linux.c:async_complete()
but am not using the same source tree as your qemu-kvm so I could be
off.  The code suggests that QEMU also logs an error message
("USBDEVFS_REAPURBNDELAY: Inappropriate ioctl for device") when this
happens.  If you want, check the libvirt log file for this guest - it
probably has tons of these messages in it.

Gerd: Does this give you enough information to recognize whether this
has already been fixed in qemu.git or how to fix it?

Emmanuel: You mentioned that upgrading to a newer version might not be
worth it, but if you're willing to test qemu.git/master just to see if
the problem has already been fixed then that would be helpful.
http://wiki.qemu.org/Download

Stefan

Re: Bug? 100% load on core after physically removing USB storage from host

[Emmanuel Noobadmin]

On 6/18/12, Stefan Hajnoczi <stefanha@gmail.com> wrote:
> off.  The code suggests that QEMU also logs an error message
> ("USBDEVFS_REAPURBNDELAY: Inappropriate ioctl for device") when this
> happens.  If you want, check the libvirt log file for this guest - it
> probably has tons of these messages in it.

I'll check for the above log entries when I next get to that site.

> Emmanuel: You mentioned that upgrading to a newer version might not be
> worth it, but if you're willing to test qemu.git/master just to see if
> the problem has already been fixed then that would be helpful.
> http://wiki.qemu.org/Download

I could try this, since the original host is actually being
repurposed, which was why I was doing some data transfer via USB. So
it would be OK to play with a newer versions when I go there next.

Re: Bug? 100% load on core after physically removing USB storage from host

[Emmanuel Noobadmin]

On 6/18/12, Stefan Hajnoczi <stefanha@gmail.com> wrote:
> I believe the call is coming from hw/usb/host-linux.c:async_complete()
> but am not using the same source tree as your qemu-kvm so I could be
> off.  The code suggests that QEMU also logs an error message
> ("USBDEVFS_REAPURBNDELAY: Inappropriate ioctl for device") when this
> happens.  If you want, check the libvirt log file for this guest - it
> probably has tons of these messages in it.

I did not have time to try a new version of QEMU but manage to check
do one plug/pull test. However, there was no error message in the
guest log. The last line in the guest log while this was happening was
this and nothing else subsequently.
husb: 1 interfaces claimed for configuration 1

Re: Bug? 100% load on core after physically removing USB storage from host

[Stefan Hajnoczi]

On Wed, Jun 20, 2012 at 10:40 AM, Emmanuel Noobadmin
<centos.admin@gmail.com> wrote:
> On 6/18/12, Stefan Hajnoczi <stefanha@gmail.com> wrote:
>> I believe the call is coming from hw/usb/host-linux.c:async_complete()
>> but am not using the same source tree as your qemu-kvm so I could be
>> off.  The code suggests that QEMU also logs an error message
>> ("USBDEVFS_REAPURBNDELAY: Inappropriate ioctl for device") when this
>> happens.  If you want, check the libvirt log file for this guest - it
>> probably has tons of these messages in it.
>
> I did not have time to try a new version of QEMU but manage to check
> do one plug/pull test. However, there was no error message in the
> guest log. The last line in the guest log while this was happening was
> this and nothing else subsequently.
> husb: 1 interfaces claimed for configuration 1

Okay, perhaps the ioctl() call is coming from elsewhere or your
version of qemu-kvm doesn't print an error (my source tree is
qemu.git/master).

Anyway, once you've tried qemu.git/master we'll know whether the bug
still exists and with all the info you've shared maybe Gerd (USB
maintainer) will know what the issue is.

Stefan

Re: Bug? 100% load on core after physically removing USB storage from host

[Emmanuel Noobadmin]

On 6/20/12, Stefan Hajnoczi <stefanha@gmail.com> wrote:
> Anyway, once you've tried qemu.git/master we'll know whether the bug
> still exists and with all the info you've shared maybe Gerd (USB
> maintainer) will know what the issue is.

Sadly, my noobness meant during the hours I had onsite, I could only
get libvirt compiled but could not get thngs to work. There were some
errors about qemu need to be compiled with/for kalj, unknown OS hvm
and then a whole bunch of other errors when I try to connect to
qemu/kvm. The only time things loaded, turned out to be another noob
error that ended up with 0.8.7 loaded instead of the git version.

Pretty much expected and largely why I dread any witch from stock :D

Unfortunately, I have to get this machine repurposed over this weekend
so unlikely I will have time to figure out how to install a newer
version of libvirt. So hopefully the problem was fixed or somebody
else could replicate this with better success.

Re: Bug? 100% load on core after physically removing USB storage from host

[Stefan Hajnoczi]

On Thu, Jun 21, 2012 at 2:49 PM, Emmanuel Noobadmin
<centos.admin@gmail.com> wrote:
> On 6/20/12, Stefan Hajnoczi <stefanha@gmail.com> wrote:
>> Anyway, once you've tried qemu.git/master we'll know whether the bug
>> still exists and with all the info you've shared maybe Gerd (USB
>> maintainer) will know what the issue is.
>
> Sadly, my noobness meant during the hours I had onsite, I could only
> get libvirt compiled but could not get thngs to work. There were some
> errors about qemu need to be compiled with/for kalj, unknown OS hvm
> and then a whole bunch of other errors when I try to connect to
> qemu/kvm. The only time things loaded, turned out to be another noob
> error that ended up with 0.8.7 loaded instead of the git version.
>
> Pretty much expected and largely why I dread any witch from stock :D
>
> Unfortunately, I have to get this machine repurposed over this weekend
> so unlikely I will have time to figure out how to install a newer
> version of libvirt. So hopefully the problem was fixed or somebody
> else could replicate this with better success.

Thanks for investigating and sharing the information you've found.
It's archived on the list so anyone who hits it in the future or wants
to reproduce it can try.

Stefan

Re: Bug? 100% load on core after physically removing USB storage from host

[Emmanuel Noobadmin]

On 6/22/12, Stefan Hajnoczi <stefanha@gmail.com> wrote:
> Thanks for investigating and sharing the information you've found.
> It's archived on the list so anyone who hits it in the future or wants
> to reproduce it can try.

I decided to give it one more try before I formatted that machine and
tried the rpm method. Thankfully, with libvirt-0.9.12.tar.gz, it
appeared to install correctly on my first try. Both virsh --version
and libvirtd --version reporting 0.9.12 so I assumed the VMs are
running on the newer libvirt.

However the problem still exists so at least until that version, it
does not appear to had been resolved.

Re: Bug? 100% load on core after physically removing USB storage from host

[Stefan Hajnoczi]

On Sat, Jun 23, 2012 at 7:08 AM, Emmanuel Noobadmin
<centos.admin@gmail.com> wrote:
> On 6/22/12, Stefan Hajnoczi <stefanha@gmail.com> wrote:
>> Thanks for investigating and sharing the information you've found.
>> It's archived on the list so anyone who hits it in the future or wants
>> to reproduce it can try.
>
> I decided to give it one more try before I formatted that machine and
> tried the rpm method. Thankfully, with libvirt-0.9.12.tar.gz, it
> appeared to install correctly on my first try. Both virsh --version
> and libvirtd --version reporting 0.9.12 so I assumed the VMs are
> running on the newer libvirt.
>
> However the problem still exists so at least until that version, it
> does not appear to had been resolved.

I had a quick chat with Gerd on IRC the other day about this issue.
He mentioned that a lot of changes have been made to QEMU USB
emulation and that there is a fair chance this issue is fixed in
qemu.git/master.

Stefan