From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-8.2 required=3.0 tests=HEADER_FROM_DIFFERENT_DOMAINS, INCLUDES_PATCH,MAILING_LIST_MULTI,SIGNED_OFF_BY,SPF_HELO_NONE,SPF_PASS, URIBL_BLOCKED,USER_AGENT_SANE_1 autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 240ABC433E1 for ; Tue, 7 Jul 2020 14:55:21 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id E912E206C3 for ; Tue, 7 Jul 2020 14:55:20 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1728306AbgGGOzT (ORCPT ); Tue, 7 Jul 2020 10:55:19 -0400 Received: from mga04.intel.com ([192.55.52.120]:31485 "EHLO mga04.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1727975AbgGGOzS (ORCPT ); Tue, 7 Jul 2020 10:55:18 -0400 IronPort-SDR: J7PIrnWwiJTG7oOZfIfnsAEYi/RF0gy8SvS3+4WAW3nsr3xv99lt1AUDw+ZNrh6GFHjEEZSC/r WbZEuxn4FdGQ== X-IronPort-AV: E=McAfee;i="6000,8403,9675"; a="145113248" X-IronPort-AV: E=Sophos;i="5.75,324,1589266800"; d="scan'208";a="145113248" X-Amp-Result: SKIPPED(no attachment in message) X-Amp-File-Uploaded: False Received: from fmsmga008.fm.intel.com ([10.253.24.58]) by fmsmga104.fm.intel.com with ESMTP/TLS/ECDHE-RSA-AES256-GCM-SHA384; 07 Jul 2020 07:55:17 -0700 IronPort-SDR: hYLFfsPhYy0Nyce1qUb4bf/xc/sE9AK7TJLWQDGuWSTuRTpJMFbZaxNaz+M8HQnOfyDbplbBeX BNVOSWJmzteg== X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.75,324,1589266800"; d="scan'208";a="268218073" Received: from linux.intel.com ([10.54.29.200]) by fmsmga008.fm.intel.com with ESMTP; 07 Jul 2020 07:55:17 -0700 Received: from [10.249.228.33] (abudanko-mobl.ccr.corp.intel.com [10.249.228.33]) by linux.intel.com (Postfix) with ESMTP id 2F7F65807C9; Tue, 7 Jul 2020 07:55:14 -0700 (PDT) Subject: Re: [PATCH v9 11/15] perf stat: implement control commands handling To: Jiri Olsa Cc: Arnaldo Carvalho de Melo , Namhyung Kim , Alexander Shishkin , Peter Zijlstra , Ingo Molnar , Andi Kleen , linux-kernel References: <21669f5a-6220-df0a-09f1-b73b32487f23@linux.intel.com> <20200706123436.GD3401866@krava> <6cf91811-ea6a-3c7c-8bbf-7f96bfa1fc82@linux.intel.com> <20200706193418.GB3424581@krava> <20200707131403.GD3424581@krava> <865ad42a-6085-41d6-06d5-730cb9904ce8@linux.intel.com> <20200707142351.GE3424581@krava> From: Alexey Budankov Organization: Intel Corp. Message-ID: <44f494d6-b4a5-2d56-001e-b3289cbeedaa@linux.intel.com> Date: Tue, 7 Jul 2020 17:55:14 +0300 User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:68.0) Gecko/20100101 Thunderbird/68.10.0 MIME-Version: 1.0 In-Reply-To: <20200707142351.GE3424581@krava> Content-Type: text/plain; charset=utf-8 Content-Language: en-US Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 >>>>>>>> --- >>>>>>>> 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 cpu-cycles >>>>>> 2.003146566 cpu-cycles >>>>>> 3.005073317 cpu-cycles >>>>>> 4.006337062 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 cpu-cycles >>>>>> 17.031131311 cpu-cycles >>>>>> 18.033010580 cpu-cycles >>>>>> 19.034918883 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 >> >