Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Date:   Mon, 6 Jul 2020 21:34:18 +0200
From:   Jiri Olsa <jolsa@redhat.com>
To:     Alexey Budankov <alexey.budankov@linux.intel.com>
Cc:     Arnaldo Carvalho de Melo <acme@kernel.org>,
        Namhyung Kim <namhyung@kernel.org>,
        Alexander Shishkin <alexander.shishkin@linux.intel.com>,
        Peter Zijlstra <peterz@infradead.org>,
        Ingo Molnar <mingo@redhat.com>,
        Andi Kleen <ak@linux.intel.com>,
        linux-kernel <linux-kernel@vger.kernel.org>
Subject: Re: [PATCH v9 11/15] perf stat: implement control commands handling
Message-ID: <20200706193418.GB3424581@krava>
References: <a4d5db4a-f25c-38dc-1c41-321a886cb122@linux.intel.com>
 <21669f5a-6220-df0a-09f1-b73b32487f23@linux.intel.com>
 <20200706123436.GD3401866@krava>
 <6cf91811-ea6a-3c7c-8bbf-7f96bfa1fc82@linux.intel.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <6cf91811-ea6a-3c7c-8bbf-7f96bfa1fc82@linux.intel.com>
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

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@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);
 			clock_gettime(CLOCK_MONOTONIC, &time_stop);
 			diff_timespec(&time_diff, &time_stop, &time_start);
 			time_to_sleep -= time_diff.tv_sec * MSEC_PER_SEC +