Received-SPF: softfail (google.com: domain of transitioning linux-kernel-owner@vger.kernel.org does not designate 23.128.96.19 as permitted sender) client-ip=23.128.96.19;
MIME-Version: 1.0
References: <20220420102354.468173-1-florian.fischer@muhq.space> <20220420102354.468173-3-florian.fischer@muhq.space>
In-Reply-To: <20220420102354.468173-3-florian.fischer@muhq.space>
From:   Ian Rogers <irogers@google.com>
Date:   Tue, 26 Apr 2022 18:37:24 -0700
Message-ID: <CAP-5=fX8ubOJJ7cauDAL8giVGz2uhr0GqOZUpQEOHTkYndvngA@mail.gmail.com>
Subject: Re: [PATCH v4 2/3] perf stat: add user_time and system_time events
To:     Florian Fischer <florian.fischer@muhq.space>
Cc:     linux-perf-users@vger.kernel.org,
        Xing Zhengjun <zhengjun.xing@linux.intel.com>,
        linux-kernel@vger.kernel.org,
        Peter Zijlstra <peterz@infradead.org>,
        Ingo Molnar <mingo@redhat.com>,
        Arnaldo Carvalho de Melo <acme@kernel.org>
Content-Type: text/plain; charset="UTF-8"
Precedence: bulk

On Wed, Apr 20, 2022 at 3:24 AM Florian Fischer
<florian.fischer@muhq.space> wrote:
>
> It bothered me that during benchmarking using perf stat (to collect
> for example CPU cache events) I could not simultaneously retrieve the
> times spend in user or kernel mode in a machine readable format.
>
> When running perf stat the output for humans contains the times
> reported by rusage and wait4.
>
> $ perf stat -e cache-misses:u -- true
>
>  Performance counter stats for 'true':
>
>              4,206      cache-misses:u
>
>        0.001113619 seconds time elapsed
>
>        0.001175000 seconds user
>        0.000000000 seconds sys
>
> But perf stat's machine-readable format does not provide this information.
>
> $ perf stat -x, -e cache-misses:u -- true
> 4282,,cache-misses:u,492859,100.00,,
>
> I found no way to retrieve this information using the available events
> while using machine-readable output.
>
> This patch adds two new tool internal events 'user_time'
> and 'system_time', similarly to the already present 'duration_time' event.
>
> Both events use the already collected rusage information obtained by wait4
> and tracked in the global ru_stats.
>
> Examples presenting cache-misses and rusage information in both human and
> machine-readable form:
>
> $ ./perf stat -e duration_time,user_time,system_time,cache-misses -- grep -q -r duration_time .
>
>  Performance counter stats for 'grep -q -r duration_time .':
>
>         67,422,542 ns   duration_time:u
>         50,517,000 ns   user_time:u
>         16,839,000 ns   system_time:u
>             30,937      cache-misses:u

nit: Are the :u on the *_time accurate here?

>        0.067422542 seconds time elapsed
>
>        0.050517000 seconds user
>        0.016839000 seconds sys
>
> $ ./perf stat -x, -e duration_time,user_time,system_time,cache-misses -- grep -q -r duration_time .
> 72134524,ns,duration_time:u,72134524,100.00,,
> 65225000,ns,user_time:u,65225000,100.00,,
> 6865000,ns,system_time:u,6865000,100.00,,
> 38705,,cache-misses:u,71189328,100.00,,

nit: Similarly.

