perf: fix counting when initial delay configured

  When creating counters with initial delay configured, the enable_on_exec
field is not set. So we need to enable the counters later. The problem
is, when a workload is specified the target__none() is still true. So
we also need to check stat_config.initial_delay.

Before this fix the event is not counted:
$ ./perf stat -e instructions -D 100 sleep 2
Events disabled
Events enabled

 Performance counter stats for 'sleep 2':

     <not counted>      instructions

       1.901661124 seconds time elapsed

       0.001602000 seconds user
       0.000000000 seconds sys

After fix it works:
$ ./perf stat -e instructions -D 100 sleep 2
Events disabled
Events enabled

 Performance counter stats for 'sleep 2':

           404,214      instructions

       1.901743475 seconds time elapsed

       0.001617000 seconds user
       0.000000000 seconds sys

Fixes: c587e77e100f ("perf stat: Do not delay the workload with --delay")
Signed-off-by: Changbin Du <changbin.du@huawei.com>
---
 tools/perf/builtin-stat.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
  

Em Thu, Feb 23, 2023 at 03:58:00PM +0800, Changbin Du escreveu:
> When creating counters with initial delay configured, the enable_on_exec
> field is not set. So we need to enable the counters later. The problem
> is, when a workload is specified the target__none() is still true. So
> we also need to check stat_config.initial_delay.
> 
> Before this fix the event is not counted:
> $ ./perf stat -e instructions -D 100 sleep 2
> Events disabled
> Events enabled
> 
>  Performance counter stats for 'sleep 2':
> 
>      <not counted>      instructions
> 
>        1.901661124 seconds time elapsed
> 
>        0.001602000 seconds user
>        0.000000000 seconds sys
> 
> After fix it works:
> $ ./perf stat -e instructions -D 100 sleep 2
> Events disabled
> Events enabled
> 
>  Performance counter stats for 'sleep 2':
> 
>            404,214      instructions
> 
>        1.901743475 seconds time elapsed
> 
>        0.001617000 seconds user
>        0.000000000 seconds sys
> 
> Fixes: c587e77e100f ("perf stat: Do not delay the workload with --delay")

Yeap, even the comment states that we need to enable when initial_delay
is set :-)

I added the additional test output below.

Namhyung, can you please ack it?

- Arnaldo

Committer testing:

Before:

Lets use stress-ng so that we have lots of samples using a CPU stressor
and also intermingle the workload output with the messages about when
the events get enabled (i.e. later on in the workload):

  $ perf stat -e instructions -D 100 stress-ng -c 32 -t 1
  Events disabled
  stress-ng: info:  [38361] setting to a 1 second run per stressor
  stress-ng: info:  [38361] dispatching hogs: 32 cpu
  Events enabled
  stress-ng: info:  [38361] successful run completed in 1.01s

   Performance counter stats for 'stress-ng -c 32 -t 1':

       <not counted>      instructions:u

         0.916479141 seconds time elapsed

        30.868003000 seconds user
         0.049851000 seconds sys


  Some events weren't counted. Try disabling the NMI watchdog:
        echo 0 > /proc/sys/kernel/nmi_watchdog
        perf stat ...
        echo 1 > /proc/sys/kernel/nmi_watchdog
  $

After the fix:

  $ perf stat -e instructions -D 100 stress-ng -c 32 -t 1
  Events disabled
  stress-ng: info:  [40429] setting to a 1 second run per stressor
  stress-ng: info:  [40429] dispatching hogs: 32 cpu
  Events enabled
  stress-ng: info:  [40429] successful run completed in 1.01s

   Performance counter stats for 'stress-ng -c 32 -t 1':

        154117865145      instructions:u

         0.920827644 seconds time elapsed

        30.864753000 seconds user
         0.073862000 seconds sys


  $

