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

[Jiri Olsa]

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?

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
>