All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH 0/2] perf test: Fix JSON linter
@ 2023-01-20 13:40 Michael Petlan
  2023-01-20 13:40 ` [PATCH 1/2] perf stat: Fix JSON metric printout for multiple metrics per line Michael Petlan
                   ` (2 more replies)
  0 siblings, 3 replies; 18+ messages in thread
From: Michael Petlan @ 2023-01-20 13:40 UTC (permalink / raw)
  To: linux-perf-users, acme; +Cc: acme, qzhao, cjense

Hello all.

We have observed issues with the 'perf stat JSON output linter' testcase
on systems that allow topdown metrics.

=========================

1) The topdown metrics handling hardcodes printing more than one metric
per line (refer to util/stat-shadow.c):

    if (retiring > 0.7 && heavy_ops > 0.1)
        color = PERF_COLOR_GREEN;
    print_metric(config, ctxp, color, "%8.1f%%", "Heavy Operations",
            heavy_ops * 100.);
    if (retiring > 0.7 && light_ops > 0.6)
        color = PERF_COLOR_GREEN;
    else
        color = NULL;
    print_metric(config, ctxp, color, "%8.1f%%", "Light Operations",
            light_ops * 100.);

Thus, the test cannot rely on the fact that there will be only one
metric per line.

2) Since the JSON printing engine thinks that one and only one metric
is printed, it always closes the line by adding '}'. This is not true,
so I have fixed the comma printing and adjusted the engine to be
capable of printing 1-N metrics and then close the line.

=========================

On machines that don't support topdown, the problem can be shown by
doubling the following line in util/stat-shadow.c, so that the simple
'insn per cycle' metric is printed twice:

  print_metric(config, ctxp, NULL, "%7.2f ", "insn per cycle", ratio);

The worst problem is that the JSON line is broken, such as:

... "pcnt-running" : 100.00, "metric-value" : 3.501931, "metric-unit"
    : "Heavy Operations"}"metric-value" : 14.007787, "metric-unit" : ...
                  here ^^^^^

=========================

The first patch solves the JSON output correctness, the second tries
to adjust the testcase to some extent, so that it should work on the
topdown-capable machines.

However, it's highly possible that the testcase will have to be fixed
or maybe rewritten in future. First, it has quite naive evaluation of
what's expected/correct/etc. Second, it does no JSON format validation
at all. As a linter it should do so though.

 ***

For further discussion: What about removing the check for number of
expected elements in the line and just check for the keywords, such
as "metric-value", "counter-value", "event", etc. and for some values
that should be numeric. And, do proper JSON format sanity check?


Thank you for inputs!

Michael




Michael Petlan (2):
  perf stat: Fix JSON metric printout for multiple metrics per line
  perf test: Fix JSON format linter test checks

 .../tests/shell/lib/perf_json_output_lint.py  | 16 +++++------
 tools/perf/util/stat-display.c                | 28 +++++++++++--------
 2 files changed, 24 insertions(+), 20 deletions(-)

--
2.18.4


^ permalink raw reply	[flat|nested] 18+ messages in thread

* [PATCH 1/2] perf stat: Fix JSON metric printout for multiple metrics per line
  2023-01-20 13:40 [PATCH 0/2] perf test: Fix JSON linter Michael Petlan
@ 2023-01-20 13:40 ` Michael Petlan
  2023-01-23  6:31   ` Namhyung Kim
  2023-05-22 12:11   ` Michael Petlan
  2023-01-20 13:40 ` [PATCH 2/2] perf test: Fix JSON format linter test checks Michael Petlan
  2023-01-20 17:37 ` [PATCH 0/2] perf test: Fix JSON linter Ian Rogers
  2 siblings, 2 replies; 18+ messages in thread
From: Michael Petlan @ 2023-01-20 13:40 UTC (permalink / raw)
  To: linux-perf-users, acme; +Cc: acme, qzhao, cjense

JSON printing engine used to always print metric (even when there should
be none and other engines (std, csv) would not print it) and the metric
used to always close the line by printing a closing curly bracket.

This caused invalid JSON output being generated for top-down metrics,
when multiple metrics are printed on a single line, so the broken output
might have looked like:

  ... "metric-value" : 15.564203, "metric-unit" : \
  "Memory Bound"}"metric-value" : 14.007787, "metric-unit" : "Core Bound"}

To fix it, print always the separating comma BEFORE the key:value pairs
and close the line outside of the JSON metric printing routine.

Fixes: df936cadfb58 ("perf stat: Add JSON output option")

Signed-off-by: Michael Petlan <mpetlan@redhat.com>
---
 tools/perf/util/stat-display.c | 28 ++++++++++++++++------------
 1 file changed, 16 insertions(+), 12 deletions(-)

diff --git a/tools/perf/util/stat-display.c b/tools/perf/util/stat-display.c
index 8bd8b0142630..8f80f6b566d0 100644
--- a/tools/perf/util/stat-display.c
+++ b/tools/perf/util/stat-display.c
@@ -86,7 +86,7 @@ static void print_running_json(struct perf_stat_config *config, u64 run, u64 ena
 
 	if (run != ena)
 		enabled_percent = 100 * run / ena;
-	fprintf(config->output, "\"event-runtime\" : %" PRIu64 ", \"pcnt-running\" : %.2f, ",
+	fprintf(config->output, ", \"event-runtime\" : %" PRIu64 ", \"pcnt-running\" : %.2f",
 		run, enabled_percent);
 }
 
@@ -121,7 +121,7 @@ static void print_noise_pct_csv(struct perf_stat_config *config,
 static void print_noise_pct_json(struct perf_stat_config *config,
 				 double pct)
 {
-	fprintf(config->output, "\"variance\" : %.2f, ", pct);
+	fprintf(config->output, ", \"variance\" : %.2f", pct);
 }
 
 static void print_noise_pct(struct perf_stat_config *config,
@@ -165,7 +165,7 @@ static void print_cgroup_csv(struct perf_stat_config *config, const char *cgrp_n
 
 static void print_cgroup_json(struct perf_stat_config *config, const char *cgrp_name)
 {
-	fprintf(config->output, "\"cgroup\" : \"%s\", ", cgrp_name);
+	fprintf(config->output, ", \"cgroup\" : \"%s\"", cgrp_name);
 }
 
 static void print_cgroup(struct perf_stat_config *config, struct cgroup *cgrp)
@@ -431,10 +431,11 @@ static void print_metric_json(struct perf_stat_config *config __maybe_unused,
 	struct outstate *os = ctx;
 	FILE *out = os->fh;
 
-	fprintf(out, "\"metric-value\" : %f, ", val);
-	fprintf(out, "\"metric-unit\" : \"%s\"", unit);
-	if (!config->metric_only)
-		fprintf(out, "}");
+	if (unit == NULL || fmt == NULL)
+		return;
+
+	fprintf(out, ", \"metric-value\" : %f", val);
+	fprintf(out, ", \"metric-unit\" : \"%s\"", unit);
 }
 
 static void new_line_json(struct perf_stat_config *config, void *ctx)
@@ -623,14 +624,14 @@ static void print_counter_value_json(struct perf_stat_config *config,
 	const char *bad_count = evsel->supported ? CNTR_NOT_COUNTED : CNTR_NOT_SUPPORTED;
 
 	if (ok)
-		fprintf(output, "\"counter-value\" : \"%f\", ", avg);
+		fprintf(output, "\"counter-value\" : \"%f\"", avg);
 	else
-		fprintf(output, "\"counter-value\" : \"%s\", ", bad_count);
+		fprintf(output, "\"counter-value\" : \"%s\"", bad_count);
 
 	if (evsel->unit)
-		fprintf(output, "\"unit\" : \"%s\", ", evsel->unit);
+		fprintf(output, ", \"unit\" : \"%s\"", evsel->unit);
 
-	fprintf(output, "\"event\" : \"%s\", ", evsel__name(evsel));
+	fprintf(output, ", \"event\" : \"%s\"", evsel__name(evsel));
 }
 
 static void print_counter_value(struct perf_stat_config *config,
@@ -835,8 +836,11 @@ static void print_counter_aggrdata(struct perf_stat_config *config,
 
 	printout(config, os, uval, run, ena, avg, s);
 
-	if (!metric_only)
+	if (!metric_only) {
+		if (config->json_output)
+			fputc('}', output);
 		fputc('\n', output);
+	}
 }
 
 static void print_metric_begin(struct perf_stat_config *config,
-- 
2.18.4


^ permalink raw reply related	[flat|nested] 18+ messages in thread

* [PATCH 2/2] perf test: Fix JSON format linter test checks
  2023-01-20 13:40 [PATCH 0/2] perf test: Fix JSON linter Michael Petlan
  2023-01-20 13:40 ` [PATCH 1/2] perf stat: Fix JSON metric printout for multiple metrics per line Michael Petlan
@ 2023-01-20 13:40 ` Michael Petlan
  2023-01-23  6:36   ` Namhyung Kim
  2023-01-27 12:26   ` Arnaldo Carvalho de Melo
  2023-01-20 17:37 ` [PATCH 0/2] perf test: Fix JSON linter Ian Rogers
  2 siblings, 2 replies; 18+ messages in thread
From: Michael Petlan @ 2023-01-20 13:40 UTC (permalink / raw)
  To: linux-perf-users, acme; +Cc: acme, qzhao, cjense

The test fails on CPUs with topdown metrics, where it is common to print
two metrics per line. Since these are included in default event set for
`perf stat -- something`, it causes the "no args" subtest to fail due to
unexpected member count. We need to accept 7 or 9 members in that case.

Coming to that, counting commas in the JSON line and consider it a number
of elements is incorrect and misleading. There should be +1 element than
the count of commas, while also, commas can potentially appear in the
event names. Count " : " substrings rather, since these better fit to
what should be actually counted.

Fixes: 0c343af2a2f8 ("perf test: JSON format checking")

Signed-off-by: Michael Petlan <mpetlan@redhat.com>
---
 .../tests/shell/lib/perf_json_output_lint.py     | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/tools/perf/tests/shell/lib/perf_json_output_lint.py b/tools/perf/tests/shell/lib/perf_json_output_lint.py
index d90f8d102eb9..4f1bbb3f07ec 100644
--- a/tools/perf/tests/shell/lib/perf_json_output_lint.py
+++ b/tools/perf/tests/shell/lib/perf_json_output_lint.py
@@ -40,17 +40,17 @@ def is_counter_value(num):
   return isfloat(num) or num == '<not counted>' or num == '<not supported>'
 
 def check_json_output(expected_items):
-  if expected_items != -1:
+  if expected_items:
     for line in Lines:
       if 'failed' not in line:
         count = 0
-        count = line.count(',')
-        if count != expected_items and count >= 1 and count <= 3 and 'metric-value' in line:
+        count = line.count(' : ')
+        if count not in expected_items and count >= 2 and count <= 4 and 'metric-value' in line:
           # Events that generate >1 metric may have isolated metric
           # values and possibly other prefixes like interval, core and
           # aggregate-number.
           continue