> Signed-off-by: Changbin Du <changbin.du@huawei.com>
> ---
>  tools/perf/builtin-stat.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
> index 9f3e4b257516..c71d85577de6 100644
> --- a/tools/perf/builtin-stat.c
> +++ b/tools/perf/builtin-stat.c
> @@ -544,7 +544,7 @@ static int enable_counters(void)
>  	 * - we don't have tracee (attaching to task or cpu)
>  	 * - we have initial delay configured
>  	 */
> -	if (!target__none(&target)) {
> +	if (!target__none(&target) || stat_config.initial_delay) {
>  		if (!all_counters_use_bpf)
>  			evlist__enable(evsel_list);
>  	}
> -- 
> 2.25.1
>
  

Hello,

On Thu, Feb 23, 2023 at 5:45 AM Arnaldo Carvalho de Melo
<acme@kernel.org> wrote:
>
> Em Thu, Feb 23, 2023 at 03:58:00PM +0800, Changbin Du escreveu:
> > When creating counters with initial delay configured, the enable_on_exec
> > field is not set. So we need to enable the counters later. The problem
> > is, when a workload is specified the target__none() is still true. So
> > we also need to check stat_config.initial_delay.
> >
> > Before this fix the event is not counted:
> > $ ./perf stat -e instructions -D 100 sleep 2
> > Events disabled
> > Events enabled
> >
> >  Performance counter stats for 'sleep 2':
> >
> >      <not counted>      instructions
> >
> >        1.901661124 seconds time elapsed
> >
> >        0.001602000 seconds user
> >        0.000000000 seconds sys
> >
> > After fix it works:
> > $ ./perf stat -e instructions -D 100 sleep 2
> > Events disabled
> > Events enabled
> >
> >  Performance counter stats for 'sleep 2':
> >
> >            404,214      instructions
> >
> >        1.901743475 seconds time elapsed
> >
> >        0.001617000 seconds user
> >        0.000000000 seconds sys
> >
> > Fixes: c587e77e100f ("perf stat: Do not delay the workload with --delay")
>
> Yeap, even the comment states that we need to enable when initial_delay
> is set :-)

Right, but the logic that checks the initial_delay is placed
out of the function.  Just checking the initial_delay value
can be confusing as it can have a negative value.

Maybe we can add an argument (bool force?) to the
enable_counters() function.

Thanks,
Namhyung


