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

[Ian Rogers]

On Wed, Nov 2, 2022 at 1:36 AM Athira Rajeev
<atrajeev at linux.vnet.ibm.com> wrote:
>
>
>
> > On 18-Oct-2022, at 2:26 PM, Athira Rajeev <atrajeev at linux.vnet.ibm.com> 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 <disgoel at linux.vnet.ibm.com>
> > Signed-off-by: Athira Rajeev <atrajeev at linux.vnet.ibm.com>
>
> 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




> Thanks
> Athira
>
> > ---
> > 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
> >
>