-        if count != expected_items:
+        if count not in expected_items:
           raise RuntimeError(f'wrong number of fields. counted {count} expected {expected_items}'
                              f' in \'{line}\'')
   checks = {
@@ -82,14 +82,14 @@ def check_json_output(expected_items):
 
 try:
   if args.no_args or args.system_wide or args.event:
-    expected_items = 6
+    expected_items = [7, 9]
   elif args.interval or args.per_thread or args.system_wide_no_aggr:
-    expected_items = 7
+    expected_items = [8, 10]
   elif args.per_core or args.per_socket or args.per_node or args.per_die:
-    expected_items = 8
+    expected_items = [9, 11]
   else:
     # If no option is specified, don't check the number of items.
-    expected_items = -1
+    expected_items = []
   check_json_output(expected_items)
 except:
   print('Test failed for input:\n' + '\n'.join(Lines))
-- 
2.18.4


^ permalink raw reply related	[flat|nested] 18+ messages in thread

* Re: [PATCH 0/2] perf test: Fix JSON linter
  2023-01-20 13:40 [PATCH 0/2] perf test: Fix JSON linter Michael Petlan
  2023-01-20 13:40 ` [PATCH 1/2] perf stat: Fix JSON metric printout for multiple metrics per line Michael Petlan
  2023-01-20 13:40 ` [PATCH 2/2] perf test: Fix JSON format linter test checks Michael Petlan
@ 2023-01-20 17:37 ` Ian Rogers
  2023-01-23  6:48   ` Namhyung Kim
                     ` (2 more replies)
  2 siblings, 3 replies; 18+ messages in thread
From: Ian Rogers @ 2023-01-20 17:37 UTC (permalink / raw)
  To: Michael Petlan, Namhyung Kim; +Cc: linux-perf-users, acme, acme, qzhao, cjense

On Fri, Jan 20, 2023 at 5:41 AM Michael Petlan <mpetlan@redhat.com> wrote:
>
> Hello all.
>
> We have observed issues with the 'perf stat JSON output linter' testcase
> on systems that allow topdown metrics.
>
> =========================
>
> 1) The topdown metrics handling hardcodes printing more than one metric
> per line (refer to util/stat-shadow.c):
>
>     if (retiring > 0.7 && heavy_ops > 0.1)
>         color = PERF_COLOR_GREEN;
>     print_metric(config, ctxp, color, "%8.1f%%", "Heavy Operations",
>             heavy_ops * 100.);
>     if (retiring > 0.7 && light_ops > 0.6)
>         color = PERF_COLOR_GREEN;
>     else
>         color = NULL;
>     print_metric(config, ctxp, color, "%8.1f%%", "Light Operations",
>             light_ops * 100.);
>
> Thus, the test cannot rely on the fact that there will be only one
> metric per line.

Right, these implicit metrics are also an issue with --metric-only. It
isn't clear from the command line flags when implicit and listed
metrics should be generated. The topdown events (Icelake+) made the
implicit metric problem worse, and they likely didn't exist or weren't
tested at the time of the json output.

> 2) Since the JSON printing engine thinks that one and only one metric
> is printed, it always closes the line by adding '}'. This is not true,
> so I have fixed the comma printing and adjusted the engine to be
> capable of printing 1-N metrics and then close the line.

So the current printing code is messy. For example, there is a newline
callback function, but that has little meaning for json where
everything is on a newline. For CSV mode, adding a summary used to
cause a column to suddenly appear on the left for the row containing
the summary. I believe the right thing to do is a refactor and
recently I did a similar refactor for 'perf list':
https://lore.kernel.org/lkml/20221114210723.2749751-11-irogers@google.com/
So it is strange that metrics are "shadows" of events, but whatever
the point is to think about the printing API. In the change linked
above you can see that everytime something is printed the print
handling code is given all the information and the print handling code
has state. Based on the state and callback's information, the print
handling code can do nothing, properly format for CSV, json, etc. This
gets completely away from the kind of madness of branches and
whac-a-mole the code currently has.

I'm happy to look at doing the refactor to be similar to 'perf
list'/builtin-list.c. Namhyung I thought might have gotten to it with
his recent work on improving aggregation. If I hear silence then I'll
assume that is a request I do it :-)

Pragmatically in the short term we could land your changes, but I
worry they are more of the whac-a-mole and something somewhere else
will break. Which is why we have a test, and so I'm not overly
worried. I can download and test too.

Anyway, sorry for the issue and let me know what you think. Thanks,
Ian


> =========================
>
> On machines that don't support topdown, the problem can be shown by
> doubling the following line in util/stat-shadow.c, so that the simple
> 'insn per cycle' metric is printed twice:
>
>   print_metric(config, ctxp, NULL, "%7.2f ", "insn per cycle", ratio);
>
> The worst problem is that the JSON line is broken, such as:
>
> ... "pcnt-running" : 100.00, "metric-value" : 3.501931, "metric-unit"
>     : "Heavy Operations"}"metric-value" : 14.007787, "metric-unit" : ...
>                   here ^^^^^
>
> =========================
>
> The first patch solves the JSON output correctness, the second tries
> to adjust the testcase to some extent, so that it should work on the
> topdown-capable machines.
>
> However, it's highly possible that the testcase will have to be fixed
> or maybe rewritten in future. First, it has quite naive evaluation of
> what's expected/correct/etc. Second, it does no JSON format validation
> at all. As a linter it should do so though.
>
>  ***
>
> For further discussion: What about removing the check for number of
> expected elements in the line and just check for the keywords, such
> as "metric-value", "counter-value", "event", etc. and for some values
> that should be numeric. And, do proper JSON format sanity check?
>
>
> Thank you for inputs!
>
> Michael
>
>
>
>
> Michael Petlan (2):
>   perf stat: Fix JSON metric printout for multiple metrics per line
>   perf test: Fix JSON format linter test checks
>
>  .../tests/shell/lib/perf_json_output_lint.py  | 16 +++++------
>  tools/perf/util/stat-display.c                | 28 +++++++++++--------
>  2 files changed, 24 insertions(+), 20 deletions(-)
>
> --
> 2.18.4
>

^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 1/2] perf stat: Fix JSON metric printout for multiple metrics per line
  2023-01-20 13:40 ` [PATCH 1/2] perf stat: Fix JSON metric printout for multiple metrics per line Michael Petlan
@ 2023-01-23  6:31   ` Namhyung Kim
  2023-05-22 12:11   ` Michael Petlan
  1 sibling, 0 replies; 18+ messages in thread
From: Namhyung Kim @ 2023-01-23  6:31 UTC (permalink / raw)
  To: Michael Petlan; +Cc: linux-perf-users, acme, acme, qzhao, cjense

Hello Michael,

On Fri, Jan 20, 2023 at 5:47 AM Michael Petlan <mpetlan@redhat.com> wrote:
>
> JSON printing engine used to always print metric (even when there should
> be none and other engines (std, csv) would not print it) and the metric
> used to always close the line by printing a closing curly bracket.
>
> This caused invalid JSON output being generated for top-down metrics,
> when multiple metrics are printed on a single line, so the broken output
> might have looked like:
>
>   ... "metric-value" : 15.564203, "metric-unit" : \
>   "Memory Bound"}"metric-value" : 14.007787, "metric-unit" : "Core Bound"}
>
> To fix it, print always the separating comma BEFORE the key:value pairs
> and close the line outside of the JSON metric printing routine.
>
> Fixes: df936cadfb58 ("perf stat: Add JSON output option")
>
> Signed-off-by: Michael Petlan <mpetlan@redhat.com>

Acked-by: Namhyung Kim <namhyung@kernel.org>

Thanks for the fix, a nitpick below..


> ---
>  tools/perf/util/stat-display.c | 28 ++++++++++++++++------------
>  1 file changed, 16 insertions(+), 12 deletions(-)
>
> diff --git a/tools/perf/util/stat-display.c b/tools/perf/util/stat-display.c
> index 8bd8b0142630..8f80f6b566d0 100644
> --- a/tools/perf/util/stat-display.c
> +++ b/tools/perf/util/stat-display.c
> @@ -86,7 +86,7 @@ static void print_running_json(struct perf_stat_config *config, u64 run, u64 ena
>
>         if (run != ena)
>                 enabled_percent = 100 * run / ena;
> -       fprintf(config->output, "\"event-runtime\" : %" PRIu64 ", \"pcnt-running\" : %.2f, ",
> +       fprintf(config->output, ", \"event-runtime\" : %" PRIu64 ", \"pcnt-running\" : %.2f",
>                 run, enabled_percent);
>  }
>
> @@ -121,7 +121,7 @@ static void print_noise_pct_csv(struct perf_stat_config *config,
>  static void print_noise_pct_json(struct perf_stat_config *config,
>                                  double pct)
>  {
> -       fprintf(config->output, "\"variance\" : %.2f, ", pct);
> +       fprintf(config->output, ", \"variance\" : %.2f", pct);
>  }
>
>  static void print_noise_pct(struct perf_stat_config *config,
> @@ -165,7 +165,7 @@ static void print_cgroup_csv(struct perf_stat_config *config, const char *cgrp_n
>
>  static void print_cgroup_json(struct perf_stat_config *config, const char *cgrp_name)
>  {
> -       fprintf(config->output, "\"cgroup\" : \"%s\", ", cgrp_name);
> +       fprintf(config->output, ", \"cgroup\" : \"%s\"", cgrp_name);
>  }
>
>  static void print_cgroup(struct perf_stat_config *config, struct cgroup *cgrp)
> @@ -431,10 +431,11 @@ static void print_metric_json(struct perf_stat_config *config __maybe_unused,
>         struct outstate *os = ctx;
>         FILE *out = os->fh;
>
> -       fprintf(out, "\"metric-value\" : %f, ", val);
> -       fprintf(out, "\"metric-unit\" : \"%s\"", unit);
> -       if (!config->metric_only)
> -               fprintf(out, "}");
> +       if (unit == NULL || fmt == NULL)
> +               return;

This seems like a separate fix.

Thanks,
Namhyung


> +
> +       fprintf(out, ", \"metric-value\" : %f", val);
> +       fprintf(out, ", \"metric-unit\" : \"%s\"", unit);
>  }
>
>  static void new_line_json(struct perf_stat_config *config, void *ctx)
> @@ -623,14 +624,14 @@ static void print_counter_value_json(struct perf_stat_config *config,
>         const char *bad_count = evsel->supported ? CNTR_NOT_COUNTED : CNTR_NOT_SUPPORTED;
>
>         if (ok)
> -               fprintf(output, "\"counter-value\" : \"%f\", ", avg);
> +               fprintf(output, "\"counter-value\" : \"%f\"", avg);
>         else
> -               fprintf(output, "\"counter-value\" : \"%s\", ", bad_count);
> +               fprintf(output, "\"counter-value\" : \"%s\"", bad_count);
>
>         if (evsel->unit)
> -               fprintf(output, "\"unit\" : \"%s\", ", evsel->unit);
> +               fprintf(output, ", \"unit\" : \"%s\"", evsel->unit);
>
> -       fprintf(output, "\"event\" : \"%s\", ", evsel__name(evsel));
> +       fprintf(output, ", \"event\" : \"%s\"", evsel__name(evsel));
>  }
>
>  static void print_counter_value(struct perf_stat_config *config,
> @@ -835,8 +836,11 @@ static void print_counter_aggrdata(struct perf_stat_config *config,
>
>         printout(config, os, uval, run, ena, avg, s);
>
> -       if (!metric_only)
> +       if (!metric_only) {
> +               if (config->json_output)
> +                       fputc('}', output);
>                 fputc('\n', output);
> +       }
>  }
>
>  static void print_metric_begin(struct perf_stat_config *config,
> --
> 2.18.4
>

^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 2/2] perf test: Fix JSON format linter test checks
  2023-01-20 13:40 ` [PATCH 2/2] perf test: Fix JSON format linter test checks Michael Petlan
@ 2023-01-23  6:36   ` Namhyung Kim
  2023-01-24 16:49     ` Michael Petlan
  2023-01-27 12:26   ` Arnaldo Carvalho de Melo
  1 sibling, 1 reply; 18+ messages in thread
From: Namhyung Kim @ 2023-01-23  6:36 UTC (permalink / raw)
  To: Michael Petlan; +Cc: linux-perf-users, acme, acme, qzhao, cjense

On Fri, Jan 20, 2023 at 6:00 AM Michael Petlan <mpetlan@redhat.com> wrote:
>
> The test fails on CPUs with topdown metrics, where it is common to print
> two metrics per line. Since these are included in default event set for
> `perf stat -- something`, it causes the "no args" subtest to fail due to
> unexpected member count. We need to accept 7 or 9 members in that case.
>
> Coming to that, counting commas in the JSON line and consider it a number
> of elements is incorrect and misleading. There should be +1 element than
> the count of commas, while also, commas can potentially appear in the
> event names. Count " : " substrings rather, since these better fit to
> what should be actually counted.

I'm also curious if ":" could appear in the event/metric names.
Probably more chances to have ":" than "," in the name, no?

Thanks,
Namhyung


>
> Fixes: 0c343af2a2f8 ("perf test: JSON format checking")
>
> Signed-off-by: Michael Petlan <mpetlan@redhat.com>
> ---
>  .../tests/shell/lib/perf_json_output_lint.py     | 16 ++++++++--------
>  1 file changed, 8 insertions(+), 8 deletions(-)
>
> diff --git a/tools/perf/tests/shell/lib/perf_json_output_lint.py b/tools/perf/tests/shell/lib/perf_json_output_lint.py
> index d90f8d102eb9..4f1bbb3f07ec 100644
> --- a/tools/perf/tests/shell/lib/perf_json_output_lint.py
> +++ b/tools/perf/tests/shell/lib/perf_json_output_lint.py
> @@ -40,17 +40,17 @@ def is_counter_value(num):
>    return isfloat(num) or num == '<not counted>' or num == '<not supported>'
>
>  def check_json_output(expected_items):
> -  if expected_items != -1:
> +  if expected_items:
>      for line in Lines:
>        if 'failed' not in line:
>          count = 0
> -        count = line.count(',')
> -        if count != expected_items and count >= 1 and count <= 3 and 'metric-value' in line:
> +        count = line.count(' : ')
> +        if count not in expected_items and count >= 2 and count <= 4 and 'metric-value' in line:
>            # Events that generate >1 metric may have isolated metric
>            # values and possibly other prefixes like interval, core and
>            # aggregate-number.
>            continue
> -        if count != expected_items:
> +        if count not in expected_items:
>            raise RuntimeError(f'wrong number of fields. counted {count} expected {expected_items}'
>                               f' in \'{line}\'')
>    checks = {
> @@ -82,14 +82,14 @@ def check_json_output(expected_items):
>
>  try:
>    if args.no_args or args.system_wide or args.event:
> -    expected_items = 6
> +    expected_items = [7, 9]
>    elif args.interval or args.per_thread or args.system_wide_no_aggr:
> -    expected_items = 7
> +    expected_items = [8, 10]
>    elif args.per_core or args.per_socket or args.per_node or args.per_die:
> -    expected_items = 8
> +    expected_items = [9, 11]
>    else:
>      # If no option is specified, don't check the number of items.
> -    expected_items = -1
> +    expected_items = []
>    check_json_output(expected_items)
>  except:
>    print('Test failed for input:\n' + '\n'.join(Lines))
> --
> 2.18.4
>

^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 0/2] perf test: Fix JSON linter
  2023-01-20 17:37 ` [PATCH 0/2] perf test: Fix JSON linter Ian Rogers
@ 2023-01-23  6:48   ` Namhyung Kim
  2023-01-23 13:38   ` Arnaldo Carvalho de Melo
  2023-01-24 17:39   ` Michael Petlan
  2 siblings, 0 replies; 18+ messages in thread
From: Namhyung Kim @ 2023-01-23  6:48 UTC (permalink / raw)
  To: Ian Rogers; +Cc: Michael Petlan, linux-perf-users, acme, acme, qzhao, cjense

On Fri, Jan 20, 2023 at 9:37 AM Ian Rogers <irogers@google.com> wrote:
>
> On Fri, Jan 20, 2023 at 5:41 AM Michael Petlan <mpetlan@redhat.com> wrote:
> >
> > Hello all.
> >
> > We have observed issues with the 'perf stat JSON output linter' testcase
> > on systems that allow topdown metrics.
> >
> > =========================
> >
> > 1) The topdown metrics handling hardcodes printing more than one metric
> > per line (refer to util/stat-shadow.c):
> >
> >     if (retiring > 0.7 && heavy_ops > 0.1)
> >         color = PERF_COLOR_GREEN;
> >     print_metric(config, ctxp, color, "%8.1f%%", "Heavy Operations",
> >             heavy_ops * 100.);
> >     if (retiring > 0.7 && light_ops > 0.6)
> >         color = PERF_COLOR_GREEN;
> >     else
> >         color = NULL;
> >     print_metric(config, ctxp, color, "%8.1f%%", "Light Operations",
> >             light_ops * 100.);
> >
> > Thus, the test cannot rely on the fact that there will be only one
> > metric per line.
>
> Right, these implicit metrics are also an issue with --metric-only. It
> isn't clear from the command line flags when implicit and listed
> metrics should be generated. The topdown events (Icelake+) made the
> implicit metric problem worse, and they likely didn't exist or weren't
> tested at the time of the json output.
>
> > 2) Since the JSON printing engine thinks that one and only one metric
> > is printed, it always closes the line by adding '}'. This is not true,
> > so I have fixed the comma printing and adjusted the engine to be
> > capable of printing 1-N metrics and then close the line.
>
> So the current printing code is messy. For example, there is a newline
> callback function, but that has little meaning for json where
> everything is on a newline. For CSV mode, adding a summary used to
> cause a column to suddenly appear on the left for the row containing
> the summary. I believe the right thing to do is a refactor and
> recently I did a similar refactor for 'perf list':
> https://lore.kernel.org/lkml/20221114210723.2749751-11-irogers@google.com/
> So it is strange that metrics are "shadows" of events, but whatever
> the point is to think about the printing API. In the change linked
> above you can see that everytime something is printed the print
> handling code is given all the information and the print handling code
> has state. Based on the state and callback's information, the print
> handling code can do nothing, properly format for CSV, json, etc. This
> gets completely away from the kind of madness of branches and
> whac-a-mole the code currently has.

Maybe we could reuse the tools/bpf/bpftool/json_writer.[ch].
It'd be nice to think about it as objects and attributes.

Thanks,
Namhyung


>
> I'm happy to look at doing the refactor to be similar to 'perf
> list'/builtin-list.c. Namhyung I thought might have gotten to it with
> his recent work on improving aggregation. If I hear silence then I'll
> assume that is a request I do it :-)
>
> Pragmatically in the short term we could land your changes, but I
> worry they are more of the whac-a-mole and something somewhere else
> will break. Which is why we have a test, and so I'm not overly
> worried. I can download and test too.
>
> Anyway, sorry for the issue and let me know what you think. Thanks,
> Ian
>
>
> > =========================
> >
> > On machines that don't support topdown, the problem can be shown by
> > doubling the following line in util/stat-shadow.c, so that the simple
> > 'insn per cycle' metric is printed twice:
> >
> >   print_metric(config, ctxp, NULL, "%7.2f ", "insn per cycle", ratio);
> >
> > The worst problem is that the JSON line is broken, such as:
> >
> > ... "pcnt-running" : 100.00, "metric-value" : 3.501931, "metric-unit"
> >     : "Heavy Operations"}"metric-value" : 14.007787, "metric-unit" : ...
> >                   here ^^^^^
> >
> > =========================
> >
> > The first patch solves the JSON output correctness, the second tries
> > to adjust the testcase to some extent, so that it should work on the
> > topdown-capable machines.
> >
> > However, it's highly possible that the testcase will have to be fixed
> > or maybe rewritten in future. First, it has quite naive evaluation of
> > what's expected/correct/etc. Second, it does no JSON format validation
> > at all. As a linter it should do so though.
> >
> >  ***
> >
> > For further discussion: What about removing the check for number of
> > expected elements in the line and just check for the keywords, such
> > as "metric-value", "counter-value", "event", etc. and for some values
> > that should be numeric. And, do proper JSON format sanity check?
> >
> >
> > Thank you for inputs!
> >
> > Michael
> >
> >
> >
> >
> > Michael Petlan (2):
> >   perf stat: Fix JSON metric printout for multiple metrics per line
> >   perf test: Fix JSON format linter test checks
> >
> >  .../tests/shell/lib/perf_json_output_lint.py  | 16 +++++------
> >  tools/perf/util/stat-display.c                | 28 +++++++++++--------
> >  2 files changed, 24 insertions(+), 20 deletions(-)
> >
> > --
> > 2.18.4
> >

^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 0/2] perf test: Fix JSON linter
  2023-01-20 17:37 ` [PATCH 0/2] perf test: Fix JSON linter Ian Rogers
  2023-01-23  6:48   ` Namhyung Kim
