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

[Athira Rajeev <atrajeev@linux.vnet.ibm.com>]

> On 03-Nov-2022, at 9:45 PM, Ian Rogers <irogers@google.com> wrote:
> 
> On Wed, Nov 2, 2022 at 1:36 AM Athira Rajeev
> <atrajeev@linux.vnet.ibm.com> wrote:
>> 
>> 
>> 
>>> On 18-Oct-2022, at 2:26 PM, Athira Rajeev <atrajeev@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@linux.vnet.ibm.com>
>>> Signed-off-by: Athira Rajeev <atrajeev@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

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

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