Re: [PATCH v2 2/3] KVM: x86: add tracepoints to trace mmio begin and complete

[Xiao Guangrong <xiaoguangrong.eric@gmail.com>]

On 02/03/2012 02:27 AM, Xiao Guangrong wrote:

> On 02/03/2012 01:56 AM, Avi Kivity wrote:
> 
>> On 02/02/2012 07:55 PM, Xiao Guangrong wrote:
>>> On 02/03/2012 01:36 AM, Avi Kivity wrote:
>>>
>>>> On 02/02/2012 07:27 PM, Xiao Guangrong wrote:
>>>>> From: Xiao Guangrong <xiaoguangrong@linux.vnet.ibm.com>
>>>>>
>>>>> 'perf kvm-events' will use kvm_exit and kvm_mmio(read...) to calculate
>>>>> mmio read emulated time for the old kernel, in order to trace mmio read
>>>>> event more exactly, we add kvm_mmio_begin to trace the time when mmio read
>>>>> begins
>>>>>
>>>>> Also, add kvm_mmio_done to trace the time when mmio/pio is completed
>>>>
>>>> Previously, we discussed using the kvm_entry to do this.  This reduces
>>>> the number of tracepoints, and is backwards compatible.  What was the
>>>> conclusion?
>>>>
>>>
>>>
>>> Since using kvm_entry can cause lots of unnecessary calculated, these new two
>>> tracepoints can let the result be exacter.
>>
>> Do you have numbers on the ratio between kvm_entry traces and
>> kvm_mmio_begin/end traces?
>>
> 
> 
> 1: Using kvm_mmio_begin/end:
> 
> # ./perf kvm-events report --event mmio
>   Warning: Error: expected type 5 but read 4
>   Warning: Error: expected type 5 but read 0
>   Warning: unknown op '}'
> 
> 
> Analyze events for all VCPUs:
> 
>          MMIO Access    Samples  Samples%     Time%         Avg time
> 
>         0xfee00380:W      54926    58.45%    57.32%      3.90us ( +-   0.29% )
>         0xfee00300:W      12906    13.73%    28.70%      8.32us ( +-   0.50% )
>         0xfee00300:R      12906    13.73%     7.68%      2.23us ( +-   1.27% )
>         0xfee00310:W      12906    13.73%     6.07%      1.76us ( +-   1.05% )
>         0xfee00190:R        323     0.34%     0.23%      2.65us ( +-   2.85% )
> 
> Total Samples:93967, Total events handled time:374012.26us.
> 
> 2: kvm_mmio_begin/end is not used:
> 
> # ./perf kvm-events report --event mmio
>   Warning: Error: expected type 5 but read 4
>   Warning: Error: expected type 5 but read 0
>   Warning: unknown op '}'
> 
> 
> Analyze events for all VCPUs:
> 
>          MMIO Access    Samples  Samples%     Time%         Avg time
> 
>         0xfee00380:W      54926    58.45%    42.90%      3.90us ( +-   0.29% )
>         0xfee00300:W      12906    13.73%    21.48%      8.32us ( +-   0.50% )
>         0xfee00300:R      12906    13.73%    30.26%     11.72us ( +-   1.40% )
>         0xfee00310:W      12906    13.73%     4.54%      1.76us ( +-   1.05% )
>         0xfee00190:R        323     0.34%     0.82%     12.63us ( +-   2.85% )
> 
> Total Samples:93967, Total events handled time:499755.82us.
> 
> In this sample, the time of MMIO Read has big different,
> in the case 1(new tracepoints), the time is calculated by kvm_mmio_begin -> kvm_mmio(read...)
> in the case 2(existing tracepoints), the time is calculated by kvm_exit -> kvm_mmio(read...)


And the pio result:

1: Using kvm_mmio_begin/end:
# ./perf kvm-events report --event ioport --key time
  Warning: Error: expected type 5 but read 4
  Warning: Error: expected type 5 but read 0
  Warning: unknown op '}'


Analyze events for all VCPUs:

      IO Port Access    Samples  Samples%     Time%         Avg time

           0x1f0:PIN          3     0.00%     0.02%    115.91us ( +-  12.55% )
          0xc026:PIN        645     0.32%     4.55%    105.21us ( +-  59.73% )
            0x64:PIN        114     0.06%     0.14%     18.63us ( +-   5.02% )
          0xc022:PIN        457     0.23%     0.53%     17.18us ( +-   4.15% )
            0x60:PIN        114     0.06%     0.11%     14.56us ( +-   7.16% )
         0xc000:POUT      22512    11.30%    17.21%     11.41us ( +-   6.84% )
           0x1f7:PIN      30044    15.08%    22.53%     11.19us ( +-  10.37% )
         0xc024:POUT          6     0.00%     0.00%     10.60us ( +-  54.28% )
......

2: kvm_mmio_begin/end is not used:
# ./perf kvm-events report --event ioport --key time
  Warning: Error: expected type 5 but read 4
  Warning: Error: expected type 5 but read 0
  Warning: unknown op '}'


Analyze events for all VCPUs:

      IO Port Access    Samples  Samples%     Time%         Avg time

           0x1f0:PIN          3     0.00%     0.02%    118.37us ( +-  12.65% )
          0xc026:PIN        645     0.32%     3.54%    107.89us ( +-  58.26% )
            0x64:PIN        114     0.06%     0.13%     23.04us ( +-   6.44% )
          0xc022:PIN        457     0.23%     0.48%     20.63us ( +-   3.65% )
            0x60:PIN        114     0.06%     0.10%     17.70us ( +-   6.41% )
         0xc000:POUT      22512    11.30%    16.19%     14.14us ( +-   6.27% )
           0x1f7:PIN      30044    15.08%    21.18%     13.85us ( +-   8.39% )
         0xc024:POUT          6     0.00%     0.00%     13.09us ( +-  47.40% )
......

The time of case 1 is calculated by kvm_pio -> kvm_mmio_done
The time of case 2 is calculated by kvm_pio -> kvm_entry