@ 2023-01-23 13:38   ` Arnaldo Carvalho de Melo
  2023-01-24 17:39   ` Michael Petlan
  2 siblings, 0 replies; 18+ messages in thread
From: Arnaldo Carvalho de Melo @ 2023-01-23 13:38 UTC (permalink / raw)
  To: Ian Rogers
  Cc: Michael Petlan, Namhyung Kim, linux-perf-users, acme, qzhao, cjense

Em Fri, Jan 20, 2023 at 09:37:33AM -0800, Ian Rogers escreveu:
> On Fri, Jan 20, 2023 at 5:41 AM Michael Petlan <mpetlan@redhat.com> wrote:
> >
> > Hello all.
> >
> > We have observed issues with the 'perf stat JSON output linter' testcase
> > on systems that allow topdown metrics.
> >
> > =========================
> >
> > 1) The topdown metrics handling hardcodes printing more than one metric
> > per line (refer to util/stat-shadow.c):
> >
> >     if (retiring > 0.7 && heavy_ops > 0.1)
> >         color = PERF_COLOR_GREEN;
> >     print_metric(config, ctxp, color, "%8.1f%%", "Heavy Operations",
> >             heavy_ops * 100.);
> >     if (retiring > 0.7 && light_ops > 0.6)
> >         color = PERF_COLOR_GREEN;
> >     else
> >         color = NULL;
> >     print_metric(config, ctxp, color, "%8.1f%%", "Light Operations",
> >             light_ops * 100.);
> >
> > Thus, the test cannot rely on the fact that there will be only one
> > metric per line.
> 
> Right, these implicit metrics are also an issue with --metric-only. It
> isn't clear from the command line flags when implicit and listed
> metrics should be generated. The topdown events (Icelake+) made the
> implicit metric problem worse, and they likely didn't exist or weren't
> tested at the time of the json output.
> 
> > 2) Since the JSON printing engine thinks that one and only one metric
> > is printed, it always closes the line by adding '}'. This is not true,
> > so I have fixed the comma printing and adjusted the engine to be
> > capable of printing 1-N metrics and then close the line.
> 
> So the current printing code is messy. For example, there is a newline
> callback function, but that has little meaning for json where
> everything is on a newline. For CSV mode, adding a summary used to
> cause a column to suddenly appear on the left for the row containing
> the summary. I believe the right thing to do is a refactor and
> recently I did a similar refactor for 'perf list':
> https://lore.kernel.org/lkml/20221114210723.2749751-11-irogers@google.com/
> So it is strange that metrics are "shadows" of events, but whatever
> the point is to think about the printing API. In the change linked
> above you can see that everytime something is printed the print
> handling code is given all the information and the print handling code
> has state. Based on the state and callback's information, the print
> handling code can do nothing, properly format for CSV, json, etc. This
> gets completely away from the kind of madness of branches and
> whac-a-mole the code currently has.
> 
> I'm happy to look at doing the refactor to be similar to 'perf
> list'/builtin-list.c. Namhyung I thought might have gotten to it with
> his recent work on improving aggregation. If I hear silence then I'll
> assume that is a request I do it :-)

Yeah, go for it :-)
 
> Pragmatically in the short term we could land your changes, but I

Ok, I saw Namhyung's Ack and will apply both, we can go from there.

- Arnaldo

> worry they are more of the whac-a-mole and something somewhere else
> will break. Which is why we have a test, and so I'm not overly
> worried. I can download and test too.
> 
> Anyway, sorry for the issue and let me know what you think. Thanks,
> Ian
> 
> 
> > =========================
> >
> > On machines that don't support topdown, the problem can be shown by
> > doubling the following line in util/stat-shadow.c, so that the simple
> > 'insn per cycle' metric is printed twice:
> >
> >   print_metric(config, ctxp, NULL, "%7.2f ", "insn per cycle", ratio);
> >
> > The worst problem is that the JSON line is broken, such as:
> >
> > ... "pcnt-running" : 100.00, "metric-value" : 3.501931, "metric-unit"
> >     : "Heavy Operations"}"metric-value" : 14.007787, "metric-unit" : ...
> >                   here ^^^^^
> >
> > =========================
> >
> > The first patch solves the JSON output correctness, the second tries
> > to adjust the testcase to some extent, so that it should work on the
> > topdown-capable machines.
> >
> > However, it's highly possible that the testcase will have to be fixed
> > or maybe rewritten in future. First, it has quite naive evaluation of
> > what's expected/correct/etc. Second, it does no JSON format validation
> > at all. As a linter it should do so though.
> >
> >  ***
> >
> > For further discussion: What about removing the check for number of
> > expected elements in the line and just check for the keywords, such
> > as "metric-value", "counter-value", "event", etc. and for some values
> > that should be numeric. And, do proper JSON format sanity check?
> >
> >
> > Thank you for inputs!
> >
> > Michael
> >
> >
> >
> >
> > Michael Petlan (2):
> >   perf stat: Fix JSON metric printout for multiple metrics per line
> >   perf test: Fix JSON format linter test checks
> >
> >  .../tests/shell/lib/perf_json_output_lint.py  | 16 +++++------
> >  tools/perf/util/stat-display.c                | 28 +++++++++++--------
> >  2 files changed, 24 insertions(+), 20 deletions(-)
> >
> > --
> > 2.18.4
> >

-- 

- Arnaldo

^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 2/2] perf test: Fix JSON format linter test checks
  2023-01-23  6:36   ` Namhyung Kim
@ 2023-01-24 16:49     ` Michael Petlan
  2023-01-24 17:26       ` Namhyung Kim
  0 siblings, 1 reply; 18+ messages in thread
From: Michael Petlan @ 2023-01-24 16:49 UTC (permalink / raw)
  To: Namhyung Kim; +Cc: linux-perf-users, acme, acme, qzhao, cjense

On Sun, 22 Jan 2023, Namhyung Kim wrote:
> On Fri, Jan 20, 2023 at 6:00 AM Michael Petlan <mpetlan@redhat.com> wrote:
> >
> > The test fails on CPUs with topdown metrics, where it is common to print
> > two metrics per line. Since these are included in default event set for
> > `perf stat -- something`, it causes the "no args" subtest to fail due to
> > unexpected member count. We need to accept 7 or 9 members in that case.
> >
> > Coming to that, counting commas in the JSON line and consider it a number
> > of elements is incorrect and misleading. There should be +1 element than
> > the count of commas, while also, commas can potentially appear in the
> > event names. Count " : " substrings rather, since these better fit to
> > what should be actually counted.
> 
> I'm also curious if ":" could appear in the event/metric names.
> Probably more chances to have ":" than "," in the name, no?

Yes, ':' can appear in the event names, but not " : " (with the spaces
around).

Michael

> 
> Thanks,
> Namhyung
> 
> 
> >
> > Fixes: 0c343af2a2f8 ("perf test: JSON format checking")
> >
> > Signed-off-by: Michael Petlan <mpetlan@redhat.com>
> > ---
> >  .../tests/shell/lib/perf_json_output_lint.py     | 16 ++++++++--------
> >  1 file changed, 8 insertions(+), 8 deletions(-)
> >
> > diff --git a/tools/perf/tests/shell/lib/perf_json_output_lint.py b/tools/perf/tests/shell/lib/perf_json_output_lint.py
> > index d90f8d102eb9..4f1bbb3f07ec 100644
> > --- a/tools/perf/tests/shell/lib/perf_json_output_lint.py
> > +++ b/tools/perf/tests/shell/lib/perf_json_output_lint.py
> > @@ -40,17 +40,17 @@ def is_counter_value(num):
> >    return isfloat(num) or num == '<not counted>' or num == '<not supported>'
> >
> >  def check_json_output(expected_items):
> > -  if expected_items != -1:
> > +  if expected_items:
> >      for line in Lines:
> >        if 'failed' not in line:
> >          count = 0
> > -        count = line.count(',')
> > -        if count != expected_items and count >= 1 and count <= 3 and 'metric-value' in line:
> > +        count = line.count(' : ')
> > +        if count not in expected_items and count >= 2 and count <= 4 and 'metric-value' in line:
> >            # Events that generate >1 metric may have isolated metric
> >            # values and possibly other prefixes like interval, core and
> >            # aggregate-number.
> >            continue
> > -        if count != expected_items:
> > +        if count not in expected_items:
> >            raise RuntimeError(f'wrong number of fields. counted {count} expected {expected_items}'
> >                               f' in \'{line}\'')
> >    checks = {
> > @@ -82,14 +82,14 @@ def check_json_output(expected_items):
> >
> >  try:
> >    if args.no_args or args.system_wide or args.event:
> > -    expected_items = 6
> > +    expected_items = [7, 9]
> >    elif args.interval or args.per_thread or args.system_wide_no_aggr:
> > -    expected_items = 7
> > +    expected_items = [8, 10]
> >    elif args.per_core or args.per_socket or args.per_node or args.per_die:
> > -    expected_items = 8
> > +    expected_items = [9, 11]
> >    else:
> >      # If no option is specified, don't check the number of items.
> > -    expected_items = -1
> > +    expected_items = []
> >    check_json_output(expected_items)
> >  except:
> >    print('Test failed for input:\n' + '\n'.join(Lines))
> > --
> > 2.18.4
> >
> 
> 


^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 2/2] perf test: Fix JSON format linter test checks
  2023-01-24 16:49     ` Michael Petlan
@ 2023-01-24 17:26       ` Namhyung Kim
  0 siblings, 0 replies; 18+ messages in thread
From: Namhyung Kim @ 2023-01-24 17:26 UTC (permalink / raw)
  To: Michael Petlan; +Cc: linux-perf-users, acme, acme, qzhao

On Tue, Jan 24, 2023 at 8:49 AM Michael Petlan <mpetlan@redhat.com> wrote:
>
> On Sun, 22 Jan 2023, Namhyung Kim wrote:
> > On Fri, Jan 20, 2023 at 6:00 AM Michael Petlan <mpetlan@redhat.com> wrote:
> > >
> > > The test fails on CPUs with topdown metrics, where it is common to print
> > > two metrics per line. Since these are included in default event set for
> > > `perf stat -- something`, it causes the "no args" subtest to fail due to
> > > unexpected member count. We need to accept 7 or 9 members in that case.
> > >
> > > Coming to that, counting commas in the JSON line and consider it a number
> > > of elements is incorrect and misleading. There should be +1 element than
> > > the count of commas, while also, commas can potentially appear in the
> > > event names. Count " : " substrings rather, since these better fit to
> > > what should be actually counted.
> >
> > I'm also curious if ":" could appear in the event/metric names.
> > Probably more chances to have ":" than "," in the name, no?
>
> Yes, ':' can appear in the event names, but not " : " (with the spaces
> around).

Ah, ok.  Missed the whitespaces. :)

Thanks,
Namhyung

^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 0/2] perf test: Fix JSON linter
  2023-01-20 17:37 ` [PATCH 0/2] perf test: Fix JSON linter Ian Rogers
  2023-01-23  6:48   ` Namhyung Kim
  2023-01-23 13:38   ` Arnaldo Carvalho de Melo
@ 2023-01-24 17:39   ` Michael Petlan
  2023-01-25  0:37     ` Ian Rogers
  2 siblings, 1 reply; 18+ messages in thread
From: Michael Petlan @ 2023-01-24 17:39 UTC (permalink / raw)
  To: Ian Rogers; +Cc: Namhyung Kim, linux-perf-users, acme, acme, qzhao, cjense

