Re: [PATCH v4] tools/perf/metricgroup: Fix printing event names of metric group with multiple events incase of overlapping events
From: kajoljain
Date: Mon Mar 02 2020 - 01:15:12 EST
On 2/20/20 4:06 PM, Joakim Zhang wrote:
>
>> -----Original Message-----
>> From: kajoljain <kjain@xxxxxxxxxxxxx>
>> Sent: 2020年2月20日 17:54
>> To: Joakim Zhang <qiangqing.zhang@xxxxxxx>; acme@xxxxxxxxxx
>> Cc: linux-kernel@xxxxxxxxxxxxxxx; linux-perf-users@xxxxxxxxxxxxxxx; Jiri Olsa
>> <jolsa@xxxxxxxxxx>; Alexander Shishkin <alexander.shishkin@xxxxxxxxxxxxxxx>;
>> Andi Kleen <ak@xxxxxxxxxxxxxxx>; Kan Liang <kan.liang@xxxxxxxxxxxxxxx>; Peter
>> Zijlstra <peterz@xxxxxxxxxxxxx>; Jin Yao <yao.jin@xxxxxxxxxxxxxxx>; Madhavan
>> Srinivasan <maddy@xxxxxxxxxxxxxxxxxx>; Anju T Sudhakar
>> <anju@xxxxxxxxxxxxxxxxxx>; Ravi Bangoria <ravi.bangoria@xxxxxxxxxxxxx>
>> Subject: Re: [PATCH v4] tools/perf/metricgroup: Fix printing event names of
>> metric group with multiple events incase of overlapping events
>>
>>
>>
>> On 2/17/20 8:41 AM, Joakim Zhang wrote:
>>>
>>>> -----Original Message-----
>>>> From: linux-perf-users-owner@xxxxxxxxxxxxxxx
>>>> <linux-perf-users-owner@xxxxxxxxxxxxxxx> On Behalf Of Kajol Jain
>>>> Sent: 2020年2月12日 13:41
>>>> To: acme@xxxxxxxxxx
>>>> Cc: linux-kernel@xxxxxxxxxxxxxxx; linux-perf-users@xxxxxxxxxxxxxxx;
>>>> kjain@xxxxxxxxxxxxx; Jiri Olsa <jolsa@xxxxxxxxxx>; Alexander Shishkin
>>>> <alexander.shishkin@xxxxxxxxxxxxxxx>; Andi Kleen
>>>> <ak@xxxxxxxxxxxxxxx>; Kan Liang <kan.liang@xxxxxxxxxxxxxxx>; Peter
>>>> Zijlstra <peterz@xxxxxxxxxxxxx>; Jin Yao <yao.jin@xxxxxxxxxxxxxxx>;
>>>> Madhavan Srinivasan <maddy@xxxxxxxxxxxxxxxxxx>; Anju T Sudhakar
>>>> <anju@xxxxxxxxxxxxxxxxxx>; Ravi Bangoria
>>>> <ravi.bangoria@xxxxxxxxxxxxx>
>>>> Subject: [PATCH v4] tools/perf/metricgroup: Fix printing event names
>>>> of metric group with multiple events incase of overlapping events
>>>>
>>>> Commit f01642e4912b ("perf metricgroup: Support multiple events for
>>>> metricgroup") introduced support for multiple events in a metric
>>>> group. But with the current upstream, metric events names are not
>>>> printed properly incase we try to run multiple metric groups with
>> overlapping event.
>>>>
>>>> With current upstream version, incase of overlapping metric events
>>>> issue is, we always start our comparision logic from start.
>>>> So, the events which already matched with some metric group also take
>>>> part in comparision logic. Because of that when we have overlapping
>>>> events, we end up matching current metric group event with already
>> matched one.
>>>>
>>>> For example, in skylake machine we have metric event CoreIPC and
>>>> Instructions. Both of them need 'inst_retired.any' event value.
>>>> As events in Instructions is subset of events in CoreIPC, they endup
>>>> in pointing to same 'inst_retired.any' value.
>>>>
>>>> In skylake platform:
>>>>
>>>> command:# ./perf stat -M CoreIPC,Instructions -C 0 sleep 1
>>>>
>>>> Performance counter stats for 'CPU(s) 0':
>>>>
>>>> 1,254,992,790 inst_retired.any # 1254992790.0
>>>>
>> Instructions
>>>> # 1.3
>>>> CoreIPC
>>>> 977,172,805 cycles
>>>> 1,254,992,756 inst_retired.any
>>>>
>>>> 1.000802596 seconds time elapsed
>>>>
>>>> command:# sudo ./perf stat -M UPI,IPC sleep 1
>>>>
>>>> Performance counter stats for 'sleep 1':
>>>>
>>>> 948,650 uops_retired.retire_slots
>>>> 866,182 inst_retired.any # 0.7 IPC
>>>> 866,182 inst_retired.any
>>>> 1,175,671 cpu_clk_unhalted.thread
>>>>
>>>> Patch fixes the issue by adding a new bool pointer 'evlist_used' to
>>>> keep track of events which already matched with some group by setting it
>> true.
>>>> So, we skip all used events in list when we start comparision logic.
>>>> Patch also make some changes in comparision logic, incase we get a
>>>> match miss, we discard the whole match and start again with first
>>>> event id in metric event.
>>>>
>>>> With this patch:
>>>> In skylake platform:
>>>>
>>>> command:# ./perf stat -M CoreIPC,Instructions -C 0 sleep 1
>>>>
>>>> Performance counter stats for 'CPU(s) 0':
>>>>
>>>> 3,348,415 inst_retired.any # 0.3
>> CoreIPC
>>>> 11,779,026 cycles
>>>> 3,348,381 inst_retired.any # 3348381.0
>>>>
>> Instructions
>>>>
>>>> 1.001649056 seconds time elapsed
>>>>
>>>> command:# ./perf stat -M UPI,IPC sleep 1
>>>>
>>>> Performance counter stats for 'sleep 1':
>>>>
>>>> 1,023,148 uops_retired.retire_slots # 1.1 UPI
>>>> 924,976 inst_retired.any
>>>> 924,976 inst_retired.any # 0.6 IPC
>>>> 1,489,414 cpu_clk_unhalted.thread
>>>>
>>>> 1.003064672 seconds time elapsed
>>>>
>>>> Signed-off-by: Kajol Jain <kjain@xxxxxxxxxxxxx>
>>>> Cc: Jiri Olsa <jolsa@xxxxxxxxxx>
>>>> Cc: Alexander Shishkin <alexander.shishkin@xxxxxxxxxxxxxxx>
>>>> Cc: Andi Kleen <ak@xxxxxxxxxxxxxxx>
>>>> Cc: Kan Liang <kan.liang@xxxxxxxxxxxxxxx>
>>>> Cc: Peter Zijlstra <peterz@xxxxxxxxxxxxx>
>>>> Cc: Jin Yao <yao.jin@xxxxxxxxxxxxxxx>
>>>> Cc: Madhavan Srinivasan <maddy@xxxxxxxxxxxxxxxxxx>
>>>> Cc: Anju T Sudhakar <anju@xxxxxxxxxxxxxxxxxx>
>>>> Cc: Ravi Bangoria <ravi.bangoria@xxxxxxxxxxxxx>
>>>> ---
>>>> tools/perf/util/metricgroup.c | 50
>>>> ++++++++++++++++++++++-------------
>>>> 1 file changed, 31 insertions(+), 19 deletions(-)
>>>
>>> Hi Kajol,
>>>
>>> I am not sure if it is good to ask a question here :-)
>>>
>>> I encountered a perf metricgroup issue, the result is incorrect when the
>> metric includes more than 2 events.
>>>
>>> git log --oneline tools/perf/util/metricgroup.c
>>> 3635b27cc058 perf metricgroup: Fix printing event names of metric
>>> group with multiple events f01642e4912b perf metricgroup: Support
>>> multiple events for metricgroup
>>> 287f2649f791 perf metricgroup: Scale the metric result
>>>
>>> I did a simple test, below is the JSON file and result.
>>> [
>>> {
>>> "PublicDescription": "Calculate DDR0 bus actual utilization
>> which vary from DDR0 controller clock frequency",
>>> "BriefDescription": "imx8qm: ddr0 bus actual utilization",
>>> "MetricName": "imx8qm-ddr0-bus-util",
>>> "MetricExpr": "( imx8_ddr0\\/read\\-cycles\\/ +
>> imx8_ddr0\\/write\\-cycles\\/ )",
>>> "MetricGroup": "i.MX8QM_DDR0_BUS_UTIL"
>>> }
>>> ]
>>> ./perf stat -I 1000 -M imx8qm-ddr0-bus-util
>>> # time counts unit events
>>> 1.000104250 16720 imx8_ddr0/read-cycles/
>> # 22921.0 imx8qm-ddr0-bus-util
>>> 1.000104250 6201 imx8_ddr0/write-cycles/
>>> 2.000525625 8316 imx8_ddr0/read-cycles/
>> # 12785.5 imx8qm-ddr0-bus-util
>>> 2.000525625 2738 imx8_ddr0/write-cycles/
>>> 3.000819125 1056 imx8_ddr0/read-cycles/
>> # 4136.7 imx8qm-ddr0-bus-util
>>> 3.000819125 303 imx8_ddr0/write-cycles/
>>> 4.001103750 6260 imx8_ddr0/read-cycles/
>> # 9149.8 imx8qm-ddr0-bus-util
>>> 4.001103750 2317 imx8_ddr0/write-cycles/
>>> 5.001392750 2084 imx8_ddr0/read-cycles/
>> # 4516.0 imx8qm-ddr0-bus-util
>>> 5.001392750 601 imx8_ddr0/write-cycles/
>>>
>>> You can see that only the first result is correct, could this be reproduced at
>> you side?
>>
>> Hi Joakim,
>> Will try to look into it from my side.
>
> Thanks Kajol for your help, I look into this issue, but don't know how to fix it.
>
> The results are always correct if signal event used in "MetricExpr" with "-I" parameters, but the results are incorrect when more than one events used in "MetricExpr".
>
Hi Joakim,
So, I try to look into this issue and understand the flow. From my understanding, whenever we do
calculation of metric expression we don't use exact count we are getting.
Basically we use mean value of each event in the calculation of metric expression.
So, I am taking same example you refer.
Metric Event: imx8qm-ddr0-bus-util
MetricExpr": "( imx8_ddr0\\/read\\-cycles\\/ + imx8_ddr0\\/write\\-cycles\\/ )"
command#: ./perf stat -I 1000 -M imx8qm-ddr0-bus-util
# time counts unit events
1.000104250 16720 imx8_ddr0/read-cycles/ # 22921.0 imx8qm-ddr0-bus-util
1.000104250 6201 imx8_ddr0/write-cycles/
2.000525625 8316 imx8_ddr0/read-cycles/ # 12785.5 imx8qm-ddr0-bus-util
2.000525625 2738 imx8_ddr0/write-cycles/
3.000819125 1056 imx8_ddr0/read-cycles/ # 4136.7 imx8qm-ddr0-bus-util
3.000819125 303 imx8_ddr0/write-cycles/
4.001103750 6260 imx8_ddr0/read-cycles/ # 9149.8 imx8qm-ddr0-bus-util
4.001103750 2317 imx8_ddr0/write-cycles/
5.001392750 2084 imx8_ddr0/read-cycles/ # 4516.0 imx8qm-ddr0-bus-util
5.001392750 601 imx8_ddr0/write-cycles/
If you see we have a function called 'update_stats' in file util/stat.c where we do this calculation
and updating stats->mean value. And this mean value is what we are using actually in our
metric expression calculation.
We call this function in each iteration where we update stats->mean and stats->n for each event.
But one weird issue is, for very first event, stat->n is always 1 that is why we are getting
mean same as count.
So this is the reason for single event you get exact aggregate of metric expression.
So doesn't matter how many events you have in your metric expression, every time
you take exact count for first one and normalized value for rest which is weird.
According to update_stats function: We are updating mean as:
stats->mean += delta / stats->n where, delta = val - stats->mean.
If we take write-cycles here. Initially mean = 0 and n = 1.
1st iteration: n=1, write cycle : 6201 and mean = 6201 (Final agg value: 16720 + 6201 = 22921)
2nd iteration: n=2, write cycles: 6201 + (2738 - 6201)/2 = 4469.5 (Final aggr value: 8316 + 4469.5 = 12785.5)
3rd iteration: n=3, write cycles: 4469.5 + (303 - 4469.5)/3 = 3080.6667 (Final aggr value: 1056 + 3080.6667 = 4136.7)
Andi and Jiri, I am not sure if its expected behavior. I mean shouldn't we either take mean value of each event
or take n as 1 for each event. And one more question, Should we add an option to say whether user want exact aggregate or
this normalize aggregate to remove the confusion? I try to find it out if we already have one but didn't get.
Please let me know if my understanding is fine.
Thanks,
Kajol
> Hope you can find the root cause :-)
>
> Best Regards,
> Joakim Zhang
>> Thanks,
>> Kajol
>>>
>>> Thanks a lot!
>>>
>>> Best Regards,
>>> Joakim Zhang
>>>