[Qemu-devel] Re: [kvm-devel] [PATCH 0/4] Rework alarm timer infrastrucure - take2

[Avi Kivity <avi@qumranet.com>]

Luca Tettamanti wrote:

> Actually I'm having troubles with cyclesoak (probably it's calibration),
> numbers are not very stable across multiple runs...
>   

I've had good results with cyclesoak; maybe you need to run it in
runlevel 3 so the load generated by moving the mouse or breathing
doesn't affect meaurements.

> I've also tried APC which was suggested by malc[1] and:
> - readings are far more stable
> - the gap between dynticks and non-dynticks seems not significant
>
>   
>> Can you verify this by running
>>
>>    strace -c -p `pgrep qemu` & sleep 10; pkill strace
>>
>> for all 4 cases, and posting the results?
>>     
>
> Plain QEMU:
>
> With dynticks:
>
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ----------------
>  57.97    0.000469           0     13795           clock_gettime
>  32.88    0.000266           0      1350           gettimeofday
>   7.42    0.000060           0      1423      1072 sigreturn
>   1.73    0.000014           0      5049           timer_gettime
>   0.00    0.000000           0      1683      1072 select
>   0.00    0.000000           0      2978           timer_settime
> ------ ----------- ----------- --------- --------- ----------------
> 100.00    0.000809                 26278      2144 total
>   

The 1072 select() errors are the delivered ticks (EINTR).  But why only
1000?  would have expected 10000 for a 1000Hz guest in a 10 sec period.

> HPET:
>
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ----------------
>  87.48    0.010459           1     10381     10050 select
>   8.45    0.001010           0     40736           clock_gettime
>   2.73    0.000326           0     10049           gettimeofday
>   1.35    0.000161           0     10086     10064 sigreturn
> ------ ----------- ----------- --------- --------- ----------------
> 100.00    0.011956                 71252     20114 total
>   

This is expected.  1 tick per millisecond.

> Unix (SIGALRM):
>
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ----------------
>  90.36    0.011663           1     10291      9959 select
>   7.38    0.000953           0     40355           clock_gettime
>   2.05    0.000264           0      9960           gettimeofday
>   0.21    0.000027           0      9985      9969 sigreturn
> ------ ----------- ----------- --------- --------- ----------------
> 100.00    0.012907                 70591     19928 total
>   

Same here.

> And KVM:
>
> dynticks:
>
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ----------------
>  78.90    0.004001           1      6681      5088 rt_sigtimedwait
>  10.87    0.000551           0     27901           clock_gettime
>   4.93    0.000250           0      7622           timer_settime
>   4.30    0.000218           0     10078           timer_gettime
>   0.39    0.000020           0      3863           gettimeofday
>   0.35    0.000018           0      6054           ioctl
>   0.26    0.000013           0      4196           select
>   0.00    0.000000           0      1593           rt_sigaction
> ------ ----------- ----------- --------- --------- ----------------
> 100.00    0.005071                 67988      5088 total
>   

kvm uses sigtimedwait() to wait for signals.  Here, an error (ETIMEDOUT)
indicates we did _not_ get a wakeup, so there are 1500 wakeups in a 10
second period.  Strange.  Some calibration error?

> HPET:
>
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ----------------
>  90.20    0.011029           0     32437     22244 rt_sigtimedwait
>   4.46    0.000545           0     44164           clock_gettime
>   2.59    0.000317           0     12128           gettimeofday
>   1.50    0.000184           0     10193           rt_sigaction
>   1.10    0.000134           0     12461           select
>   0.15    0.000018           0      6060           ioctl
> ------ ----------- ----------- --------- --------- ----------------
> 100.00    0.012227                117443     22244 total
>   

10K wakeups per second.  The code is not particularly efficient (11
syscalls per tick), but overhead is still low.

> Unix:
>
> % time     seconds  usecs/call     calls    errors syscall
> ------ ----------- ----------- --------- --------- ----------------
>  83.29    0.012522           0     31652     21709 rt_sigtimedwait
>   6.91    0.001039           0     43125           clock_gettime
>   3.50    0.000526           0      6042           ioctl
>   2.74    0.000412           0      9943           rt_sigaction
>   1.98    0.000298           0     12183           select
>   1.58    0.000238           0     11850           gettimeofday
> ------ ----------- ----------- --------- --------- ----------------
> 100.00    0.015035                114795     21709 total
>   

Same thing.

> The guest is an idle kernel with HZ=1000.
>   

Can you double check this?  The dyntick results show that this is either
a 100Hz kernel, or that there is a serious bug in dynticks.

-- 
Do not meddle in the internals of kernels, for they are subtle and quick to panic.