On Fri, 20 Jan 2023, Ian Rogers wrote:
> On Fri, Jan 20, 2023 at 5:41 AM Michael Petlan <mpetlan@redhat.com> wrote:
> >
> > Hello all.
> >
> > We have observed issues with the 'perf stat JSON output linter' testcase
> > on systems that allow topdown metrics.
> >
> > =========================
> >
[...]
> > 2) Since the JSON printing engine thinks that one and only one metric
> > is printed, it always closes the line by adding '}'. This is not true,
> > so I have fixed the comma printing and adjusted the engine to be
> > capable of printing 1-N metrics and then close the line.
> 
> So the current printing code is messy. For example, there is a newline
> callback function, but that has little meaning for json where
> everything is on a newline. For CSV mode, adding a summary used to
> cause a column to suddenly appear on the left for the row containing
> the summary. I believe the right thing to do is a refactor and
> recently I did a similar refactor for 'perf list':
> https://lore.kernel.org/lkml/20221114210723.2749751-11-irogers@google.com/
> So it is strange that metrics are "shadows" of events, but whatever
> the point is to think about the printing API. In the change linked
> above you can see that everytime something is printed the print
> handling code is given all the information and the print handling code
> has state. Based on the state and callback's information, the print
> handling code can do nothing, properly format for CSV, json, etc. This
> gets completely away from the kind of madness of branches and
> whac-a-mole the code currently has.
> 
> I'm happy to look at doing the refactor to be similar to 'perf
> list'/builtin-list.c. Namhyung I thought might have gotten to it with
> his recent work on improving aggregation. If I hear silence then I'll
> assume that is a request I do it :-)
> 
> Pragmatically in the short term we could land your changes, but I
> worry they are more of the whac-a-mole and something somewhere else
> will break. Which is why we have a test, and so I'm not overly
> worried. I can download and test too.
> 
> Anyway, sorry for the issue and let me know what you think. Thanks,
> Ian

Hello.

I think that applying the patchset won't make things worse, eventhough
we know it would deserve a better solution for the whole print engine.

Yes, we have a test, but maybe that's what should be improved first,
since it does not actually verify the format correctness. I have hit
the problem because of failing test, but the fail cause was that there
were too many commas, but strings like

  "Heavy Operations"}"metric-value"

are still OK according to the linter.

Proper JSON linter might be in some library, but we don't want to add
too many dependencies I guess.

Maybe some simple JSON linter I used when preparing the patchset would
be enough for our perf-stat output... I'll convert it to Python and
post it to see.

=============================

Finally, speaking of tests, I think that thinking of integrating the
external perf testsuite [1] might be a better approach than adding
new shell-based tests such as "perf stat tests", etc. Tests like that
have been already written, see [1].

Some years ago, I was trying to add it to perf-test, however it was
unsuccessful, but since then, many shell-based tests were added
instead and I think they slightly duplicate the work already done.

Thoughts?
Michael

[1] https://github.com/rfmvh/perftool-testsuite

> 
> 
> > =========================
> >
> > On machines that don't support topdown, the problem can be shown by
> > doubling the following line in util/stat-shadow.c, so that the simple
> > 'insn per cycle' metric is printed twice:
> >
> >   print_metric(config, ctxp, NULL, "%7.2f ", "insn per cycle", ratio);
> >
> > The worst problem is that the JSON line is broken, such as:
> >
> > ... "pcnt-running" : 100.00, "metric-value" : 3.501931, "metric-unit"
> >     : "Heavy Operations"}"metric-value" : 14.007787, "metric-unit" : ...
> >                   here ^^^^^
> >
> > =========================
> >
> > The first patch solves the JSON output correctness, the second tries
> > to adjust the testcase to some extent, so that it should work on the
> > topdown-capable machines.
> >
> > However, it's highly possible that the testcase will have to be fixed
> > or maybe rewritten in future. First, it has quite naive evaluation of
> > what's expected/correct/etc. Second, it does no JSON format validation
> > at all. As a linter it should do so though.
> >
> >  ***
> >
> > For further discussion: What about removing the check for number of
> > expected elements in the line and just check for the keywords, such
> > as "metric-value", "counter-value", "event", etc. and for some values
> > that should be numeric. And, do proper JSON format sanity check?
> >
> >
> > Thank you for inputs!
> >
> > Michael
> >
> >
> >
> >
> > Michael Petlan (2):
> >   perf stat: Fix JSON metric printout for multiple metrics per line
> >   perf test: Fix JSON format linter test checks
> >
> >  .../tests/shell/lib/perf_json_output_lint.py  | 16 +++++------
> >  tools/perf/util/stat-display.c                | 28 +++++++++++--------
> >  2 files changed, 24 insertions(+), 20 deletions(-)
> >
> > --
> > 2.18.4
> >
> 
> 


^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 0/2] perf test: Fix JSON linter
  2023-01-24 17:39   ` Michael Petlan
@ 2023-01-25  0:37     ` Ian Rogers
  0 siblings, 0 replies; 18+ messages in thread
From: Ian Rogers @ 2023-01-25  0:37 UTC (permalink / raw)
  To: Michael Petlan; +Cc: Namhyung Kim, linux-perf-users, acme, acme, qzhao, cjense

On Tue, Jan 24, 2023 at 9:39 AM Michael Petlan <mpetlan@redhat.com> wrote:
>
> On Fri, 20 Jan 2023, Ian Rogers wrote:
> > On Fri, Jan 20, 2023 at 5:41 AM Michael Petlan <mpetlan@redhat.com> wrote:
> > >
> > > Hello all.
> > >
> > > We have observed issues with the 'perf stat JSON output linter' testcase
> > > on systems that allow topdown metrics.
> > >
> > > =========================
> > >
> [...]
> > > 2) Since the JSON printing engine thinks that one and only one metric
> > > is printed, it always closes the line by adding '}'. This is not true,
> > > so I have fixed the comma printing and adjusted the engine to be
> > > capable of printing 1-N metrics and then close the line.
> >
> > So the current printing code is messy. For example, there is a newline
> > callback function, but that has little meaning for json where
> > everything is on a newline. For CSV mode, adding a summary used to
> > cause a column to suddenly appear on the left for the row containing
> > the summary. I believe the right thing to do is a refactor and
> > recently I did a similar refactor for 'perf list':
> > https://lore.kernel.org/lkml/20221114210723.2749751-11-irogers@google.com/
> > So it is strange that metrics are "shadows" of events, but whatever
> > the point is to think about the printing API. In the change linked
> > above you can see that everytime something is printed the print
> > handling code is given all the information and the print handling code
> > has state. Based on the state and callback's information, the print
> > handling code can do nothing, properly format for CSV, json, etc. This
> > gets completely away from the kind of madness of branches and
> > whac-a-mole the code currently has.
> >
> > I'm happy to look at doing the refactor to be similar to 'perf
> > list'/builtin-list.c. Namhyung I thought might have gotten to it with
> > his recent work on improving aggregation. If I hear silence then I'll
> > assume that is a request I do it :-)
> >
> > Pragmatically in the short term we could land your changes, but I
> > worry they are more of the whac-a-mole and something somewhere else
> > will break. Which is why we have a test, and so I'm not overly
> > worried. I can download and test too.
> >
> > Anyway, sorry for the issue and let me know what you think. Thanks,
> > Ian
>
> Hello.
>
> I think that applying the patchset won't make things worse, eventhough
> we know it would deserve a better solution for the whole print engine.
>
> Yes, we have a test, but maybe that's what should be improved first,
> since it does not actually verify the format correctness. I have hit
> the problem because of failing test, but the fail cause was that there
> were too many commas, but strings like
>
>   "Heavy Operations"}"metric-value"
>
> are still OK according to the linter.
>
> Proper JSON linter might be in some library, but we don't want to add
> too many dependencies I guess.
>
> Maybe some simple JSON linter I used when preparing the patchset would
> be enough for our perf-stat output... I'll convert it to Python and
> post it to see.

I've been trying to tidy up the libraries under tools/lib recently,
and their build. I'm hoping that with this we can have more statically
built in libraries rather than a big monolithic application. In part
for testing reasons, but also separation of concerns and the like.
Fwiw, we did have a json reader library from jsmn in the pmu-events
jevents.c code in the past. As it was never updated and had become
forked, I wasn't a huge fan of it.

> =============================
>
> Finally, speaking of tests, I think that thinking of integrating the
> external perf testsuite [1] might be a better approach than adding
> new shell-based tests such as "perf stat tests", etc. Tests like that
> have been already written, see [1].
>
> Some years ago, I was trying to add it to perf-test, however it was
> unsuccessful, but since then, many shell-based tests were added
> instead and I think they slightly duplicate the work already done.
>
> Thoughts?
> Michael
>
> [1] https://github.com/rfmvh/perftool-testsuite

As someone who maintains a build, I'd love to see all of the perf
testing in the kernel tree :-) What do you think would be the best
strategy to integrate the test suite? Perhaps create a new directory
under perf/tools/tests/shell, add the tests there and then add a
wrapper shell script that invokes them all as one large shell test.
From this we can work to have smaller tests, better output within perf
test, etc. I think it'd be best for you to do an initial push, but I'd
be willing to help from then on.

Thanks,
Ian

> >
> >
> > > =========================
> > >
> > > On machines that don't support topdown, the problem can be shown by
> > > doubling the following line in util/stat-shadow.c, so that the simple
> > > 'insn per cycle' metric is printed twice:
> > >
> > >   print_metric(config, ctxp, NULL, "%7.2f ", "insn per cycle", ratio);
> > >
> > > The worst problem is that the JSON line is broken, such as:
> > >
> > > ... "pcnt-running" : 100.00, "metric-value" : 3.501931, "metric-unit"
> > >     : "Heavy Operations"}"metric-value" : 14.007787, "metric-unit" : ...
> > >                   here ^^^^^
> > >
> > > =========================
> > >
> > > The first patch solves the JSON output correctness, the second tries
> > > to adjust the testcase to some extent, so that it should work on the
> > > topdown-capable machines.
> > >
> > > However, it's highly possible that the testcase will have to be fixed
> > > or maybe rewritten in future. First, it has quite naive evaluation of
> > > what's expected/correct/etc. Second, it does no JSON format validation
> > > at all. As a linter it should do so though.
> > >
> > >  ***
> > >
> > > For further discussion: What about removing the check for number of
> > > expected elements in the line and just check for the keywords, such
> > > as "metric-value", "counter-value", "event", etc. and for some values
> > > that should be numeric. And, do proper JSON format sanity check?
> > >
> > >
> > > Thank you for inputs!
> > >
> > > Michael
> > >
> > >
> > >
> > >
> > > Michael Petlan (2):
> > >   perf stat: Fix JSON metric printout for multiple metrics per line
> > >   perf test: Fix JSON format linter test checks
> > >
> > >  .../tests/shell/lib/perf_json_output_lint.py  | 16 +++++------
> > >  tools/perf/util/stat-display.c                | 28 +++++++++++--------
> > >  2 files changed, 24 insertions(+), 20 deletions(-)
> > >
> > > --
> > > 2.18.4
> > >
> >
> >
>

^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 2/2] perf test: Fix JSON format linter test checks
  2023-01-20 13:40 ` [PATCH 2/2] perf test: Fix JSON format linter test checks Michael Petlan
  2023-01-23  6:36   ` Namhyung Kim
@ 2023-01-27 12:26   ` Arnaldo Carvalho de Melo
  2023-01-27 12:30     ` Arnaldo Carvalho de Melo
  1 sibling, 1 reply; 18+ messages in thread
From: Arnaldo Carvalho de Melo @ 2023-01-27 12:26 UTC (permalink / raw)
  To: Michael Petlan
  Cc: linux-perf-users, acme, qzhao, cjense, Ian Rogers,
	Linux Kernel Mailing List, Namhyung Kim, Jiri Olsa,
	Adrian Hunter

Em Fri, Jan 20, 2023 at 02:40:39PM +0100, Michael Petlan escreveu:
> The test fails on CPUs with topdown metrics, where it is common to print
> two metrics per line. Since these are included in default event set for
> `perf stat -- something`, it causes the "no args" subtest to fail due to
> unexpected member count. We need to accept 7 or 9 members in that case.
> 
> Coming to that, counting commas in the JSON line and consider it a number
> of elements is incorrect and misleading. There should be +1 element than
> the count of commas, while also, commas can potentially appear in the
> event names. Count " : " substrings rather, since these better fit to
> what should be actually counted.

Before I apply this first patch I can run, as root, the 'perf test' JSON
lint 100 times without problems:

