Re: high load with usb device

[Avi Kivity <avi@redhat.com>]

  On 09/14/2010 06:29 PM, Michael Tokarev wrote:
> 14.09.2010 20:00, Avi Kivity wrote:
> >>  As I mentioned in other emails in this thread:
> >>
> >>  o yes, I do have CONFIG_EVENTFD set, and it is being used
> >>     too (fd#12 in the above strace).
> >
> >  I thought that was the signalfd.
>
> Uh. Yes, it was, i confused the two.  And yes, CONFIG_EVENTFD is
> set and used too.
>
> $ grep FD= config-host.mak
> CONFIG_EVENTFD=y
> CONFIG_SIGNALFD=y
>
> >>  o 0.13.0-rc1 behaves the same way (that is, it also shows
> >>     high load when idle -- the same 18% of host CPU), but it
> >>     has no pipe on fd#5.
> >
> >  I think it's host_alarm_handler()'s use of qemu_notify_event().  It's
> >  telling the main loop to rescan pending events, even though it's called
> >  from the main loop itself.  Please drop it and rerun.
>
> Without qemu_notify_event() in host_alarm_handler():
>
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ----------------
>   98.96   48.184832       13747      3505           ioctl
>    0.39    0.191613          25      7745        28 futex
>    0.37    0.181032           1    173192           select
>    0.09    0.045379           0    980369           clock_gettime
>    0.05    0.024362           0    351024    173220 read
>    0.05    0.023247           0    487766           gettimeofday
>    0.04    0.017996           0    319428           timer_gettime
>    0.03    0.013837           0    198267           timer_settime
>    0.02    0.010036           0    177790           rt_sigaction
>    0.00    0.000000           0         1           writev
>    0.00    0.000000           0         2           poll
>    0.00    0.000000           0         1           rt_sigpending
>    0.00    0.000000           0         1         1 rt_sigtimedwait
> ------ ----------- ----------- --------- --------- ----------------
> 100.00   48.692334               2699091    173249 total
>
> The picture is pretty similar to the one before :)
> (And yes, I'm sure I've run the right binary).

No more writes, and read() is cut to twice select() (due to the need to 
see a 0, we can probably elimate it if we know it's a real eventfd), 
somewhat fewer select()s.

What's the cpu load?

> But it looks like we're barking the wrong tree.  It's spending
> 99% time in ioctl.  Yes, there's quite large amount of reads
> and gettimes, but they're taking very small time, even combined.
>
> It is still spending much more time in the ioctl (apparently in
> kvm_run).

That time includes guest sleep time, not just cpu time, so it isn't an 
indicator.

> For comparison, here's the same strace stats without -usbdevice:
>
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ----------------
>   97.70    0.080237          22      3584           select
>    1.09    0.000895           0      6018      3584 read
>    0.33    0.000271           0      9670           clock_gettime
>    0.31    0.000254           0      6086           gettimeofday
>    0.26    0.000210           0      2432           rt_sigaction
>    0.17    0.000137           0      3653           timer_gettime
>    0.15    0.000122           0      2778           timer_settime
>    0.00    0.000000           0         1           ioctl
>    0.00    0.000000           0         1           rt_sigpending
>    0.00    0.000000           0         1         1 rt_sigtimedwait
> ------ ----------- ----------- --------- --------- ----------------
> 100.00    0.082126                 34224      3585 total
>
> Yes, it is still doing lots of unnecessary stuff, but the load
> is<1%.
>
> (This is without host_alarm_handler() in qemu_notify_event())
>
>

I guess it only saw a single ioctl, so it didn't measure it.  Ping the 
guest and you'll see ioctl times surge back.

-- 
error compiling committee.c: too many arguments to function