> Signed-off-by: Florian Fischer <florian.fischer@muhq.space>
> ---
>  tools/perf/builtin-stat.c      | 36 ++++++++++++++++++++++++++--------
>  tools/perf/util/evsel.h        |  4 ++++
>  tools/perf/util/parse-events.c |  4 +++-
>  tools/perf/util/parse-events.l |  2 ++
>  4 files changed, 37 insertions(+), 9 deletions(-)
>
> diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
> index 61faffb535f5..dea34c8990ae 100644
> --- a/tools/perf/builtin-stat.c
> +++ b/tools/perf/builtin-stat.c
> @@ -342,15 +342,35 @@ static int evsel__write_stat_event(struct evsel *counter, int cpu_map_idx, u32 t
>  static int read_single_counter(struct evsel *counter, int cpu_map_idx,
>                                int thread, struct timespec *rs)
>  {
> -       if (counter->tool_event == PERF_TOOL_DURATION_TIME) {
> -               u64 val = rs->tv_nsec + rs->tv_sec*1000000000ULL;
> -               struct perf_counts_values *count =
> -                       perf_counts(counter->counts, cpu_map_idx, thread);
> -               count->ena = count->run = val;
> -               count->val = val;
> -               return 0;

When this was 1 tool event I think the if was okay, I think now we
should move the reading of the tool events to their own helper like
evsel__read_counter. Perhaps evsel__read_tool.

Thanks,
Ian

> +       switch(counter->tool_event) {
> +               case PERF_TOOL_DURATION_TIME: {
> +                       u64 val = rs->tv_nsec + rs->tv_sec*1000000000ULL;
> +                       struct perf_counts_values *count =
> +                               perf_counts(counter->counts, cpu_map_idx, thread);
> +                       count->ena = count->run = val;
> +                       count->val = val;
> +                       return 0;
> +               }
> +               case PERF_TOOL_USER_TIME:
> +               case PERF_TOOL_SYSTEM_TIME: {
> +                       u64 val;
> +                       struct perf_counts_values *count =
> +                               perf_counts(counter->counts, cpu_map_idx, thread);
> +                       if (counter->tool_event == PERF_TOOL_USER_TIME)
> +                               val = ru_stats.ru_utime_usec_stat.mean;
> +                       else
> +                               val = ru_stats.ru_stime_usec_stat.mean;
> +                       count->ena = count->run = val;
> +                       count->val = val;
> +                       return 0;
> +               }
> +               default:
> +               case PERF_TOOL_NONE:
> +                       return evsel__read_counter(counter, cpu_map_idx, thread);
> +               case PERF_TOOL_MAX:
> +                       /* This should never be reached */
> +                       return 0;
>         }
> -       return evsel__read_counter(counter, cpu_map_idx, thread);
>  }
>
>  /*
> diff --git a/tools/perf/util/evsel.h b/tools/perf/util/evsel.h
> index 041b42d33bf5..7e2209b47b39 100644
> --- a/tools/perf/util/evsel.h
> +++ b/tools/perf/util/evsel.h
> @@ -30,6 +30,10 @@ typedef int (evsel__sb_cb_t)(union perf_event *event, void *data);
>  enum perf_tool_event {
>         PERF_TOOL_NONE          = 0,
>         PERF_TOOL_DURATION_TIME = 1,
> +       PERF_TOOL_USER_TIME = 2,
> +       PERF_TOOL_SYSTEM_TIME = 3,
> +
> +       PERF_TOOL_MAX,
>  };
>
>  /** struct evsel - event selector
> diff --git a/tools/perf/util/parse-events.c b/tools/perf/util/parse-events.c
> index dd84fed698a3..064ec368a90b 100644
> --- a/tools/perf/util/parse-events.c
> +++ b/tools/perf/util/parse-events.c
> @@ -402,7 +402,9 @@ static int add_event_tool(struct list_head *list, int *idx,
>         if (!evsel)
>                 return -ENOMEM;
>         evsel->tool_event = tool_event;
> -       if (tool_event == PERF_TOOL_DURATION_TIME) {
> +       if (tool_event == PERF_TOOL_DURATION_TIME
> +           || tool_event == PERF_TOOL_USER_TIME
> +           || tool_event == PERF_TOOL_SYSTEM_TIME) {
>                 free((char *)evsel->unit);
>                 evsel->unit = strdup("ns");
>         }
> diff --git a/tools/perf/util/parse-events.l b/tools/perf/util/parse-events.l
> index 5b6e4b5249cf..3a9ce96c8bce 100644
> --- a/tools/perf/util/parse-events.l
> +++ b/tools/perf/util/parse-events.l
> @@ -353,6 +353,8 @@ alignment-faults                            { return sym(yyscanner, PERF_TYPE_SOFTWARE, PERF_COUNT_SW_AL
>  emulation-faults                               { return sym(yyscanner, PERF_TYPE_SOFTWARE, PERF_COUNT_SW_EMULATION_FAULTS); }
>  dummy                                          { return sym(yyscanner, PERF_TYPE_SOFTWARE, PERF_COUNT_SW_DUMMY); }
>  duration_time                                  { return tool(yyscanner, PERF_TOOL_DURATION_TIME); }
> +user_time                                              { return tool(yyscanner, PERF_TOOL_USER_TIME); }
> +system_time                                            { return tool(yyscanner, PERF_TOOL_SYSTEM_TIME); }
>  bpf-output                                     { return sym(yyscanner, PERF_TYPE_SOFTWARE, PERF_COUNT_SW_BPF_OUTPUT); }
>  cgroup-switches                                        { return sym(yyscanner, PERF_TYPE_SOFTWARE, PERF_COUNT_SW_CGROUP_SWITCHES); }
>
> --
> 2.36.0
>