Re: [PATCH 1/2] tools/perf: Fix printing os->prefix in CSV metrics output

On 03-Nov-2022, at 9:45 PM, Ian Rogers [off-list ref] wrote:

On Wed, Nov 2, 2022 at 1:36 AM Athira Rajeev
[off-list ref] wrote:

quoted

quoted

On 18-Oct-2022, at 2:26 PM, Athira Rajeev [off-list ref] wrote:

Perf stat with CSV output option prints an extra empty
string as first field in metrics output line.
Sample output below:

     # ./perf stat -x, --per-socket -a -C 1 ls
     S0,1,1.78,msec,cpu-clock,1785146,100.00,0.973,CPUs utilized
     S0,1,26,,context-switches,1781750,100.00,0.015,M/sec
     S0,1,1,,cpu-migrations,1780526,100.00,0.561,K/sec
     S0,1,1,,page-faults,1779060,100.00,0.561,K/sec
     S0,1,875807,,cycles,1769826,100.00,0.491,GHz
     S0,1,85281,,stalled-cycles-frontend,1767512,100.00,9.74,frontend cycles idle
     S0,1,576839,,stalled-cycles-backend,1766260,100.00,65.86,backend cycles idle
     S0,1,288430,,instructions,1762246,100.00,0.33,insn per cycle
====> ,S0,1,,,,,,,2.00,stalled cycles per insn

The above command line uses field separator as ","
via "-x," option and per-socket option displays
socket value as first field. But here the last line
for "stalled cycles per insn" has "," in the
beginning.

Sample output using interval mode:
     # ./perf stat -I 1000 -x, --per-socket -a -C 1 ls
     0.001813453,S0,1,1.87,msec,cpu-clock,1872052,100.00,0.002,CPUs utilized
     0.001813453,S0,1,2,,context-switches,1868028,100.00,1.070,K/sec
     ------
     0.001813453,S0,1,85379,,instructions,1856754,100.00,0.32,insn per cycle
====> 0.001813453,,S0,1,,,,,,,1.34,stalled cycles per insn

Above result also has an extra csv separator after
the timestamp. Patch addresses extra field separator
in the beginning of the metric output line.

The counter stats are displayed by function
"perf_stat__print_shadow_stats" in code
"util/stat-shadow.c". While printing the stats info
for "stalled cycles per insn", function "new_line_csv"
is used as new_line callback.

The new_line_csv function has check for "os->prefix"
and if prefix is not null, it will be printed along
with cvs separator.
Snippet from "new_line_csv":
     if (os->prefix)
             fprintf(os->fh, "%s%s", os->prefix, config->csv_sep);

Here os->prefix gets printed followed by ","
which is the cvs separator. The os->prefix is
used in interval mode option ( -I ), to print
time stamp on every new line. But prefix is
already set to contain csv separator when used
in interval mode for csv option.

Reference: Function "static void print_interval"
Snippet:
     sprintf(prefix, "%6lu.%09lu%s", ts->tv_sec, ts->tv_nsec, config->csv_sep);

Also if prefix is not assigned (if not used with
-I option), it gets set to empty string.
Reference: function printout() in util/stat-display.c
Snippet:
     .prefix = prefix ? prefix : "",

Since prefix already set to contain cvs_sep in interval
option, patch removes printing config->csv_sep in
new_line_csv function to avoid printing extra field.

After the patch:

     # ./perf stat -x, --per-socket -a -C 1 ls
     S0,1,2.04,msec,cpu-clock,2045202,100.00,1.013,CPUs utilized
     S0,1,2,,context-switches,2041444,100.00,979.289,/sec
     S0,1,0,,cpu-migrations,2040820,100.00,0.000,/sec
     S0,1,2,,page-faults,2040288,100.00,979.289,/sec
     S0,1,254589,,cycles,2036066,100.00,0.125,GHz
     S0,1,82481,,stalled-cycles-frontend,2032420,100.00,32.40,frontend cycles idle
     S0,1,113170,,stalled-cycles-backend,2031722,100.00,44.45,backend cycles idle
     S0,1,88766,,instructions,2030942,100.00,0.35,insn per cycle
     S0,1,,,,,,,1.27,stalled cycles per insn

Fixes: 92a61f6412d3 ("perf stat: Implement CSV metrics output")
Reported-by: Disha Goel <redacted>
Signed-off-by: Athira Rajeev <redacted>

Hi All,

Looking for review comments for this change.

Hi,

Thanks for addressing issues in this code. What is the status of the
CSV output test following these changes?

I think going forward we need to move away from CSV and columns, to
something with structure like json. We also need to refactor this
code, trying to add meaning to a newline character is a bad strategy
and creates some unnatural things. To some extent this overlaps with
Namhyung's aggregation cleanup. There are also weirdnesses in
jevents/pmu-events, like the same ScaleUnit applying to a metric and
an event - why are metrics even parts of events?

Given the current code is wac-a-mole, and this is another whack, if
the testing is okay I think we should move forward with this change.

Thanks,
Ian

Hi Ian,

Thanks for checking the patch.
Yes, CSV output test passes with the change.

	perf stat CSV output linter                                     : Ok
	perf stat csv summary test                                      : Ok

Thanks
Athira

quoted

Thanks
Athira

quoted

---
tools/perf/util/stat-display.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/perf/util/stat-display.c b/tools/perf/util/stat-display.c
index 5c47ee9963a7..879874a4bc07 100644
--- a/tools/perf/util/stat-display.c
+++ b/tools/perf/util/stat-display.c

@@ -273,7 +273,7 @@ static void new_line_csv(struct perf_stat_config *config, void *ctx)

     fputc('\n', os->fh);
     if (os->prefix)
-             fprintf(os->fh, "%s%s", os->prefix, config->csv_sep);
+             fprintf(os->fh, "%s", os->prefix);
     aggr_printout(config, os->evsel, os->id, os->nr);
     for (i = 0; i < os->nfields; i++)
             fputs(config->csv_sep, os->fh);
--

2.31.1