[root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
1 98: perf stat JSON output linter                                    : Ok
2 98: perf stat JSON output linter                                    : Ok
3 98: perf stat JSON output linter                                    : Ok
4 98: perf stat JSON output linter                                    : Ok
<SNIP>
96 98: perf stat JSON output linter                                    : Ok
97 98: perf stat JSON output linter                                    : Ok
98 98: perf stat JSON output linter                                    : Ok
99 98: perf stat JSON output linter                                    : Ok
100 98: perf stat JSON output linter                                    : Ok
[root@quaco ~]#

After applying it it fails seemingly randomly, I'll remove both patches
from my tmp.perf/core branch and investigate.

[acme@quaco perf]$ git log --oneline -1
fdafd42aac3629db (HEAD) perf stat: Fix JSON metric printout for multiple metrics per line
[acme@quaco perf]$ perf -v
perf version 6.2.rc5.gfdafd42aac36
[acme@quaco perf]$
[root@quaco ~]# perf -v
perf version 6.2.rc5.gfdafd42aac36
[root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
[root@quaco ~]# perf -v
perf version 6.2.rc5.gfdafd42aac36
[root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
1 98: perf stat JSON output linter                                    : Ok
2 98: perf stat JSON output linter                                    : Ok
3 98: perf stat JSON output linter                                    : FAILED!
4 98: perf stat JSON output linter                                    : Ok
5 98: perf stat JSON output linter                                    : Ok
6 98: perf stat JSON output linter                                    : Ok
7 98: perf stat JSON output linter                                    : FAILED!
8 98: perf stat JSON output linter                                    : Ok
9 98: perf stat JSON output linter                                    : Ok
10 98: perf stat JSON output linter                                    : Ok
11 98: perf stat JSON output linter                                    : Ok
12 98: perf stat JSON output linter                                    : Ok
13 98: perf stat JSON output linter                                    : Ok
14 98: perf stat JSON output linter                                    : Ok
15 98: perf stat JSON output linter                                    : Ok
16 98: perf stat JSON output linter                                    : FAILED!
17 98: perf stat JSON output linter                                    : Ok
18 98: perf stat JSON output linter                                    : Ok
19 98: perf stat JSON output linter                                    : Ok
20 98: perf stat JSON output linter                                    : FAILED!
21 98: perf stat JSON output linter                                    : Ok
22 98: perf stat JSON output linter                                    : Ok
23 98: perf stat JSON output linter                                    : FAILED!
24 98: perf stat JSON output linter                                    : Ok
25 98: perf stat JSON output linter                                    : Ok
26 98: perf stat JSON output linter                                    : Ok
27 98: perf stat JSON output linter                                    : Ok
28 98: perf stat JSON output linter                                    : FAILED!
29 98: perf stat JSON output linter                                    : Ok
30 98: perf stat JSON output linter                                    : Ok
31 98: perf stat JSON output linter                                    : FAILED!
32 98: perf stat JSON output linter                                    : FAILED!
33 98: perf stat JSON output linter                                    : FAILED!
34 98: perf stat JSON output linter                                    : Ok
35 98: perf stat JSON output linter                                    : Ok
36 98: perf stat JSON output linter                                    : Ok
37 98: perf stat JSON output linter                                    : Ok
38 98: perf stat JSON output linter                                    : FAILED!
39 98: perf stat JSON output linter                                    : FAILED!
40 98: perf stat JSON output linter                                    : FAILED!
41 98: perf stat JSON output linter                                    : Ok
42 98: perf stat JSON output linter                                    : Ok
43 98: perf stat JSON output linter                                    : Ok
44 98: perf stat JSON output linter                                    : Ok
45 98: perf stat JSON output linter                                    : Ok
46 98: perf stat JSON output linter                                    : FAILED!
47 98: perf stat JSON output linter                                    : Ok
48 98: perf stat JSON output linter                                    : FAILED!
49 98: perf stat JSON output linter                                    : FAILED!
50 98: perf stat JSON output linter                                    : FAILED!
51 98: perf stat JSON output linter                                    : FAILED!
52 98: perf stat JSON output linter                                    : Ok
53 98: perf stat JSON output linter                                    : FAILED!
54 98: perf stat JSON output linter                                    : Ok
55 98: perf stat JSON output linter                                    : Ok
56 98: perf stat JSON output linter                                    : FAILED!
57 98: perf stat JSON output linter                                    : Ok
58 98: perf stat JSON output linter                                    : Ok
59 98: perf stat JSON output linter                                    : FAILED!
60 98: perf stat JSON output linter                                    : Ok
61 98: perf stat JSON output linter                                    : FAILED!
62 98: perf stat JSON output linter                                    : Ok
63 98: perf stat JSON output linter                                    : Ok
64 98: perf stat JSON output linter                                    : Ok
65 98: perf stat JSON output linter                                    : Ok
66 98: perf stat JSON output linter                                    : Ok
67 98: perf stat JSON output linter                                    : Ok
68 98: perf stat JSON output linter                                    : Ok
69 98: perf stat JSON output linter                                    : Ok
70 98: perf stat JSON output linter                                    : Ok
71 98: perf stat JSON output linter                                    : FAILED!
72 98: perf stat JSON output linter                                    : FAILED!
73 98: perf stat JSON output linter                                    : Ok
74 98: perf stat JSON output linter                                    : FAILED!
75 98: perf stat JSON output linter                                    : Ok
76 98: perf stat JSON output linter                                    : FAILED!
77 98: perf stat JSON output linter                                    : Ok
78 98: perf stat JSON output linter                                    : FAILED!
79 98: perf stat JSON output linter                                    : FAILED!
80 98: perf stat JSON output linter                                    : FAILED!
81 98: perf stat JSON output linter                                    : Ok
82 98: perf stat JSON output linter                                    : FAILED!
83 98: perf stat JSON output linter                                    : FAILED!
84 98: perf stat JSON output linter                                    : Ok
85 98: perf stat JSON output linter                                    : Ok
86 98: perf stat JSON output linter                                    : Ok
87 98: perf stat JSON output linter                                    : FAILED!
88 98: perf stat JSON output linter                                    : FAILED!
89 98: perf stat JSON output linter                                    : Ok
90 98: perf stat JSON output linter                                    : FAILED!
91 98: perf stat JSON output linter                                    : FAILED!
92 98: perf stat JSON output linter                                    : Ok
93 98: perf stat JSON output linter                                    : FAILED!
94 98: perf stat JSON output linter                                    : FAILED!
95 98: perf stat JSON output linter                                    : FAILED!
96 98: perf stat JSON output linter                                    : FAILED!
97 98: perf stat JSON output linter                                    : FAILED!
98 98: perf stat JSON output linter                                    : Ok
99 98: perf stat JSON output linter                                    : Ok
100 98: perf stat JSON output linter                                    : FAILED!
[root@quaco ~]#

 
> Fixes: 0c343af2a2f8 ("perf test: JSON format checking")
> 
> Signed-off-by: Michael Petlan <mpetlan@redhat.com>
> ---
>  .../tests/shell/lib/perf_json_output_lint.py     | 16 ++++++++--------
>  1 file changed, 8 insertions(+), 8 deletions(-)
> 
> diff --git a/tools/perf/tests/shell/lib/perf_json_output_lint.py b/tools/perf/tests/shell/lib/perf_json_output_lint.py
> index d90f8d102eb9..4f1bbb3f07ec 100644
> --- a/tools/perf/tests/shell/lib/perf_json_output_lint.py
> +++ b/tools/perf/tests/shell/lib/perf_json_output_lint.py
> @@ -40,17 +40,17 @@ def is_counter_value(num):
>    return isfloat(num) or num == '<not counted>' or num == '<not supported>'
>  
>  def check_json_output(expected_items):
> -  if expected_items != -1:
> +  if expected_items:
>      for line in Lines:
>        if 'failed' not in line:
>          count = 0
> -        count = line.count(',')
> -        if count != expected_items and count >= 1 and count <= 3 and 'metric-value' in line:
> +        count = line.count(' : ')
> +        if count not in expected_items and count >= 2 and count <= 4 and 'metric-value' in line:
>            # Events that generate >1 metric may have isolated metric
>            # values and possibly other prefixes like interval, core and
>            # aggregate-number.
>            continue
> -        if count != expected_items:
> +        if count not in expected_items:
>            raise RuntimeError(f'wrong number of fields. counted {count} expected {expected_items}'
>                               f' in \'{line}\'')
>    checks = {
> @@ -82,14 +82,14 @@ def check_json_output(expected_items):
>  
>  try:
>    if args.no_args or args.system_wide or args.event:
> -    expected_items = 6
> +    expected_items = [7, 9]
>    elif args.interval or args.per_thread or args.system_wide_no_aggr:
> -    expected_items = 7
> +    expected_items = [8, 10]
>    elif args.per_core or args.per_socket or args.per_node or args.per_die:
> -    expected_items = 8
> +    expected_items = [9, 11]
>    else:
>      # If no option is specified, don't check the number of items.
> -    expected_items = -1
> +    expected_items = []
>    check_json_output(expected_items)
>  except:
>    print('Test failed for input:\n' + '\n'.join(Lines))
> -- 
> 2.18.4
> 

-- 

- Arnaldo

^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 2/2] perf test: Fix JSON format linter test checks
  2023-01-27 12:26   ` Arnaldo Carvalho de Melo
@ 2023-01-27 12:30     ` Arnaldo Carvalho de Melo
  2023-01-31 17:14       ` Michael Petlan
  0 siblings, 1 reply; 18+ messages in thread
From: Arnaldo Carvalho de Melo @ 2023-01-27 12:30 UTC (permalink / raw)
  To: Michael Petlan
  Cc: linux-perf-users, acme, qzhao, cjense, Ian Rogers,
	Linux Kernel Mailing List, Namhyung Kim, Jiri Olsa,
	Adrian Hunter

Em Fri, Jan 27, 2023 at 09:26:03AM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Fri, Jan 20, 2023 at 02:40:39PM +0100, Michael Petlan escreveu:
> > The test fails on CPUs with topdown metrics, where it is common to print
> > two metrics per line. Since these are included in default event set for
> > `perf stat -- something`, it causes the "no args" subtest to fail due to
> > unexpected member count. We need to accept 7 or 9 members in that case.
> > 
> > Coming to that, counting commas in the JSON line and consider it a number
> > of elements is incorrect and misleading. There should be +1 element than
> > the count of commas, while also, commas can potentially appear in the
> > event names. Count " : " substrings rather, since these better fit to
> > what should be actually counted.
> 
> Before I apply this first patch I can run, as root, the 'perf test' JSON
> lint 100 times without problems:
> 
> [root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
> 1 98: perf stat JSON output linter                                    : Ok
> 2 98: perf stat JSON output linter                                    : Ok
> 3 98: perf stat JSON output linter                                    : Ok
> 4 98: perf stat JSON output linter                                    : Ok
> <SNIP>
> 96 98: perf stat JSON output linter                                    : Ok
> 97 98: perf stat JSON output linter                                    : Ok
> 98 98: perf stat JSON output linter                                    : Ok
> 99 98: perf stat JSON output linter                                    : Ok
> 100 98: perf stat JSON output linter                                    : Ok
> [root@quaco ~]#
> 
> After applying it it fails seemingly randomly, I'll remove both patches
> from my tmp.perf/core branch and investigate.
> 
> [acme@quaco perf]$ git log --oneline -1
> fdafd42aac3629db (HEAD) perf stat: Fix JSON metric printout for multiple metrics per line
> [acme@quaco perf]$ perf -v
> perf version 6.2.rc5.gfdafd42aac36
> [acme@quaco perf]$
> [root@quaco ~]# perf -v
> perf version 6.2.rc5.gfdafd42aac36
> [root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
> [root@quaco ~]# perf -v
> perf version 6.2.rc5.gfdafd42aac36
> [root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
> 1 98: perf stat JSON output linter                                    : Ok
> 2 98: perf stat JSON output linter                                    : Ok
> 3 98: perf stat JSON output linter                                    : FAILED!
> 4 98: perf stat JSON output linter                                    : Ok

BTW, after applying the second patch, the one for 'perf test', the
problem persists:

[acme@quaco perf]$ git log --oneline -1
320cd37176508ec2 (HEAD, acme/tmp.perf/core, acme.korg/tmp.perf/core) perf test: Fix JSON format linter test checks
[acme@quaco perf]$ perf -v
perf version 6.2.rc5.g320cd3717650
[acme@quaco perf]$
[root@quaco ~]# perf -v
perf version 6.2.rc5.g320cd3717650
[root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
1 98: perf stat JSON output linter                                    : Ok
2 98: perf stat JSON output linter                                    : FAILED!
3 98: perf stat JSON output linter                                    : Ok
4 98: perf stat JSON output linter                                    : Ok
5 98: perf stat JSON output linter                                    : FAILED!
6 98: perf stat JSON output linter                                    : Ok
7 98: perf stat JSON output linter                                    : FAILED!
8 98: perf stat JSON output linter                                    : Ok
9 98: perf stat JSON output linter                                    : Ok
10 98: perf stat JSON output linter                                    : FAILED!
11 98: perf stat JSON output linter                                    : FAILED!
12 98: perf stat JSON output linter                                    : FAILED!
13 98: perf stat JSON output linter                                    : Ok
14 98: perf stat JSON output linter                                    : Ok
15 98: perf stat JSON output linter                                    : FAILED!
16 98: perf stat JSON output linter                                    : FAILED!
17 98: perf stat JSON output linter                                    : FAILED!
18 98: perf stat JSON output linter                                    :^C
[root@quaco ~]#

When it works:

[root@quaco ~]# perf test -v 98
 98: perf stat JSON output linter                                    :
--- start ---
test child forked, pid 62202
Checking json output: no args [Success]
Checking json output: system wide [Success]
Checking json output: interval [Success]
Checking json output: event [Success]
Checking json output: per thread [Success]
Checking json output: per node [Success]
Checking json output: system wide Checking json output: system wide no aggregation [Success]
Checking json output: per core [Success]
Checking json output: per die [Success]
Checking json output: per socket [Success]
test child finished with 0
---- end ----
perf stat JSON output linter: Ok
[root@quaco ~]#

When it fails:

[root@quaco ~]# perf test -v 98
 98: perf stat JSON output linter                                    :
--- start ---
test child forked, pid 62270
Checking json output: no args [Success]
Checking json output: system wide [Success]
Checking json output: interval [Success]
Checking json output: event [Success]
Checking json output: per thread Test failed for input:
{"thread" : "rcu_preempt-16", "counter-value" : "0.018340", "unit" : "msec", "event" : "cpu-clock", "event-runtime" : 19071, "pcnt-running" : 100.00, "metric-value" : 0.001758, "metric-unit" : "CPUs utilized"}

{"thread" : "gnome-terminal--2977", "counter-value" : "0.061868", "unit" : "msec", "event" : "cpu-clock", "event-runtime" : 62075, "pcnt-running" : 100.00, "metric-value" : 0.005930, "metric-unit" : "CPUs utilized"}

{"thread" : "perf-62294", "counter-value" : "9.398635", "unit" : "msec", "event" : "cpu-clock", "event-runtime" : 9398904, "pcnt-running" : 100.00, "metric-value" : 0.900916, "metric-unit" : "CPUs utilized"}

{"thread" : "rcu_preempt-16", "counter-value" : "4.000000", "unit" : "", "event" : "context-switches", "event-runtime" : 15203, "pcnt-running" : 100.00, "metric-value" : 218.102508, "metric-unit" : "K/sec"}

{"thread" : "gnome-terminal--2977", "counter-value" : "1.000000", "unit" : "", "event" : "context-switches", "event-runtime" : 62075, "pcnt-running" : 100.00, "metric-value" : 16.163445, "metric-unit" : "K/sec"}

{"thread" : "perf-62294", "counter-value" : "1.000000", "unit" : "", "event" : "context-switches", "event-runtime" : 9388658, "pcnt-running" : 100.00, "metric-value" : 106.398429, "metric-unit" : "/sec"}

{"thread" : "rcu_preempt-16", "counter-value" : "1.000000", "unit" : "", "event" : "cpu-migrations", "event-runtime" : 12511, "pcnt-running" : 100.00, "metric-value" : 54.525627, "metric-unit" : "K/sec"}

{"thread" : "perf-62294", "counter-value" : "2.000000", "unit" : "", "event" : "page-faults", "event-runtime" : 9427495, "pcnt-running" : 100.00, "metric-value" : 212.796858, "metric-unit" : "/sec"}

{"thread" : "rcu_preempt-16", "counter-value" : "41498.000000", "unit" : "", "event" : "cycles", "event-runtime" : 20944, "pcnt-running" : 100.00, "metric-value" : 2.262704, "metric-unit" : "GHz"}

{"thread" : "ksoftirqd/1-22", "counter-value" : "23883.000000", "unit" : "", "event" : "cycles", "event-runtime" : 9949, "pcnt-running" : 100.00}

{"thread" : "perf-62294", "counter-value" : "36686750.000000", "unit" : "", "event" : "cycles", "event-runtime" : 9439269, "pcnt-running" : 100.00, "metric-value" : 3.903413, "metric-unit" : "GHz"}

{"thread" : "rcu_preempt-16", "counter-value" : "25086.000000", "unit" : "", "event" : "instructions", "event-runtime" : 20944, "pcnt-running" : 100.00, "metric-value" : 0.604511, "metric-unit" : "insn per cycle"}

{"thread" : "ksoftirqd/1-22", "counter-value" : "13360.000000", "unit" : "", "event" : "instructions", "event-runtime" : 9949, "pcnt-running" : 100.00, "metric-value" : 0.559394, "metric-unit" : "insn per cycle"}

{"thread" : "perf-62294", "counter-value" : "7905940.000000", "unit" : "", "event" : "instructions", "event-runtime" : 9438686, "pcnt-running" : 100.00, "metric-value" : 0.215499, "metric-unit" : "insn per cycle"}

{"thread" : "rcu_preempt-16", "counter-value" : "3951.000000", "unit" : "", "event" : "branches", "event-runtime" : 16533, "pcnt-running" : 100.00, "metric-value" : 215.430752, "metric-unit" : "M/sec"}

{"thread" : "ksoftirqd/1-22", "counter-value" : "2822.000000", "unit" : "", "event" : "branches", "event-runtime" : 9949, "pcnt-running" : 100.00, "metric-value" : 0.000000, "metric-unit" : "/sec"}

{"thread" : "perf-62294", "counter-value" : "1691804.000000", "unit" : "", "event" : "branches", "event-runtime" : 9474118, "pcnt-running" : 100.00, "metric-value" : 180.005288, "metric-unit" : "M/sec"}

{"thread" : "rcu_preempt-16", "counter-value" : "279.000000", "unit" : "", "event" : "branch-misses", "event-runtime" : 16533, "pcnt-running" : 100.00, "metric-value" : 7.061503, "metric-unit" : "of all branches"}

{"thread" : "ksoftirqd/1-22", "counter-value" : "153.000000", "unit" : "", "event" : "branch-misses", "event-runtime" : 9949, "pcnt-running" : 100.00, "metric-value" : 5.421687, "metric-unit" : "of all branches"}

{"thread" : "kworker/1:2-events-752", "counter-value" : "121.000000", "unit" : "", "event" : "branch-misses", "event-runtime" : 9850, "pcnt-running" : 100.00, "metric-value" : 0.000000, "metric-unit" : "of all branches"}

{"thread" : "perf-62294", "counter-value" : "52693.000000", "unit" : "", "event" : "branch-misses", "event-runtime" : 9451948, "pcnt-running" : 100.00, "metric-value" : 3.114604, "metric-unit" : "of all branches"}

Traceback (most recent call last):
  File "/home/acme/libexec/perf-core/tests/shell/lib/perf_json_output_lint.py", line 93, in <module>
    check_json_output(expected_items)
  File "/home/acme/libexec/perf-core/tests/shell/lib/perf_json_output_lint.py", line 54, in check_json_output
    raise RuntimeError(f'wrong number of fields. counted {count} expected {expected_items}'
RuntimeError: wrong number of fields. counted 6 expected [8, 10] in '{"thread" : "ksoftirqd/1-22", "counter-value" : "23883.000000", "unit" : "", "event" : "cycles", "event-runtime" : 9949, "pcnt-running" : 100.00}
'
test child finished with -1
---- end ----
perf stat JSON output linter: FAILED!
[root@quaco ~]#

^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 2/2] perf test: Fix JSON format linter test checks
  2023-01-27 12:30     ` Arnaldo Carvalho de Melo
@ 2023-01-31 17:14       ` Michael Petlan
  2023-02-02  1:18         ` Arnaldo Carvalho de Melo
  0 siblings, 1 reply; 18+ messages in thread
From: Michael Petlan @ 2023-01-31 17:14 UTC (permalink / raw)
  To: Arnaldo Carvalho de Melo
  Cc: linux-perf-users, acme, qzhao, cjense, Ian Rogers,
	Linux Kernel Mailing List, Namhyung Kim, Jiri Olsa,
	Adrian Hunter

On Fri, 27 Jan 2023, Arnaldo Carvalho de Melo wrote:
> Em Fri, Jan 27, 2023 at 09:26:03AM -0300, Arnaldo Carvalho de Melo escreveu:
[...]

> > Before I apply this first patch I can run, as root, the 'perf test' JSON
> > lint 100 times without problems:
> > 
> > [root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
> > 1 98: perf stat JSON output linter                                    : Ok
> > 2 98: perf stat JSON output linter                                    : Ok
> > 3 98: perf stat JSON output linter                                    : Ok
> > 4 98: perf stat JSON output linter                                    : Ok
> > <SNIP>
> > 96 98: perf stat JSON output linter                                    : Ok
> > 97 98: perf stat JSON output linter                                    : Ok
> > 98 98: perf stat JSON output linter                                    : Ok
> > 99 98: perf stat JSON output linter                                    : Ok
> > 100 98: perf stat JSON output linter                                    : Ok
> > [root@quaco ~]#
> > 
> > After applying it it fails seemingly randomly, I'll remove both patches
> > from my tmp.perf/core branch and investigate.

Hello Arnaldo. Have you found anything?

Which patch of the two causes the failures? The one that changes the JSON
printing or the second that changes the test?

I hope that the JSON printing is now correct, it seems to be, at least on my
machine + the SPR box I was debugging this on.


> > 
> > [acme@quaco perf]$ git log --oneline -1
> > fdafd42aac3629db (HEAD) perf stat: Fix JSON metric printout for multiple metrics per line
> > [acme@quaco perf]$ perf -v
> > perf version 6.2.rc5.gfdafd42aac36
> > [acme@quaco perf]$
> > [root@quaco ~]# perf -v
> > perf version 6.2.rc5.gfdafd42aac36
> > [root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
> > [root@quaco ~]# perf -v
> > perf version 6.2.rc5.gfdafd42aac36
> > [root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
> > 1 98: perf stat JSON output linter                                    : Ok
> > 2 98: perf stat JSON output linter                                    : Ok
> > 3 98: perf stat JSON output linter                                    : FAILED!
> > 4 98: perf stat JSON output linter                                    : Ok
> 
> BTW, after applying the second patch, the one for 'perf test', the
> problem persists:
> 
> [acme@quaco perf]$ git log --oneline -1
> 320cd37176508ec2 (HEAD, acme/tmp.perf/core, acme.korg/tmp.perf/core) perf test: Fix JSON format linter test checks
> [acme@quaco perf]$ perf -v
> perf version 6.2.rc5.g320cd3717650
> [acme@quaco perf]$
> [root@quaco ~]# perf -v
> perf version 6.2.rc5.g320cd3717650
> [root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
> 1 98: perf stat JSON output linter                                    : Ok
> 2 98: perf stat JSON output linter                                    : FAILED!
> 3 98: perf stat JSON output linter                                    : Ok
> 4 98: perf stat JSON output linter                                    : Ok
> 5 98: perf stat JSON output linter                                    : FAILED!
> 6 98: perf stat JSON output linter                                    : Ok
> 7 98: perf stat JSON output linter                                    : FAILED!
> 8 98: perf stat JSON output linter                                    : Ok
> 9 98: perf stat JSON output linter                                    : Ok
> 10 98: perf stat JSON output linter                                    : FAILED!
> 11 98: perf stat JSON output linter                                    : FAILED!
> 12 98: perf stat JSON output linter                                    : FAILED!
> 13 98: perf stat JSON output linter                                    : Ok
> 14 98: perf stat JSON output linter                                    : Ok
> 15 98: perf stat JSON output linter                                    : FAILED!
> 16 98: perf stat JSON output linter                                    : FAILED!
> 17 98: perf stat JSON output linter                                    : FAILED!
> 18 98: perf stat JSON output linter                                    :^C
> [root@quaco ~]#
> 
> When it works:
> 
> [root@quaco ~]# perf test -v 98
>  98: perf stat JSON output linter                                    :
> --- start ---
> test child forked, pid 62202
> Checking json output: no args [Success]
> Checking json output: system wide [Success]
> Checking json output: interval [Success]
> Checking json output: event [Success]
> Checking json output: per thread [Success]
> Checking json output: per node [Success]
> Checking json output: system wide Checking json output: system wide no aggregation [Success]
> Checking json output: per core [Success]
> Checking json output: per die [Success]
> Checking json output: per socket [Success]
> test child finished with 0
> ---- end ----
> perf stat JSON output linter: Ok
> [root@quaco ~]#
> 
> When it fails:
> 
> [root@quaco ~]# perf test -v 98
>  98: perf stat JSON output linter                                    :
> --- start ---
> test child forked, pid 62270
> Checking json output: no args [Success]
> Checking json output: system wide [Success]
> Checking json output: interval [Success]
> Checking json output: event [Success]
> Checking json output: per thread Test failed for input:
> {"thread" : "rcu_preempt-16", "counter-value" : "0.018340", "unit" : "msec", "event" : "cpu-clock", "event-runtime" : 19071, "pcnt-running" : 100.00, "metric-value" : 0.001758, "metric-unit" : "CPUs utilized"}
> 
> {"thread" : "gnome-terminal--2977", "counter-value" : "0.061868", "unit" : "msec", "event" : "cpu-clock", "event-runtime" : 62075, "pcnt-running" : 100.00, "metric-value" : 0.005930, "metric-unit" : "CPUs utilized"}
> 
> {"thread" : "perf-62294", "counter-value" : "9.398635", "unit" : "msec", "event" : "cpu-clock", "event-runtime" : 9398904, "pcnt-running" : 100.00, "metric-value" : 0.900916, "metric-unit" : "CPUs utilized"}
> 
> {"thread" : "rcu_preempt-16", "counter-value" : "4.000000", "unit" : "", "event" : "context-switches", "event-runtime" : 15203, "pcnt-running" : 100.00, "metric-value" : 218.102508, "metric-unit" : "K/sec"}
> 
> {"thread" : "gnome-terminal--2977", "counter-value" : "1.000000", "unit" : "", "event" : "context-switches", "event-runtime" : 62075, "pcnt-running" : 100.00, "metric-value" : 16.163445, "metric-unit" : "K/sec"}
> 
> {"thread" : "perf-62294", "counter-value" : "1.000000", "unit" : "", "event" : "context-switches", "event-runtime" : 9388658, "pcnt-running" : 100.00, "metric-value" : 106.398429, "metric-unit" : "/sec"}
> 
> {"thread" : "rcu_preempt-16", "counter-value" : "1.000000", "unit" : "", "event" : "cpu-migrations", "event-runtime" : 12511, "pcnt-running" : 100.00, "metric-value" : 54.525627, "metric-unit" : "K/sec"}
> 
> {"thread" : "perf-62294", "counter-value" : "2.000000", "unit" : "", "event" : "page-faults", "event-runtime" : 9427495, "pcnt-running" : 100.00, "metric-value" : 212.796858, "metric-unit" : "/sec"}
> 
> {"thread" : "rcu_preempt-16", "counter-value" : "41498.000000", "unit" : "", "event" : "cycles", "event-runtime" : 20944, "pcnt-running" : 100.00, "metric-value" : 2.262704, "metric-unit" : "GHz"}
> 
> {"thread" : "ksoftirqd/1-22", "counter-value" : "23883.000000", "unit" : "", "event" : "cycles", "event-runtime" : 9949, "pcnt-running" : 100.00}
> 
> {"thread" : "perf-62294", "counter-value" : "36686750.000000", "unit" : "", "event" : "cycles", "event-runtime" : 9439269, "pcnt-running" : 100.00, "metric-value" : 3.903413, "metric-unit" : "GHz"}
> 
> {"thread" : "rcu_preempt-16", "counter-value" : "25086.000000", "unit" : "", "event" : "instructions", "event-runtime" : 20944, "pcnt-running" : 100.00, "metric-value" : 0.604511, "metric-unit" : "insn per cycle"}
> 
> {"thread" : "ksoftirqd/1-22", "counter-value" : "13360.000000", "unit" : "", "event" : "instructions", "event-runtime" : 9949, "pcnt-running" : 100.00, "metric-value" : 0.559394, "metric-unit" : "insn per cycle"}
> 
> {"thread" : "perf-62294", "counter-value" : "7905940.000000", "unit" : "", "event" : "instructions", "event-runtime" : 9438686, "pcnt-running" : 100.00, "metric-value" : 0.215499, "metric-unit" : "insn per cycle"}
> 
> {"thread" : "rcu_preempt-16", "counter-value" : "3951.000000", "unit" : "", "event" : "branches", "event-runtime" : 16533, "pcnt-running" : 100.00, "metric-value" : 215.430752, "metric-unit" : "M/sec"}
> 
> {"thread" : "ksoftirqd/1-22", "counter-value" : "2822.000000", "unit" : "", "event" : "branches", "event-runtime" : 9949, "pcnt-running" : 100.00, "metric-value" : 0.000000, "metric-unit" : "/sec"}
> 
> {"thread" : "perf-62294", "counter-value" : "1691804.000000", "unit" : "", "event" : "branches", "event-runtime" : 9474118, "pcnt-running" : 100.00, "metric-value" : 180.005288, "metric-unit" : "M/sec"}
> 
> {"thread" : "rcu_preempt-16", "counter-value" : "279.000000", "unit" : "", "event" : "branch-misses", "event-runtime" : 16533, "pcnt-running" : 100.00, "metric-value" : 7.061503, "metric-unit" : "of all branches"}
> 
> {"thread" : "ksoftirqd/1-22", "counter-value" : "153.000000", "unit" : "", "event" : "branch-misses", "event-runtime" : 9949, "pcnt-running" : 100.00, "metric-value" : 5.421687, "metric-unit" : "of all branches"}
> 
> {"thread" : "kworker/1:2-events-752", "counter-value" : "121.000000", "unit" : "", "event" : "branch-misses", "event-runtime" : 9850, "pcnt-running" : 100.00, "metric-value" : 0.000000, "metric-unit" : "of all branches"}
> 
> {"thread" : "perf-62294", "counter-value" : "52693.000000", "unit" : "", "event" : "branch-misses", "event-runtime" : 9451948, "pcnt-running" : 100.00, "metric-value" : 3.114604, "metric-unit" : "of all branches"}
> 
> Traceback (most recent call last):
>   File "/home/acme/libexec/perf-core/tests/shell/lib/perf_json_output_lint.py", line 93, in <module>
>     check_json_output(expected_items)
>   File "/home/acme/libexec/perf-core/tests/shell/lib/perf_json_output_lint.py", line 54, in check_json_output
>     raise RuntimeError(f'wrong number of fields. counted {count} expected {expected_items}'
> RuntimeError: wrong number of fields. counted 6 expected [8, 10] in '{"thread" : "ksoftirqd/1-22", "counter-value" : "23883.000000", "unit" : "", "event" : "cycles", "event-runtime" : 9949, "pcnt-running" : 100.00}

Here it seems that the test finds unexpected number of entities in the
line. It can be, 6 is not in [8, 10]. However, since the line looks OK,
we should expand the set of accepted results to [6, 8, 10] then.

If this fails even without the test patch, so only with my JSON printing
patch, AND it does NOT fail without it, it seems very weird. The patch
fixes the JSON format breakage that happens when two metrics are per line.

The JSON output above looks sane, especially looking at the line that
failed:

  {"thread" : "ksoftirqd/1-22", "counter-value" : "23883.000000", "unit" : "", "event" : "cycles", "event-runtime" : 9949, "pcnt-running" : 100.00}

It rather seems that depending on the values counted, something gets
computed or not, and that changes the output, so sometimes a line with
unexpected count of elements appears there. Couldn't anything else
cause the change of the output?

Michael
> '
> test child finished with -1
> ---- end ----
> perf stat JSON output linter: FAILED!
> [root@quaco ~]#
> 
> 


^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 2/2] perf test: Fix JSON format linter test checks
  2023-01-31 17:14       ` Michael Petlan
@ 2023-02-02  1:18         ` Arnaldo Carvalho de Melo
  0 siblings, 0 replies; 18+ messages in thread
From: Arnaldo Carvalho de Melo @ 2023-02-02  1:18 UTC (permalink / raw)
  To: Michael Petlan
  Cc: linux-perf-users, acme, qzhao, cjense, Ian Rogers,
	Linux Kernel Mailing List, Namhyung Kim, Jiri Olsa,
	Adrian Hunter

Em Tue, Jan 31, 2023 at 06:14:17PM +0100, Michael Petlan escreveu:
> On Fri, 27 Jan 2023, Arnaldo Carvalho de Melo wrote:
> > Em Fri, Jan 27, 2023 at 09:26:03AM -0300, Arnaldo Carvalho de Melo escreveu:
> [...]
> 
> > > Before I apply this first patch I can run, as root, the 'perf test' JSON
> > > lint 100 times without problems:
> > > 
> > > [root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
> > > 1 98: perf stat JSON output linter                                    : Ok
> > > 2 98: perf stat JSON output linter                                    : Ok
> > > 3 98: perf stat JSON output linter                                    : Ok
> > > 4 98: perf stat JSON output linter                                    : Ok
> > > <SNIP>
> > > 96 98: perf stat JSON output linter                                    : Ok
> > > 97 98: perf stat JSON output linter                                    : Ok
> > > 98 98: perf stat JSON output linter                                    : Ok
> > > 99 98: perf stat JSON output linter                                    : Ok
> > > 100 98: perf stat JSON output linter                                    : Ok
> > > [root@quaco ~]#
> > > 
> > > After applying it it fails seemingly randomly, I'll remove both patches
> > > from my tmp.perf/core branch and investigate.
> 
> Hello Arnaldo. Have you found anything?
> 
> Which patch of the two causes the failures? The one that changes the JSON

Its described below, the first patch introduces the problem.

IT may well be due to the Intel model of my test machine, from what I
could read on the other threads about the "all metrics test", but I
haven't had time to fully investigate.

[acme@quaco pahole]$ grep -m1 ^model\ name /proc/cpuinfo 
model name	: Intel(R) Core(TM) i7-8650U CPU @ 1.90GHz
[acme@quaco pahole]$ 

- Arnaldo

> printing or the second that changes the test?
> 
> I hope that the JSON printing is now correct, it seems to be, at least on my
> machine + the SPR box I was debugging this on.
> 
> 
> > > 
> > > [acme@quaco perf]$ git log --oneline -1
> > > fdafd42aac3629db (HEAD) perf stat: Fix JSON metric printout for multiple metrics per line
> > > [acme@quaco perf]$ perf -v
> > > perf version 6.2.rc5.gfdafd42aac36
> > > [acme@quaco perf]$
> > > [root@quaco ~]# perf -v
> > > perf version 6.2.rc5.gfdafd42aac36
> > > [root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
> > > [root@quaco ~]# perf -v
> > > perf version 6.2.rc5.gfdafd42aac36
> > > [root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
> > > 1 98: perf stat JSON output linter                                    : Ok
> > > 2 98: perf stat JSON output linter                                    : Ok
> > > 3 98: perf stat JSON output linter                                    : FAILED!
> > > 4 98: perf stat JSON output linter                                    : Ok
> > 
> > BTW, after applying the second patch, the one for 'perf test', the
> > problem persists:
> > 
> > [acme@quaco perf]$ git log --oneline -1
> > 320cd37176508ec2 (HEAD, acme/tmp.perf/core, acme.korg/tmp.perf/core) perf test: Fix JSON format linter test checks
> > [acme@quaco perf]$ perf -v
> > perf version 6.2.rc5.g320cd3717650
> > [acme@quaco perf]$
> > [root@quaco ~]# perf -v
> > perf version 6.2.rc5.g320cd3717650
> > [root@quaco ~]# for a in $(seq 100) ; do echo -n $a ; perf test 98 ; done
> > 1 98: perf stat JSON output linter                                    : Ok
> > 2 98: perf stat JSON output linter                                    : FAILED!
> > 3 98: perf stat JSON output linter                                    : Ok
> > 4 98: perf stat JSON output linter                                    : Ok
> > 5 98: perf stat JSON output linter                                    : FAILED!
> > 6 98: perf stat JSON output linter                                    : Ok
> > 7 98: perf stat JSON output linter                                    : FAILED!
> > 8 98: perf stat JSON output linter                                    : Ok
> > 9 98: perf stat JSON output linter                                    : Ok
> > 10 98: perf stat JSON output linter                                    : FAILED!
> > 11 98: perf stat JSON output linter                                    : FAILED!
> > 12 98: perf stat JSON output linter                                    : FAILED!
> > 13 98: perf stat JSON output linter                                    : Ok
> > 14 98: perf stat JSON output linter                                    : Ok
> > 15 98: perf stat JSON output linter                                    : FAILED!
> > 16 98: perf stat JSON output linter                                    : FAILED!
> > 17 98: perf stat JSON output linter                                    : FAILED!
> > 18 98: perf stat JSON output linter                                    :^C
> > [root@quaco ~]#
> > 
> > When it works:
> > 
> > [root@quaco ~]# perf test -v 98
> >  98: perf stat JSON output linter                                    :
> > --- start ---
> > test child forked, pid 62202
> > Checking json output: no args [Success]
> > Checking json output: system wide [Success]
> > Checking json output: interval [Success]
> > Checking json output: event [Success]
> > Checking json output: per thread [Success]
> > Checking json output: per node [Success]
> > Checking json output: system wide Checking json output: system wide no aggregation [Success]
> > Checking json output: per core [Success]
> > Checking json output: per die [Success]
> > Checking json output: per socket [Success]
> > test child finished with 0
> > ---- end ----
> > perf stat JSON output linter: Ok
> > [root@quaco ~]#
> > 
> > When it fails:
> > 
> > [root@quaco ~]# perf test -v 98
> >  98: perf stat JSON output linter                                    :
> > --- start ---
> > test child forked, pid 62270
> > Checking json output: no args [Success]
> > Checking json output: system wide [Success]
> > Checking json output: interval [Success]
> > Checking json output: event [Success]
> > Checking json output: per thread Test failed for input:
> > {"thread" : "rcu_preempt-16", "counter-value" : "0.018340", "unit" : "msec", "event" : "cpu-clock", "event-runtime" : 19071, "pcnt-running" : 100.00, "metric-value" : 0.001758, "metric-unit" : "CPUs utilized"}
> > 
> > {"thread" : "gnome-terminal--2977", "counter-value" : "0.061868", "unit" : "msec", "event" : "cpu-clock", "event-runtime" : 62075, "pcnt-running" : 100.00, "metric-value" : 0.005930, "metric-unit" : "CPUs utilized"}
> > 
> > {"thread" : "perf-62294", "counter-value" : "9.398635", "unit" : "msec", "event" : "cpu-clock", "event-runtime" : 9398904, "pcnt-running" : 100.00, "metric-value" : 0.900916, "metric-unit" : "CPUs utilized"}
> > 
> > {"thread" : "rcu_preempt-16", "counter-value" : "4.000000", "unit" : "", "event" : "context-switches", "event-runtime" : 15203, "pcnt-running" : 100.00, "metric-value" : 218.102508, "metric-unit" : "K/sec"}
> > 
> > {"thread" : "gnome-terminal--2977", "counter-value" : "1.000000", "unit" : "", "event" : "context-switches", "event-runtime" : 62075, "pcnt-running" : 100.00, "metric-value" : 16.163445, "metric-unit" : "K/sec"}
> > 
> > {"thread" : "perf-62294", "counter-value" : "1.000000", "unit" : "", "event" : "context-switches", "event-runtime" : 9388658, "pcnt-running" : 100.00, "metric-value" : 106.398429, "metric-unit" : "/sec"}
> > 
> > {"thread" : "rcu_preempt-16", "counter-value" : "1.000000", "unit" : "", "event" : "cpu-migrations", "event-runtime" : 12511, "pcnt-running" : 100.00, "metric-value" : 54.525627, "metric-unit" : "K/sec"}
> > 
> > {"thread" : "perf-62294", "counter-value" : "2.000000", "unit" : "", "event" : "page-faults", "event-runtime" : 9427495, "pcnt-running" : 100.00, "metric-value" : 212.796858, "metric-unit" : "/sec"}
> > 
> > {"thread" : "rcu_preempt-16", "counter-value" : "41498.000000", "unit" : "", "event" : "cycles", "event-runtime" : 20944, "pcnt-running" : 100.00, "metric-value" : 2.262704, "metric-unit" : "GHz"}
> > 
> > {"thread" : "ksoftirqd/1-22", "counter-value" : "23883.000000", "unit" : "", "event" : "cycles", "event-runtime" : 9949, "pcnt-running" : 100.00}
> > 
> > {"thread" : "perf-62294", "counter-value" : "36686750.000000", "unit" : "", "event" : "cycles", "event-runtime" : 9439269, "pcnt-running" : 100.00, "metric-value" : 3.903413, "metric-unit" : "GHz"}
> > 
> > {"thread" : "rcu_preempt-16", "counter-value" : "25086.000000", "unit" : "", "event" : "instructions", "event-runtime" : 20944, "pcnt-running" : 100.00, "metric-value" : 0.604511, "metric-unit" : "insn per cycle"}
> > 
> > {"thread" : "ksoftirqd/1-22", "counter-value" : "13360.000000", "unit" : "", "event" : "instructions", "event-runtime" : 9949, "pcnt-running" : 100.00, "metric-value" : 0.559394, "metric-unit" : "insn per cycle"}
> > 
> > {"thread" : "perf-62294", "counter-value" : "7905940.000000", "unit" : "", "event" : "instructions", "event-runtime" : 9438686, "pcnt-running" : 100.00, "metric-value" : 0.215499, "metric-unit" : "insn per cycle"}
> > 
> > {"thread" : "rcu_preempt-16", "counter-value" : "3951.000000", "unit" : "", "event" : "branches", "event-runtime" : 16533, "pcnt-running" : 100.00, "metric-value" : 215.430752, "metric-unit" : "M/sec"}
> > 
> > {"thread" : "ksoftirqd/1-22", "counter-value" : "2822.000000", "unit" : "", "event" : "branches", "event-runtime" : 9949, "pcnt-running" : 100.00, "metric-value" : 0.000000, "metric-unit" : "/sec"}
> > 
> > {"thread" : "perf-62294", "counter-value" : "1691804.000000", "unit" : "", "event" : "branches", "event-runtime" : 9474118, "pcnt-running" : 100.00, "metric-value" : 180.005288, "metric-unit" : "M/sec"}
> > 
> > {"thread" : "rcu_preempt-16", "counter-value" : "279.000000", "unit" : "", "event" : "branch-misses", "event-runtime" : 16533, "pcnt-running" : 100.00, "metric-value" : 7.061503, "metric-unit" : "of all branches"}
> > 
> > {"thread" : "ksoftirqd/1-22", "counter-value" : "153.000000", "unit" : "", "event" : "branch-misses", "event-runtime" : 9949, "pcnt-running" : 100.00, "metric-value" : 5.421687, "metric-unit" : "of all branches"}
> > 
> > {"thread" : "kworker/1:2-events-752", "counter-value" : "121.000000", "unit" : "", "event" : "branch-misses", "event-runtime" : 9850, "pcnt-running" : 100.00, "metric-value" : 0.000000, "metric-unit" : "of all branches"}
> > 
> > {"thread" : "perf-62294", "counter-value" : "52693.000000", "unit" : "", "event" : "branch-misses", "event-runtime" : 9451948, "pcnt-running" : 100.00, "metric-value" : 3.114604, "metric-unit" : "of all branches"}
> > 
> > Traceback (most recent call last):
> >   File "/home/acme/libexec/perf-core/tests/shell/lib/perf_json_output_lint.py", line 93, in <module>
> >     check_json_output(expected_items)
> >   File "/home/acme/libexec/perf-core/tests/shell/lib/perf_json_output_lint.py", line 54, in check_json_output
> >     raise RuntimeError(f'wrong number of fields. counted {count} expected {expected_items}'
> > RuntimeError: wrong number of fields. counted 6 expected [8, 10] in '{"thread" : "ksoftirqd/1-22", "counter-value" : "23883.000000", "unit" : "", "event" : "cycles", "event-runtime" : 9949, "pcnt-running" : 100.00}
> 
> Here it seems that the test finds unexpected number of entities in the
> line. It can be, 6 is not in [8, 10]. However, since the line looks OK,
> we should expand the set of accepted results to [6, 8, 10] then.
> 
> If this fails even without the test patch, so only with my JSON printing
> patch, AND it does NOT fail without it, it seems very weird. The patch
> fixes the JSON format breakage that happens when two metrics are per line.
> 
> The JSON output above looks sane, especially looking at the line that
> failed:
> 
>   {"thread" : "ksoftirqd/1-22", "counter-value" : "23883.000000", "unit" : "", "event" : "cycles", "event-runtime" : 9949, "pcnt-running" : 100.00}
> 
> It rather seems that depending on the values counted, something gets
> computed or not, and that changes the output, so sometimes a line with
> unexpected count of elements appears there. Couldn't anything else
> cause the change of the output?
> 
> Michael
> > '
> > test child finished with -1
> > ---- end ----
> > perf stat JSON output linter: FAILED!
> > [root@quaco ~]#
> > 
> > 
> 

-- 

- Arnaldo

^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 1/2] perf stat: Fix JSON metric printout for multiple metrics per line
  2023-01-20 13:40 ` [PATCH 1/2] perf stat: Fix JSON metric printout for multiple metrics per line Michael Petlan
  2023-01-23  6:31   ` Namhyung Kim
@ 2023-05-22 12:11   ` Michael Petlan
  2023-06-06 11:16     ` Michael Petlan
  1 sibling, 1 reply; 18+ messages in thread
From: Michael Petlan @ 2023-05-22 12:11 UTC (permalink / raw)
  To: acme; +Cc: linux-perf-users, acme, qzhao, cjense, irogers

Hello Ian and Arnaldo,

I've recently got back to the JSON test failures. In January, I post two
patches within a patchset. I see that Ian has updated the testcase code,
so the second patch is probably no more needed. However I don't see this
one applied upstream yet, although it seemed on the list, it had got some
acks. Has it been forgotten somehow?

To remind, since the JSON printer engine wasn't ready to print multiple
metrics per line, the JSON output got screwed up in that situation. The
situation happened on some SPR CPUs, where Top-Down metrics are supported.

The patch below fixes the printer to handle this situation correctly.

I remember someone saying that the whole printer engine needs to be
refactored some day, but I'd think that before that happens, it'd be
nice to have it fixed...

What do you think?

Regards,
Michael

On Fri, 20 Jan 2023, Michael Petlan wrote:
> JSON printing engine used to always print metric (even when there should
> be none and other engines (std, csv) would not print it) and the metric
> used to always close the line by printing a closing curly bracket.
> 
> This caused invalid JSON output being generated for top-down metrics,
> when multiple metrics are printed on a single line, so the broken output
> might have looked like:
> 
>   ... "metric-value" : 15.564203, "metric-unit" : \
>   "Memory Bound"}"metric-value" : 14.007787, "metric-unit" : "Core Bound"}
> 
> To fix it, print always the separating comma BEFORE the key:value pairs
> and close the line outside of the JSON metric printing routine.
> 
> Fixes: df936cadfb58 ("perf stat: Add JSON output option")
> 
> Signed-off-by: Michael Petlan <mpetlan@redhat.com>
> ---
>  tools/perf/util/stat-display.c | 28 ++++++++++++++++------------
>  1 file changed, 16 insertions(+), 12 deletions(-)
> 
> diff --git a/tools/perf/util/stat-display.c b/tools/perf/util/stat-display.c
> index 8bd8b0142630..8f80f6b566d0 100644
> --- a/tools/perf/util/stat-display.c
> +++ b/tools/perf/util/stat-display.c
> @@ -86,7 +86,7 @@ static void print_running_json(struct perf_stat_config *config, u64 run, u64 ena
>  
>  	if (run != ena)
>  		enabled_percent = 100 * run / ena;
> -	fprintf(config->output, "\"event-runtime\" : %" PRIu64 ", \"pcnt-running\" : %.2f, ",
> +	fprintf(config->output, ", \"event-runtime\" : %" PRIu64 ", \"pcnt-running\" : %.2f",
>  		run, enabled_percent);
>  }
>  
> @@ -121,7 +121,7 @@ static void print_noise_pct_csv(struct perf_stat_config *config,
>  static void print_noise_pct_json(struct perf_stat_config *config,
>  				 double pct)
>  {
> -	fprintf(config->output, "\"variance\" : %.2f, ", pct);
> +	fprintf(config->output, ", \"variance\" : %.2f", pct);
>  }
>  
>  static void print_noise_pct(struct perf_stat_config *config,
> @@ -165,7 +165,7 @@ static void print_cgroup_csv(struct perf_stat_config *config, const char *cgrp_n
>  
>  static void print_cgroup_json(struct perf_stat_config *config, const char *cgrp_name)
>  {
> -	fprintf(config->output, "\"cgroup\" : \"%s\", ", cgrp_name);
> +	fprintf(config->output, ", \"cgroup\" : \"%s\"", cgrp_name);
>  }
>  
>  static void print_cgroup(struct perf_stat_config *config, struct cgroup *cgrp)
> @@ -431,10 +431,11 @@ static void print_metric_json(struct perf_stat_config *config __maybe_unused,
>  	struct outstate *os = ctx;
>  	FILE *out = os->fh;
>  
> -	fprintf(out, "\"metric-value\" : %f, ", val);
> -	fprintf(out, "\"metric-unit\" : \"%s\"", unit);
> -	if (!config->metric_only)
> -		fprintf(out, "}");
> +	if (unit == NULL || fmt == NULL)
> +		return;
> +
> +	fprintf(out, ", \"metric-value\" : %f", val);
> +	fprintf(out, ", \"metric-unit\" : \"%s\"", unit);
>  }
>  
>  static void new_line_json(struct perf_stat_config *config, void *ctx)
> @@ -623,14 +624,14 @@ static void print_counter_value_json(struct perf_stat_config *config,
>  	const char *bad_count = evsel->supported ? CNTR_NOT_COUNTED : CNTR_NOT_SUPPORTED;
>  
>  	if (ok)
> -		fprintf(output, "\"counter-value\" : \"%f\", ", avg);
> +		fprintf(output, "\"counter-value\" : \"%f\"", avg);
>  	else
> -		fprintf(output, "\"counter-value\" : \"%s\", ", bad_count);
> +		fprintf(output, "\"counter-value\" : \"%s\"", bad_count);
>  
>  	if (evsel->unit)
> -		fprintf(output, "\"unit\" : \"%s\", ", evsel->unit);
> +		fprintf(output, ", \"unit\" : \"%s\"", evsel->unit);
>  
> -	fprintf(output, "\"event\" : \"%s\", ", evsel__name(evsel));
> +	fprintf(output, ", \"event\" : \"%s\"", evsel__name(evsel));
>  }
>  
>  static void print_counter_value(struct perf_stat_config *config,
> @@ -835,8 +836,11 @@ static void print_counter_aggrdata(struct perf_stat_config *config,
>  
>  	printout(config, os, uval, run, ena, avg, s);
>  
> -	if (!metric_only)
> +	if (!metric_only) {
> +		if (config->json_output)
> +			fputc('}', output);
>  		fputc('\n', output);
> +	}
>  }
>  
>  static void print_metric_begin(struct perf_stat_config *config,
> -- 
> 2.18.4
> 
> 


^ permalink raw reply	[flat|nested] 18+ messages in thread

* Re: [PATCH 1/2] perf stat: Fix JSON metric printout for multiple metrics per line
  2023-05-22 12:11   ` Michael Petlan
@ 2023-06-06 11:16     ` Michael Petlan
  0 siblings, 0 replies; 18+ messages in thread
From: Michael Petlan @ 2023-06-06 11:16 UTC (permalink / raw)
  To: acme; +Cc: linux-perf-users, acme, qzhao, cjense, irogers

Gently ping...

On Mon, 22 May 2023, Michael Petlan wrote:
> Hello Ian and Arnaldo,
> 
> I've recently got back to the JSON test failures. In January, I post two
> patches within a patchset. I see that Ian has updated the testcase code,
> so the second patch is probably no more needed. However I don't see this
> one applied upstream yet, although it seemed on the list, it had got some
> acks. Has it been forgotten somehow?
> 
> To remind, since the JSON printer engine wasn't ready to print multiple
> metrics per line, the JSON output got screwed up in that situation. The
> situation happened on some SPR CPUs, where Top-Down metrics are supported.
> 
> The patch below fixes the printer to handle this situation correctly.
> 
> I remember someone saying that the whole printer engine needs to be
> refactored some day, but I'd think that before that happens, it'd be
> nice to have it fixed...
> 
> What do you think?
> 
> Regards,
> Michael
> 
> On Fri, 20 Jan 2023, Michael Petlan wrote:
> > JSON printing engine used to always print metric (even when there should
> > be none and other engines (std, csv) would not print it) and the metric
> > used to always close the line by printing a closing curly bracket.
> > 
> > This caused invalid JSON output being generated for top-down metrics,
> > when multiple metrics are printed on a single line, so the broken output
> > might have looked like:
> > 
> >   ... "metric-value" : 15.564203, "metric-unit" : \
> >   "Memory Bound"}"metric-value" : 14.007787, "metric-unit" : "Core Bound"}
> > 
> > To fix it, print always the separating comma BEFORE the key:value pairs
> > and close the line outside of the JSON metric printing routine.
> > 
> > Fixes: df936cadfb58 ("perf stat: Add JSON output option")
> > 
> > Signed-off-by: Michael Petlan <mpetlan@redhat.com>
> > ---
> >  tools/perf/util/stat-display.c | 28 ++++++++++++++++------------
> >  1 file changed, 16 insertions(+), 12 deletions(-)
> > 
> > diff --git a/tools/perf/util/stat-display.c b/tools/perf/util/stat-display.c
> > index 8bd8b0142630..8f80f6b566d0 100644
> > --- a/tools/perf/util/stat-display.c
> > +++ b/tools/perf/util/stat-display.c
> > @@ -86,7 +86,7 @@ static void print_running_json(struct perf_stat_config *config, u64 run, u64 ena
> >  
> >  	if (run != ena)
> >  		enabled_percent = 100 * run / ena;
> > -	fprintf(config->output, "\"event-runtime\" : %" PRIu64 ", \"pcnt-running\" : %.2f, ",
> > +	fprintf(config->output, ", \"event-runtime\" : %" PRIu64 ", \"pcnt-running\" : %.2f",
> >  		run, enabled_percent);
> >  }
> >  
> > @@ -121,7 +121,7 @@ static void print_noise_pct_csv(struct perf_stat_config *config,
> >  static void print_noise_pct_json(struct perf_stat_config *config,
> >  				 double pct)
> >  {
> > -	fprintf(config->output, "\"variance\" : %.2f, ", pct);
> > +	fprintf(config->output, ", \"variance\" : %.2f", pct);
> >  }
> >  
> >  static void print_noise_pct(struct perf_stat_config *config,
> > @@ -165,7 +165,7 @@ static void print_cgroup_csv(struct perf_stat_config *config, const char *cgrp_n
> >  
> >  static void print_cgroup_json(struct perf_stat_config *config, const char *cgrp_name)
> >  {
> > -	fprintf(config->output, "\"cgroup\" : \"%s\", ", cgrp_name);
> > +	fprintf(config->output, ", \"cgroup\" : \"%s\"", cgrp_name);
> >  }
> >  
> >  static void print_cgroup(struct perf_stat_config *config, struct cgroup *cgrp)
> > @@ -431,10 +431,11 @@ static void print_metric_json(struct perf_stat_config *config __maybe_unused,
> >  	struct outstate *os = ctx;
> >  	FILE *out = os->fh;
> >  
> > -	fprintf(out, "\"metric-value\" : %f, ", val);
> > -	fprintf(out, "\"metric-unit\" : \"%s\"", unit);
> > -	if (!config->metric_only)
> > -		fprintf(out, "}");
> > +	if (unit == NULL || fmt == NULL)
> > +		return;
> > +
> > +	fprintf(out, ", \"metric-value\" : %f", val);
> > +	fprintf(out, ", \"metric-unit\" : \"%s\"", unit);
> >  }
> >  
> >  static void new_line_json(struct perf_stat_config *config, void *ctx)
> > @@ -623,14 +624,14 @@ static void print_counter_value_json(struct perf_stat_config *config,
> >  	const char *bad_count = evsel->supported ? CNTR_NOT_COUNTED : CNTR_NOT_SUPPORTED;
> >  
> >  	if (ok)
> > -		fprintf(output, "\"counter-value\" : \"%f\", ", avg);
> > +		fprintf(output, "\"counter-value\" : \"%f\"", avg);
> >  	else
> > -		fprintf(output, "\"counter-value\" : \"%s\", ", bad_count);
> > +		fprintf(output, "\"counter-value\" : \"%s\"", bad_count);
> >  
> >  	if (evsel->unit)
> > -		fprintf(output, "\"unit\" : \"%s\", ", evsel->unit);
> > +		fprintf(output, ", \"unit\" : \"%s\"", evsel->unit);
> >  
> > -	fprintf(output, "\"event\" : \"%s\", ", evsel__name(evsel));
> > +	fprintf(output, ", \"event\" : \"%s\"", evsel__name(evsel));
> >  }
> >  
> >  static void print_counter_value(struct perf_stat_config *config,
> > @@ -835,8 +836,11 @@ static void print_counter_aggrdata(struct perf_stat_config *config,
> >  
> >  	printout(config, os, uval, run, ena, avg, s);
> >  
> > -	if (!metric_only)
> > +	if (!metric_only) {
> > +		if (config->json_output)
> > +			fputc('}', output);
> >  		fputc('\n', output);
> > +	}
> >  }
> >  
> >  static void print_metric_begin(struct perf_stat_config *config,
> > -- 
> > 2.18.4
> > 
> > 
> 
> 


^ permalink raw reply	[flat|nested] 18+ messages in thread

end of thread, other threads:[~2023-06-06 11:17 UTC | newest]

Thread overview: 18+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2023-01-20 13:40 [PATCH 0/2] perf test: Fix JSON linter Michael Petlan
2023-01-20 13:40 ` [PATCH 1/2] perf stat: Fix JSON metric printout for multiple metrics per line Michael Petlan
2023-01-23  6:31   ` Namhyung Kim
2023-05-22 12:11   ` Michael Petlan
2023-06-06 11:16     ` Michael Petlan
2023-01-20 13:40 ` [PATCH 2/2] perf test: Fix JSON format linter test checks Michael Petlan
2023-01-23  6:36   ` Namhyung Kim
2023-01-24 16:49     ` Michael Petlan
2023-01-24 17:26       ` Namhyung Kim
2023-01-27 12:26   ` Arnaldo Carvalho de Melo
2023-01-27 12:30     ` Arnaldo Carvalho de Melo
2023-01-31 17:14       ` Michael Petlan
2023-02-02  1:18         ` Arnaldo Carvalho de Melo
2023-01-20 17:37 ` [PATCH 0/2] perf test: Fix JSON linter Ian Rogers
2023-01-23  6:48   ` Namhyung Kim
2023-01-23 13:38   ` Arnaldo Carvalho de Melo
2023-01-24 17:39   ` Michael Petlan
2023-01-25  0:37     ` Ian Rogers

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.