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

[kajoljain]

On 11/4/22 13:07, Disha Goel wrote:
> On 11/4/22 12: 59 PM, Athira Rajeev wrote: 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 ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍
> ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍
> ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍ ‍
> 
> 
> 
> On 11/4/22 12:59 PM, Athira Rajeev wrote:
>>> On 03-Nov-2022, at 9:45 PM, Ian Rogers <irogers at google.com> wrote:
>>>
>>> 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>
> 
> perf stat csv test passed after applying the patch
> Tested-by: Disha Goel <disgoel at linux.vnet.ibm.com>


Hi,
  Patch looks fine to me.

Reviewed-By: Kajol Jain <kjain at linux.ibm.com>

Thanks,
Kajol Jain

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