Re: high load with usb device

[Michael Tokarev <mjt@tls.msk.ru>]

14.09.2010 13:08, Avi Kivity wrote:
>>  On 09/14/2010 08:51 AM, Michael Tokarev wrote:
>>> 12.09.2010 13:26, Avi Kivity пишет:
>>> Guest: 0 load
>>> Host:
>>> Cpu(s):  5.3%us,  6.7%sy,  0.0%ni, 88.0%id,  0.0%wa,  0.0%hi, 
>>> 0.0%si,  0.0%st
>>>    PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
>>> 25685 mjt       20   0 1074m 109m 4652 S   19  1.9   0:29.03
>>> qemu-system-x86
>>>
>>> So it appears it's the qemu process that's doing something,
>>> after all.  Is there a way to compile it with profiling
>>> information?  I tried, but it does not compile: it uses
>>> -fomit-frame-pointer which is not compatible with -p[g],
>>> but when removing -fo-f-p it complains about assembly.
>>
>> Really, 'perf top' should have shown what qemu was doing.  I don't
>> have a lot of experience with profiling userspace, copying
>> linux-perf-users for tips.

`perf top' shows nothing interesting.  Here it is:

-----------------------------------------------------------------------------------------
   PerfTop:    1161 irqs/sec  kernel:93.7%  exact:  0.0% [1000Hz cycles],  (all, 2 CPUs)
-----------------------------------------------------------------------------------------

             samples  pcnt function                       DSO
             _______ _____ ______________________________ __________________

            12345.00 74.4% native_safe_halt               [kernel.kallsyms]
              224.00  1.4% hpet_next_event                [kernel.kallsyms]
              178.00  1.1% tick_dev_program_event         [kernel.kallsyms]
              125.00  0.8% tick_broadcast_oneshot_control [kernel.kallsyms]
              113.00  0.7% do_select                      [kernel.kallsyms]
              105.00  0.6% delay_tsc                      [kernel.kallsyms]
               94.00  0.6% schedule                       [kernel.kallsyms]
               79.00  0.5% ktime_get                      [kernel.kallsyms]
               78.00  0.5% main_loop_wait                 qemu-system-x86_64
               75.00  0.5% __hrtimer_start_range_ns       [kernel.kallsyms]
               69.00  0.4% tick_nohz_stop_sched_tick      [kernel.kallsyms]
               61.00  0.4% rb_erase                       [kernel.kallsyms]
               58.00  0.3% _raw_spin_unlock_irqrestore    [kernel.kallsyms]
               55.00  0.3% _raw_spin_lock_irqsave         [kernel.kallsyms]
               54.00  0.3% enqueue_hrtimer                [kernel.kallsyms]
               54.00  0.3% __switch_to                    [kernel.kallsyms]
               49.00  0.3% ia32_syscall                   [kernel.kallsyms]

I started perf after guest were running for some time, and waited
for about a minute for perf to get proper stats.

Here's vmstat on host, when an idle linux guest is running with usbdevice:

procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 1  0      0 306744 1213984 1376000    0    0     1     0 5531 4114  4  5 91  0
 1  0      0 306356 1213996 1375972    0    0     0     0 5886 4229  4  6 90  0

when linux guest is running w/o -usbdevice:

 1  0      0 303604 1214116 1376388    0    0     0     9  986  623  1  2 97  0
 1  0      0 303356 1214116 1376340    0    0     0     0  946  600  2  1 96  0

when no guest running:

 1  0      0 415048 1214000 1374860    0    0     0     9  821  481  2  2 96  0
 0  0      0 415056 1214000 1374868    0    0     0     0  717  454  1  1 98  0

> Also, please strace qemu.  Try 'strace -p $pid1 -p $pid2 -p $pid3 -c' to
> get a summary.

There are only two qemu threads running (as shown in /proc/$pid/task).  Here's
a sample (after hitting Ctrl+C):

# strace -p 23020 -p 23023 -c
Process 23020 attached - interrupt to quit
Process 23023 attached - interrupt to quit
^CProcess 23020 detached
Process 23023 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 98.98   23.462158       15569      1507           ioctl
  0.64    0.151725          37      4063         5 futex
  0.11    0.025051           0     86932           select
  0.09    0.021188           0    408836           clock_gettime
  0.07    0.016543           0    271933    136484 read
  0.04    0.008958           0    181118           gettimeofday
  0.02    0.005756           0    101190           write
  0.02    0.005506           0     89180           timer_settime
  0.02    0.004754           0     96271           timer_gettime
  0.01    0.002682           0     50595           rt_sigaction
  0.00    0.000000           0         1           rt_sigpending
  0.00    0.000000           0         1         1 rt_sigtimedwait
------ ----------- ----------- --------- --------- ----------------
100.00   23.704321               1291627    136490 total

(Note that during strace run the CPU is >100% busy -- top(1)
reports 65% for strace and 45% for the qemu process).

Thanks!

/mjt