>
> I added the additional test output below.
>
> Namhyung, can you please ack it?
>
> - Arnaldo
>
> Committer testing:
>
> Before:
>
> Lets use stress-ng so that we have lots of samples using a CPU stressor
> and also intermingle the workload output with the messages about when
> the events get enabled (i.e. later on in the workload):
>
>   $ perf stat -e instructions -D 100 stress-ng -c 32 -t 1
>   Events disabled
>   stress-ng: info:  [38361] setting to a 1 second run per stressor
>   stress-ng: info:  [38361] dispatching hogs: 32 cpu
>   Events enabled
>   stress-ng: info:  [38361] successful run completed in 1.01s
>
>    Performance counter stats for 'stress-ng -c 32 -t 1':
>
>        <not counted>      instructions:u
>
>          0.916479141 seconds time elapsed
>
>         30.868003000 seconds user
>          0.049851000 seconds sys
>
>
>   Some events weren't counted. Try disabling the NMI watchdog:
>         echo 0 > /proc/sys/kernel/nmi_watchdog
>         perf stat ...
>         echo 1 > /proc/sys/kernel/nmi_watchdog
>   $
>
> After the fix:
>
>   $ perf stat -e instructions -D 100 stress-ng -c 32 -t 1
>   Events disabled
>   stress-ng: info:  [40429] setting to a 1 second run per stressor
>   stress-ng: info:  [40429] dispatching hogs: 32 cpu
>   Events enabled
>   stress-ng: info:  [40429] successful run completed in 1.01s
>
>    Performance counter stats for 'stress-ng -c 32 -t 1':
>
>         154117865145      instructions:u
>
>          0.920827644 seconds time elapsed
>
>         30.864753000 seconds user
>          0.073862000 seconds sys
>
>
>   $
>
> > Signed-off-by: Changbin Du <changbin.du@huawei.com>
> > ---
> >  tools/perf/builtin-stat.c | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> >
> > diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
> > index 9f3e4b257516..c71d85577de6 100644
> > --- a/tools/perf/builtin-stat.c
> > +++ b/tools/perf/builtin-stat.c
> > @@ -544,7 +544,7 @@ static int enable_counters(void)
> >        * - we don't have tracee (attaching to task or cpu)
> >        * - we have initial delay configured
> >        */
> > -     if (!target__none(&target)) {
> > +     if (!target__none(&target) || stat_config.initial_delay) {
> >               if (!all_counters_use_bpf)
> >                       evlist__enable(evsel_list);
> >       }
> > --
> > 2.25.1
> >
>
> --
>
> - Arnaldo
  

On Thu, Feb 23, 2023 at 02:48:26PM -0800, Namhyung Kim wrote:
> Hello,
> 
> On Thu, Feb 23, 2023 at 5:45 AM Arnaldo Carvalho de Melo
> <acme@kernel.org> wrote:
> >
> > Em Thu, Feb 23, 2023 at 03:58:00PM +0800, Changbin Du escreveu:
> > > When creating counters with initial delay configured, the enable_on_exec
> > > field is not set. So we need to enable the counters later. The problem
> > > is, when a workload is specified the target__none() is still true. So
> > > we also need to check stat_config.initial_delay.
> > >
> > > Before this fix the event is not counted:
> > > $ ./perf stat -e instructions -D 100 sleep 2
> > > Events disabled
> > > Events enabled
> > >
> > >  Performance counter stats for 'sleep 2':
> > >
> > >      <not counted>      instructions
> > >
> > >        1.901661124 seconds time elapsed
> > >
> > >        0.001602000 seconds user
> > >        0.000000000 seconds sys
> > >
> > > After fix it works:
> > > $ ./perf stat -e instructions -D 100 sleep 2
> > > Events disabled
> > > Events enabled
> > >
> > >  Performance counter stats for 'sleep 2':
> > >
> > >            404,214      instructions
> > >
> > >        1.901743475 seconds time elapsed
> > >
> > >        0.001617000 seconds user
> > >        0.000000000 seconds sys
> > >
> > > Fixes: c587e77e100f ("perf stat: Do not delay the workload with --delay")
> >
> > Yeap, even the comment states that we need to enable when initial_delay
> > is set :-)
> 
> Right, but the logic that checks the initial_delay is placed
> out of the function.  Just checking the initial_delay value
> can be confusing as it can have a negative value.
> 
> Maybe we can add an argument (bool force?) to the
> enable_counters() function.
>
Yes, it could be done.

Maybe we can fold the 'initial_delay' into 'struct target', and provide
consistent behaviour for all subcommands. Here I add a
target__enable_counter_on_exec() to determine whether enable_on_exec should
set for all counters.

$ git diff -U1
diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index c71d85577de6..e807be2214c7 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -541,8 +541,3 @@ static int enable_counters(void)

