[PATCH v1 21/41] perf script: Fix metrics computed from samples

[Ian Rogers <irogers@google.com>]

perf script -F metric computes metrics from the sum of sample periods of
the events, but the computed values were wrong and the output was
garbled:

 - perf_stat_process_counter() replaces each count with its delta from
   the previous raw count. As counts were left as deltas, the next sample
   computed negative deltas for the counts of all CPUs and threads other
   than the sample's. Restore the counts to the running totals after
   processing.

 - Metrics for all events were displayed after every sample. Only display
   the metrics associated with the sampled event.

 - The new_line callback started a metric line that the next metric
   started again. Each metric starts its own line, so make it a no-op.

 - The metric value was written to stdout rather than the event's output
   file.

For example, with whitespace reduced:

  $ perf record -e '{cpu_core/instructions/,cpu_core/cycles/}:S' -a sleep 1
  $ perf script -F comm,cpu,event,period,metric

Before:

  perf [001]  2206 cpu_core/cycles/:
  perf [001] metric: 42972.00 tma_info_inst_mix_instructions
  perf [001] metric: perf [001] metric: 1.20 tma_info_thread_cpi
  perf [001] metric: perf [001] metric: 0.83 tma_info_thread_ipc
  perf [001] metric: 51762.00 tma_info_thread_clks
  perf [001]   804 cpu_core/instructions/:
  perf [001] metric: 18446744073709549568.00 tma_info_inst_mix_instructions

After:

  perf [001]  2206 cpu_core/cycles/:
  perf [001] metric: 67668.00 tma_info_thread_clks
  perf [001]   804 cpu_core/instructions/:
  perf [001] metric: 46758.00 tma_info_inst_mix_instructions
  perf [001] metric:     1.45 tma_info_thread_cpi
  perf [001] metric:     0.69 tma_info_thread_ipc

Before, the cpu_core/cycles/ sample is followed by the metrics of both
events, such as tma_info_inst_mix_instructions that only uses the
instructions event, rather than just tma_info_thread_clks. The CPI and
IPC lines repeat the "perf [001] metric:" prefix as script_new_line()
started a line that script_print_metric() started again. The following
cpu_core/instructions/ sample shows tma_info_inst_mix_instructions as
18446744073709549568, a negative delta, as the counts of the other CPUs
were left as deltas by the previous sample. The same deltas made the
before tma_info_thread_clks value of 51762 too small.

After, each sample is followed only by the metrics of the sampled event,
one per line, and the metric values are computed from the running totals
of the sample periods of all CPUs.

Fixes: 4bd1bef8bba2 ("perf script: Allow computing 'perf stat' style metrics")
Fixes: 3622990efaab ("perf script: Change metric format to use json metrics")
Signed-off-by: Ian Rogers <irogers@google.com>
---
 tools/perf/builtin-script.c | 32 ++++++++++++++++++--------------
 1 file changed, 18 insertions(+), 14 deletions(-)

diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index da3f1793774e..199a5af81f37 100644
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -2340,18 +2340,14 @@ static void script_print_metric(struct perf_stat_config *config __maybe_unused,
 	if (color)
 		color_fprintf(mctx->fp, color, fmt, val);
 	else
-		printf(fmt, val);
+		fprintf(mctx->fp, fmt, val);
 	fprintf(mctx->fp, " %s\n", unit);
 }
 
 static void script_new_line(struct perf_stat_config *config __maybe_unused,
-			    void *ctx)
+			    void *ctx __maybe_unused)
 {
-	struct metric_ctx *mctx = ctx;
-
-	perf_sample__fprintf_start(NULL, mctx->sample, mctx->thread, mctx->evsel,
-				   PERF_RECORD_SAMPLE, mctx->fp);
-	fputs("\tmetric: ", mctx->fp);
+	/* Each metric is printed on its own line by script_print_metric(). */
 }
 
 static struct aggr_cpu_id script_aggr_cpu_id_get(struct perf_stat_config *config __maybe_unused,
@@ -2379,7 +2375,6 @@ static void perf_sample__fprint_metric(struct thread *thread,
 	};
 	struct perf_counts_values *count, *old_count;
 	int cpu_map_idx, thread_map_idx, aggr_idx;
-	struct evsel *pos;
 
 	if (!init_metrics) {
 		/* One time initialization of stat_config and metric data. */
@@ -2445,14 +2440,23 @@ static void perf_sample__fprint_metric(struct thread *thread,
 	/* Update the aggregated stats. */
 	perf_stat_process_counter(&stat_config, evsel);
 
-	/* Display all metrics. */
-	evlist__for_each_entry(evsel->evlist, pos) {
-		cpu_aggr_map__for_each_idx(aggr_idx, stat_config.aggr_map) {
-			perf_stat__print_shadow_stats(&stat_config, pos,
-						aggr_idx,
-						&ctx);
+	/*
+	 * Processing the counter replaced the counts with deltas from the
+	 * previous raw counts. Restore the running totals so that only the
+	 * next sample's period is added to the aggregated stats.
+	 */
+	for (unsigned int cpu_idx = 0; cpu_idx < perf_cpu_map__nr(evsel->core.cpus); cpu_idx++) {
+		for (int thread_idx = 0;
+		     thread_idx < perf_thread_map__nr(evsel->core.threads);
+		     thread_idx++) {
+			*perf_counts(evsel->counts, cpu_idx, thread_idx) =
+				*perf_counts(evsel->prev_raw_counts, cpu_idx, thread_idx);
 		}
 	}
+
+	/* Display the metrics associated with the sampled event. */
+	cpu_aggr_map__for_each_idx(aggr_idx, stat_config.aggr_map)
+		perf_stat__print_shadow_stats(&stat_config, evsel, aggr_idx, &ctx);
 }
 
 static bool show_event(struct perf_sample *sample,
-- 
2.56.0.385.gac671c819a-goog