Re: [PATCH v9 11/15] perf stat: implement control commands handling

[Alexey Budankov]

On 07.07.2020 17:23, Jiri Olsa wrote:
> On Tue, Jul 07, 2020 at 04:24:28PM +0300, Alexey Budankov wrote:
>>
>> 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.budankov@xxxxxxxxxxxxxxx>
>>>>>>>> ---
>>>>>>>>  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:
> 
> hm, can't process list just return true
> when the interval needs to be printed?

process_evlist() now looks suboptimal since record mode code directly calls evlist__ctlfd_process()
and then handles returned command specifically to the mode. So in v10 I replaced process_evlist()
call with direct evlist__ctlfd_process() call and then handling the returned command by printing
command msg tag and counter values in the required order. Like this:

+		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 */
+			if (evlist__ctlfd_process(evsel_list, &cmd) > 0) {
+				if (interval) {
+					switch (cmd) {
+					case EVLIST_CTL_CMD_ENABLE:
+						pr_info(EVLIST_ENABLED_MSG);
+						process_interval();
+						break;
+					case EVLIST_CTL_CMD_DISABLE:
+						process_interval();
+						pr_info(EVLIST_DISABLED_MSG);
+						break;
+					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

> 
> jirka
> 
>>
>> 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
>>
>