On 07.07.2020 16:14, Jiri Olsa wrote:
> On Tue, Jul 07, 2020 at 04:07:42PM +0300, Alexey Budankov wrote:
>>
>> On 06.07.2020 22:34, Jiri Olsa wrote:
>>> On Mon, Jul 06, 2020 at 05:47:54PM +0300, Alexey Budankov wrote:
>>>>
>>>> On 06.07.2020 15:34, Jiri Olsa wrote:
>>>>> On Fri, Jul 03, 2020 at 10:47:22AM +0300, Alexey Budankov wrote:
>>>>>>
>>>>>> Implement handling of 'enable' and 'disable' control commands
>>>>>> coming from control file descriptor. process_evlist() function
>>>>>> checks for events on control fds and makes required operations.
>>>>>> If poll event splits initiated timeout interval then the reminder
>>>>>> is calculated and still waited in the following poll() syscall.
>>>>>>
>>>>>> Signed-off-by: Alexey Budankov <alexey.budan...@linux.intel.com>
>>>>>> ---
>>>>>> tools/perf/builtin-stat.c | 75 ++++++++++++++++++++++++++++-----------
>>>>>> 1 file changed, 55 insertions(+), 20 deletions(-)
>>>>>>
>>>>>> diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
>>>>>> index 9e4288ecf2b8..5021f7286422 100644
>>>>>> --- a/tools/perf/builtin-stat.c
>>>>>> +++ b/tools/perf/builtin-stat.c
>>>>>> @@ -485,6 +485,31 @@ static bool handle_interval(unsigned int interval,
>>>>>> int *times)
>>>>>> return false;
>>>>>> }
>>>>>>
>>>>>> +static bool process_evlist(struct evlist *evlist, unsigned int
>>>>>> interval, int *times)
>>>>>> +{
>>>>>> + bool stop = false;
>>>>>> + enum evlist_ctl_cmd cmd = EVLIST_CTL_CMD_UNSUPPORTED;
>>>>>> +
>>>>>> + if (evlist__ctlfd_process(evlist, &cmd) > 0) {
>>>>>> + switch (cmd) {
>>>>>> + case EVLIST_CTL_CMD_ENABLE:
>>>>>> + pr_info(EVLIST_ENABLED_MSG);
>>>>>> + stop = handle_interval(interval, times);
>>>>>> + break;
>>>>>> + case EVLIST_CTL_CMD_DISABLE:
>>>>>> + stop = handle_interval(interval, times);
>>>>>
>>>>> I still don't understand why you call handle_interval in here
>>>>>
>>>>> I don't see it being necessary.. you enable events and handle_interval,
>>>>> wil be called in the next iteration of dispatch_events, why complicate
>>>>> this function with that?
>>>>
>>>> Printing event counts at the moment of command processing lets scripts
>>>> built on top of stat output to provide more plain and accurate metrics.
>>>> Otherwise it may get spikes in the beginning of the next time interval
>>>> because not all counts lay inside [Events enabled, Events disable]
>>>> If -I interval is large tail event count can be also large. Compare the
>>>> output below with the output in the cover letter. Either way is possible
>>>> but the latter one likely complicates the scripts I mentioned above.
>>>>
>>>> perf=tools/perf/perf
>>>> ${perf} stat -D -1 -e cpu-cycles -a -I 1000 \
>>>> --control fd:${ctl_fd},${ctl_fd_ack} \
>>>> -- sleep 40 &
>>>>
>>>> Events disabled
>>>> # time counts unit events
>>>> 1.001100723 <not counted> cpu-cycles
>>>>
>>>> 2.003146566 <not counted> cpu-cycles
>>>>
>>>> 3.005073317 <not counted> cpu-cycles
>>>>
>>>> 4.006337062 <not counted> cpu-cycles
>>>>
>>>> Events enabled
>>>> enable acked(ack)
>>>> 5.011182000 54,128,692 cpu-cycles <===
>>>>
>>>> 6.012300167 3,648,804,827 cpu-cycles
>>>>
>>>> 7.013631689 590,438,536 cpu-cycles
>>>>
>>>> 8.015558583 406,935,663 cpu-cycles
>>>>
>>>> 9.017455505 407,806,862 cpu-cycles
>>>>
>>>> 10.019300780 399,351,824 cpu-cycles
>>>>
>>>> 11.021180025 404,584,417 cpu-cycles
>>>>
>>>> 12.023033661 537,787,981 cpu-cycles
>>>>
>>>> 13.024422354 699,395,364 cpu-cycles
>>>>
>>>> 14.026325749 397,871,324 cpu-cycles
>>>>
>>>> disable acked()
>>>> Events disabled
>>>> 15.027857981 396,956,159 cpu-cycles <===
>>>> 16.029279264 <not counted> cpu-cycles
>>>>
>>>> 17.031131311 <not counted> cpu-cycles
>>>>
>>>> 18.033010580 <not counted> cpu-cycles
>>>>
>>>> 19.034918883 <not counted> cpu-cycles
>>>>
>>>> enable acked(ack)
>>>> Events enabled
>>>> 20.036758793 183,544,975 cpu-cycles <===
>>>>
>>>> 21.038163289 419,054,544 cpu-cycles
>>>>
>>>> 22.040108245 413,993,309 cpu-cycles
>>>>
>>>> 23.042042365 403,584,493 cpu-cycles
>>>>
>>>> 24.043985381 416,512,094 cpu-cycles
>>>>
>>>> 25.045925682 401,513,429 cpu-cycles
>>>>
>>>> # time counts unit events
>>>> 26.047822238 461,205,096 cpu-cycles
>>>>
>>>> 27.049784263 414,319,162 cpu-cycles
>>>>
>>>> 28.051745360 403,706,915 cpu-cycles
>>>>
>>>> 29.053674600 416,502,883 cpu-cycles
>>>>
>>>> disable acked()
>>>> Events disabled
>>>> 30.054750685 414,184,409 cpu-cycles <===
>>>
>>> ok, but we could still take handle_interval out of process_evlist
>>> and the interval process will be more clear for me (with some
>>> additional comments in the code) ... perhaps something like below?
>>>
>>> thanks,
>>> jirka
>>>
>>>
>>> ---
>>> diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
>>> index 5021f7286422..af83bf6b2db0 100644
>>> --- a/tools/perf/builtin-stat.c
>>> +++ b/tools/perf/builtin-stat.c
>>> @@ -485,19 +485,18 @@ static bool handle_interval(unsigned int interval,
>>> int *times)
>>> return false;
>>> }
>>>
>>> -static bool process_evlist(struct evlist *evlist, unsigned int interval,
>>> int *times)
>>> +static bool process_evlist(struct evlist *evlist)
>>> {
>>> - bool stop = false;
>>> enum evlist_ctl_cmd cmd = EVLIST_CTL_CMD_UNSUPPORTED;
>>> + bool enabled = false;
>>>
>>> if (evlist__ctlfd_process(evlist, &cmd) > 0) {
>>> switch (cmd) {
>>> case EVLIST_CTL_CMD_ENABLE:
>>> pr_info(EVLIST_ENABLED_MSG);
>>> - stop = handle_interval(interval, times);
>>> + enabled = true;
>>> break;
>>> case EVLIST_CTL_CMD_DISABLE:
>>> - stop = handle_interval(interval, times);
>>> pr_info(EVLIST_DISABLED_MSG);
>>> break;
>>> case EVLIST_CTL_CMD_ACK:
>>> @@ -507,7 +506,7 @@ static bool process_evlist(struct evlist *evlist,
>>> unsigned int interval, int *ti
>>> }
>>> }
>>>
>>> - return stop;
>>> + return enabled;
>>> }
>>>
>>> static void enable_counters(void)
>>> @@ -618,7 +617,8 @@ static int dispatch_events(bool forks, int timeout, int
>>> interval, int *times)
>>> stop = handle_interval(interval, times);
>>> time_to_sleep = sleep_time;
>>> } else { /* fd revent */
>>> - stop = process_evlist(evsel_list, interval, times);
>>> + if (process_evlist(evsel_list))
>>> + stop = handle_interval(interval, times);
>>
>> It will call only on enable command and lead to artificial spikes in the
>> beginning of interval.
>> May be just take handle_interval() out of process_evlist() and have it
>> similar to record case?
>
> it can be called also for disable case then
Made it like this so now times counter is not affected during commands
processing:
static void process_evlist(struct evlist *evlist, enum evlist_ctl_cmd *cmd)
{
if (evlist__ctlfd_process(evlist, cmd) > 0) {
switch (*cmd) {
case EVLIST_CTL_CMD_ENABLE:
pr_info(EVLIST_ENABLED_MSG);
break;
case EVLIST_CTL_CMD_DISABLE:
pr_info(EVLIST_DISABLED_MSG);
break;
case EVLIST_CTL_CMD_ACK:
case EVLIST_CTL_CMD_UNSUPPORTED:
default:
break;
}
}
}
...
clock_gettime(CLOCK_MONOTONIC, &time_start);
if (!(evlist__poll(evsel_list, time_to_sleep) > 0)) { /* poll
timeout or EINTR */
if (timeout)
break;
else
stop = handle_interval(interval, times);
time_to_sleep = sleep_time;
} else { /* fd revent */
process_evlist(evsel_list, &cmd);
if (interval) {
switch (cmd) {
case EVLIST_CTL_CMD_ENABLE:
case EVLIST_CTL_CMD_DISABLE:
process_interval();
case EVLIST_CTL_CMD_ACK:
case EVLIST_CTL_CMD_UNSUPPORTED:
default:
break;
}
}
clock_gettime(CLOCK_MONOTONIC, &time_stop);
compute_tts(&time_start, &time_stop, &time_to_sleep);
}
Alexey