-       /*
-        * We need to enable counters only if:
-        * - we don't have tracee (attaching to task or cpu)
-        * - we have initial delay configured
-        */
-       if (!target__none(&target) || stat_config.initial_delay) {
+       if (!target__enable_counter_on_exec(&target)) {
                if (!all_counters_use_bpf)
@@ -916,3 +911,3 @@ static int __run_perf_stat(int argc, const char **argv, int run_idx)

-       if (stat_config.initial_delay) {
+       if (target.initial_delay) {
                pr_info(EVLIST_DISABLED_MSG);
@@ -928,4 +923,4 @@ static int __run_perf_stat(int argc, const char **argv, int run_idx)

-       if (stat_config.initial_delay > 0) {
-               usleep(stat_config.initial_delay * USEC_PER_MSEC);
+       if (target.initial_delay > 0) {
+               usleep(target.initial_delay * USEC_PER_MSEC);
                err = enable_counters();
@@ -1250,3 +1245,3 @@ static struct option stat_options[] = {
                     "aggregate counts per numa node", AGGR_NODE),
-       OPT_INTEGER('D', "delay", &stat_config.initial_delay,
+       OPT_INTEGER('D', "delay", &target.initial_delay,
                    "ms to wait before starting measurement after program start (-1: start with events disabled)"),
diff --git a/tools/perf/util/stat.c b/tools/perf/util/stat.c
index 534d36d26fc3..40984d124db1 100644
--- a/tools/perf/util/stat.c
+++ b/tools/perf/util/stat.c
@@ -848,3 +848,3 @@ int create_perf_stat_counter(struct evsel *evsel,
                 */
-               if (target__none(target) && !config->initial_delay)
+               if (target__enable_counter_on_exec(target))
                        attr->enable_on_exec = 1;
diff --git a/tools/perf/util/target.h b/tools/perf/util/target.h
index daec6cba500d..a6721b644bfb 100644
--- a/tools/perf/util/target.h
+++ b/tools/perf/util/target.h
@@ -20,2 +20,3 @@ struct target {
        bool         hybrid;
+       int          initial_delay;
        const char   *attr_map;
@@ -74,2 +75,7 @@ static inline bool target__none(struct target *target)

+static inline bool target__enable_counter_on_exec(struct target *target)
+{
+       return target__none(target) && !target->initial_delay;
+}
+

> Thanks,
> Namhyung
> 
> 
> >
> > I added the additional test output below.
> >
> > Namhyung, can you please ack it?
> >
> > - Arnaldo
> >
> > Committer testing:
> >
> > Before:
> >
> > Lets use stress-ng so that we have lots of samples using a CPU stressor
> > and also intermingle the workload output with the messages about when
> > the events get enabled (i.e. later on in the workload):
> >
> >   $ perf stat -e instructions -D 100 stress-ng -c 32 -t 1
> >   Events disabled
> >   stress-ng: info:  [38361] setting to a 1 second run per stressor
> >   stress-ng: info:  [38361] dispatching hogs: 32 cpu
> >   Events enabled
> >   stress-ng: info:  [38361] successful run completed in 1.01s
> >
> >    Performance counter stats for 'stress-ng -c 32 -t 1':
> >
> >        <not counted>      instructions:u
> >
> >          0.916479141 seconds time elapsed
> >
> >         30.868003000 seconds user
> >          0.049851000 seconds sys
> >
> >
> >   Some events weren't counted. Try disabling the NMI watchdog:
> >         echo 0 > /proc/sys/kernel/nmi_watchdog
> >         perf stat ...
> >         echo 1 > /proc/sys/kernel/nmi_watchdog
> >   $
> >
> > After the fix:
> >
> >   $ perf stat -e instructions -D 100 stress-ng -c 32 -t 1
> >   Events disabled
> >   stress-ng: info:  [40429] setting to a 1 second run per stressor
> >   stress-ng: info:  [40429] dispatching hogs: 32 cpu
> >   Events enabled
> >   stress-ng: info:  [40429] successful run completed in 1.01s
> >
> >    Performance counter stats for 'stress-ng -c 32 -t 1':
> >
> >         154117865145      instructions:u
> >
> >          0.920827644 seconds time elapsed
> >
> >         30.864753000 seconds user
> >          0.073862000 seconds sys
> >
> >
> >   $
> >
> > > Signed-off-by: Changbin Du <changbin.du@huawei.com>
> > > ---
> > >  tools/perf/builtin-stat.c | 2 +-
> > >  1 file changed, 1 insertion(+), 1 deletion(-)
> > >
> > > diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
> > > index 9f3e4b257516..c71d85577de6 100644
> > > --- a/tools/perf/builtin-stat.c
> > > +++ b/tools/perf/builtin-stat.c
> > > @@ -544,7 +544,7 @@ static int enable_counters(void)
> > >        * - we don't have tracee (attaching to task or cpu)
> > >        * - we have initial delay configured
> > >        */
> > > -     if (!target__none(&target)) {
> > > +     if (!target__none(&target) || stat_config.initial_delay) {
> > >               if (!all_counters_use_bpf)
> > >                       evlist__enable(evsel_list);
> > >       }
> > > --
> > > 2.25.1
> > >
> >
> > --
> >
> > - Arnaldo
>
  

On Thu, Feb 23, 2023 at 11:25 PM Changbin Du <changbin.du@huawei.com> wrote:
>
> On Thu, Feb 23, 2023 at 02:48:26PM -0800, Namhyung Kim wrote:
> > Hello,
> >
> > On Thu, Feb 23, 2023 at 5:45 AM Arnaldo Carvalho de Melo
> > <acme@kernel.org> wrote:
> > >
> > > Em Thu, Feb 23, 2023 at 03:58:00PM +0800, Changbin Du escreveu:
> > > > When creating counters with initial delay configured, the enable_on_exec
> > > > field is not set. So we need to enable the counters later. The problem
> > > > is, when a workload is specified the target__none() is still true. So
> > > > we also need to check stat_config.initial_delay.
> > > >
> > > > Before this fix the event is not counted:
> > > > $ ./perf stat -e instructions -D 100 sleep 2
> > > > Events disabled
> > > > Events enabled
> > > >
> > > >  Performance counter stats for 'sleep 2':
> > > >
> > > >      <not counted>      instructions
> > > >
> > > >        1.901661124 seconds time elapsed
> > > >
> > > >        0.001602000 seconds user
> > > >        0.000000000 seconds sys
> > > >
> > > > After fix it works:
> > > > $ ./perf stat -e instructions -D 100 sleep 2
> > > > Events disabled
> > > > Events enabled
> > > >
> > > >  Performance counter stats for 'sleep 2':
> > > >
> > > >            404,214      instructions
> > > >
> > > >        1.901743475 seconds time elapsed
> > > >
> > > >        0.001617000 seconds user
> > > >        0.000000000 seconds sys
> > > >
> > > > Fixes: c587e77e100f ("perf stat: Do not delay the workload with --delay")
> > >
> > > Yeap, even the comment states that we need to enable when initial_delay
> > > is set :-)
> >
> > Right, but the logic that checks the initial_delay is placed
> > out of the function.  Just checking the initial_delay value
> > can be confusing as it can have a negative value.
> >
> > Maybe we can add an argument (bool force?) to the
> > enable_counters() function.
> >
> Yes, it could be done.
>
> Maybe we can fold the 'initial_delay' into 'struct target', and provide
> consistent behaviour for all subcommands. Here I add a
> target__enable_counter_on_exec() to determine whether enable_on_exec should
> set for all counters.

Maybe just target__enable_on_exec() ?  Note that we have
similar logic in the perf record.  Otherwise looks good.

Thanks,
Namhyung

>
> $ git diff -U1
> diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
> index c71d85577de6..e807be2214c7 100644
> --- a/tools/perf/builtin-stat.c
> +++ b/tools/perf/builtin-stat.c
> @@ -541,8 +541,3 @@ static int enable_counters(void)
>
> -       /*
> -        * We need to enable counters only if:
> -        * - we don't have tracee (attaching to task or cpu)
> -        * - we have initial delay configured
> -        */
> -       if (!target__none(&target) || stat_config.initial_delay) {
> +       if (!target__enable_counter_on_exec(&target)) {
>                 if (!all_counters_use_bpf)
> @@ -916,3 +911,3 @@ static int __run_perf_stat(int argc, const char **argv, int run_idx)
>
> -       if (stat_config.initial_delay) {
> +       if (target.initial_delay) {
>                 pr_info(EVLIST_DISABLED_MSG);
> @@ -928,4 +923,4 @@ static int __run_perf_stat(int argc, const char **argv, int run_idx)
>
> -       if (stat_config.initial_delay > 0) {
> -               usleep(stat_config.initial_delay * USEC_PER_MSEC);
> +       if (target.initial_delay > 0) {
> +               usleep(target.initial_delay * USEC_PER_MSEC);
>                 err = enable_counters();
> @@ -1250,3 +1245,3 @@ static struct option stat_options[] = {
>                      "aggregate counts per numa node", AGGR_NODE),
> -       OPT_INTEGER('D', "delay", &stat_config.initial_delay,
> +       OPT_INTEGER('D', "delay", &target.initial_delay,
>                     "ms to wait before starting measurement after program start (-1: start with events disabled)"),
> diff --git a/tools/perf/util/stat.c b/tools/perf/util/stat.c
> index 534d36d26fc3..40984d124db1 100644
> --- a/tools/perf/util/stat.c
> +++ b/tools/perf/util/stat.c
> @@ -848,3 +848,3 @@ int create_perf_stat_counter(struct evsel *evsel,
>                  */
> -               if (target__none(target) && !config->initial_delay)
> +               if (target__enable_counter_on_exec(target))
>                         attr->enable_on_exec = 1;
> diff --git a/tools/perf/util/target.h b/tools/perf/util/target.h
> index daec6cba500d..a6721b644bfb 100644
> --- a/tools/perf/util/target.h
> +++ b/tools/perf/util/target.h
> @@ -20,2 +20,3 @@ struct target {
>         bool         hybrid;
> +       int          initial_delay;
>         const char   *attr_map;
> @@ -74,2 +75,7 @@ static inline bool target__none(struct target *target)
>
> +static inline bool target__enable_counter_on_exec(struct target *target)
> +{
> +       return target__none(target) && !target->initial_delay;
> +}
> +
>
> > Thanks,
> > Namhyung
> >
> >
> > >
> > > I added the additional test output below.
> > >
> > > Namhyung, can you please ack it?
> > >
> > > - Arnaldo
> > >
> > > Committer testing:
> > >
> > > Before:
> > >
> > > Lets use stress-ng so that we have lots of samples using a CPU stressor
> > > and also intermingle the workload output with the messages about when
> > > the events get enabled (i.e. later on in the workload):
> > >
> > >   $ perf stat -e instructions -D 100 stress-ng -c 32 -t 1
> > >   Events disabled
> > >   stress-ng: info:  [38361] setting to a 1 second run per stressor
> > >   stress-ng: info:  [38361] dispatching hogs: 32 cpu
> > >   Events enabled
> > >   stress-ng: info:  [38361] successful run completed in 1.01s
> > >
> > >    Performance counter stats for 'stress-ng -c 32 -t 1':
> > >
> > >        <not counted>      instructions:u
> > >
> > >          0.916479141 seconds time elapsed
> > >
> > >         30.868003000 seconds user
> > >          0.049851000 seconds sys
> > >
> > >
> > >   Some events weren't counted. Try disabling the NMI watchdog:
> > >         echo 0 > /proc/sys/kernel/nmi_watchdog
> > >         perf stat ...
> > >         echo 1 > /proc/sys/kernel/nmi_watchdog
> > >   $
> > >
> > > After the fix:
> > >
> > >   $ perf stat -e instructions -D 100 stress-ng -c 32 -t 1
> > >   Events disabled
> > >   stress-ng: info:  [40429] setting to a 1 second run per stressor
> > >   stress-ng: info:  [40429] dispatching hogs: 32 cpu
> > >   Events enabled
> > >   stress-ng: info:  [40429] successful run completed in 1.01s
> > >
> > >    Performance counter stats for 'stress-ng -c 32 -t 1':
> > >
> > >         154117865145      instructions:u
> > >
> > >          0.920827644 seconds time elapsed
> > >
> > >         30.864753000 seconds user
> > >          0.073862000 seconds sys
> > >
> > >
> > >   $
> > >
> > > > Signed-off-by: Changbin Du <changbin.du@huawei.com>
> > > > ---
> > > >  tools/perf/builtin-stat.c | 2 +-
> > > >  1 file changed, 1 insertion(+), 1 deletion(-)
> > > >
> > > > diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
> > > > index 9f3e4b257516..c71d85577de6 100644
> > > > --- a/tools/perf/builtin-stat.c
> > > > +++ b/tools/perf/builtin-stat.c
> > > > @@ -544,7 +544,7 @@ static int enable_counters(void)
> > > >        * - we don't have tracee (attaching to task or cpu)
> > > >        * - we have initial delay configured
> > > >        */
> > > > -     if (!target__none(&target)) {
> > > > +     if (!target__none(&target) || stat_config.initial_delay) {
> > > >               if (!all_counters_use_bpf)
> > > >                       evlist__enable(evsel_list);
> > > >       }
> > > > --
> > > > 2.25.1
> > > >
> > >
> > > --
> > >
> > > - Arnaldo
> >
>
> --
> Cheers,
> Changbin Du