Re: [PATCH] perf bench: flush stats when pipe it to a file or to tee

Arnaldo Carvalho de Melo
2021-11-16T13:48:05Z

Em Tue, Nov 16, 2021 at 12:41:51AM +0200, Sohaib Mohamed escreveu:
> Hello, Arnaldo
>
> On Sat, Nov 13, 2021 at 09:18:22AM -0300, Arnaldo Carvalho de Melo wrote:
> > Em Sat, Nov 13, 2021 at 09:16:42AM -0300, Arnaldo Carvalho de Melo escreveu:
> > > Em Fri, Nov 12, 2021 at 11:53:12PM +0200, Sohaib Mohamed escreveu:
> > > > The output of perf bench gets buffered when I pipe it to a file or to
> > > > tee, in such a way that I can see it only at the end.
> > >
> > > Good, now try with 'perf test' :-)
> > >
> > > Applying,
> >
> > Humm, take that back, when I almost did it for 'perf test' I used
> > setvbuf(), take a look at it so that you don't have to go sprinkling
> > fflush() calls and missing some places.
> >
> > - Arnaldo
>
> I'm not sure about the meaning of 'perf test' here, Should I write new unit
> tests?

Try:

$ perf test 2>&1 | tee /tmp/bla

It uses buffered output, so we see the output in bumps, would be better
to use unbuffered.

> I found I could invoke this function at the beginning of perf-bench:
> setvbuf(stdout, NULL, _IONBF, 0);
> This looks to me will resolve the issue for all perf-bench subcommands.
> I'm not sure if a good practice...

Well, it will achieve what you want, right? Unbuffered output, which I
think is desirable.

> This probably is version 2 of this patch:

Yeah, looks ok.

- Arnaldo

>
> diff --git a/tools/perf/builtin-bench.c b/tools/perf/builtin-bench.c
> index d0895162c2ba..a0b812cde1ee 100644
> --- a/tools/perf/builtin-bench.c
> +++ b/tools/perf/builtin-bench.c
> @@ -226,7 +226,6 @@ static void run_collection(struct collection *coll)
> if (!bench->fn)
> break;
> printf("# Running %s/%s benchmark...\n", coll->name, bench->name);
> - fflush(stdout);
>
> argv[1] = bench->name;
> run_bench(coll->name, bench->name, bench->fn, 1, argv);
> @@ -247,6 +246,8 @@ int cmd_bench(int argc, const char **argv)
> struct collection *coll;
> int ret = 0;
>
> + setvbuf(stdout, NULL, _IONBF, 0);
> +
> if (argc < 2) {
> /* No collection specified. */
> print_usage();
> @@ -300,7 +301,6 @@ int cmd_bench(int argc, const char **argv)
>
> if (bench_format == BENCH_FORMAT_DEFAULT)
> printf("# Running '%s/%s' benchmark:\n", coll->name, bench->name);
> - fflush(stdout);
> ret = run_bench(coll->name, bench->name, bench->fn, argc-1, argv+1);
> goto end;
> }
>
>
>
> Thanks,
> - Sohaib
>
> >
> > > - Arnaldo
> > >
> > > > E.g.
> > > > $ perf bench internals synthesize -t
> > > > < output comes out fine after each test run >
> > > >
> > > > $ perf bench internals synthesize -t | tee file.txt
> > > > < output comes out only at the end of all tests >
> > > >
> > > > See, also:
> > > > $ perf bench mem all | tee file.txt
> > > > $ perf bench sched all | tee file.txt
> > > > $ perf bench internals all -t | tee file.txt
> > > > $ perf bench internals all | tee file.txt
> > > >
> > > > Suggested-by: Riccardo Mancini <rickyman7@gmail.com>
> > > > Signed-off-by: Sohaib Mohamed <sohaib.amhmd@gmail.com>
> > > > ---
> > > > tools/perf/bench/find-bit-bench.c | 1 +
> > > > tools/perf/bench/synthesize.c | 2 ++
> > > > 2 files changed, 3 insertions(+)
> > > >
> > > > diff --git a/tools/perf/bench/find-bit-bench.c b/tools/perf/bench/find-bit-bench.c
> > > > index 22b5cfe97023..39fb4184fbcb 100644
> > > > --- a/tools/perf/bench/find-bit-bench.c
> > > > +++ b/tools/perf/bench/find-bit-bench.c
> > > > @@ -113,6 +113,7 @@ static int do_for_each_set_bit(unsigned int num_bits)
> > > >
> > > > if (use_of_val == accumulator) /* Try to avoid compiler tricks. */
> > > > printf("\n");
> > > > + fflush(stdout);
> > > > }
> > > > bitmap_free(to_test);
> > > > return 0;
> > > > diff --git a/tools/perf/bench/synthesize.c b/tools/perf/bench/synthesize.c
> > > > index 7401ebbac100..d21d311df61b 100644
> > > > --- a/tools/perf/bench/synthesize.c
> > > > +++ b/tools/perf/bench/synthesize.c
> > > > @@ -92,6 +92,7 @@ static int do_run_single_threaded(struct perf_session *session,
> > > > update_stats(&event_stats, atomic_read(&event_count));
> > > > }
> > > >
> > > > + fflush(stdout);
> > > > time_average = avg_stats(&time_stats);
> > > > time_stddev = stddev_stats(&time_stats);
> > > > printf(" Average %ssynthesis took: %.3f usec (+- %.3f usec)\n",
> > > > @@ -186,6 +187,7 @@ static int do_run_multi_threaded(struct target *target,
> > > > perf_session__delete(session);
> > > > }
> > > >
> > > > + fflush(stdout);
> > > > time_average = avg_stats(&time_stats);
> > > > time_stddev = stddev_stats(&time_stats);
> > > > printf(" Average synthesis took: %.3f usec (+- %.3f usec)\n",
> > > > --
> > > > 2.25.1
> > >
> > > --
> > >
> > > - Arnaldo
> >
> > --
> >
> > - Arnaldo

--

- Arnaldo