Re: [PATCH 2/2] perf script: flush output stream after events in verbose mode

From: Jiri Olsa
Date: Mon Oct 22 2018 - 05:43:22 EST


On Sun, Oct 21, 2018 at 09:14:24PM +0200, Milian Wolff wrote:
> When the perf script output is written to a terminal stream,
> the normal output of `perf script` would get buffered, but its
> debug output would be written directly. This made it quite hard
> to figure out where a given debug output is coming from. We can
> improve on this by flushing the output buffer after processing an
> event. To see the value, compare the following output for a
> `perf script -v` run:
>
> Before this patch:
> ```
> unwind: reg 16, val 7faf7dfdc000
> unwind: reg 7, val 7ffc80811e30
> unwind: find_proc_info dso /usr/lib/ld-2.28.so
> unwind: reg 6, val 0
> unwind: _start:ip = 0x7faf7dfdc000 (0x2000)
> unwind: reg 16, val 7faf7dfdc000
> unwind: reg 7, val 7ffc80811e30
> unwind: find_proc_info dso /usr/lib/ld-2.28.so
> unwind: reg 6, val 0
> unwind: _start:ip = 0x7faf7dfdc000 (0x2000)
> unwind: reg 16, val 7faf7dfdc000
> unwind: reg 7, val 7ffc80811e30
> unwind: find_proc_info dso /usr/lib/ld-2.28.so
> unwind: reg 6, val 0
> unwind: _start:ip = 0x7faf7dfdc000 (0x2000)
> unwind: reg 16, val 7faf7dfdc000
> unwind: reg 7, val 7ffc80811e30
> ... lots and lots of verbose debug output
> cpp-inlining 24617 90229.122036534: 1 cycles:uppp:
> 7faf7dfdc000 _start+0x0 (/usr/lib/ld-2.28.so)
>
> cpp-inlining 24617 90229.122043974: 1 cycles:uppp:
> 7faf7dfdc000 _start+0x0 (/usr/lib/ld-2.28.so)
> ...
> ```
>
> After this patch:
> ```
> ...
> unwind: reg 16, val 7faf7dfdc000
> unwind: reg 7, val 7ffc80811e30
> unwind: find_proc_info dso /usr/lib/ld-2.28.so
> unwind: reg 6, val 0
> unwind: _start:ip = 0x7faf7dfdc000 (0x2000)
> cpp-inlining 24617 90229.122036534: 1 cycles:uppp:
> 7faf7dfdc000 _start+0x0 (/usr/lib/ld-2.28.so)
>
> unwind: reg 16, val 7faf7dfdc000
> unwind: reg 7, val 7ffc80811e30
> unwind: find_proc_info dso /usr/lib/ld-2.28.so
> unwind: reg 6, val 0
> unwind: _start:ip = 0x7faf7dfdc000 (0x2000)
> cpp-inlining 24617 90229.122043974: 1 cycles:uppp:
> 7faf7dfdc000 _start+0x0 (/usr/lib/ld-2.28.so)
> ...
> ```
>
> This new output format makes it much easier to use perf script
> output for debugging purposes, e.g. to investigate broken dwarf
> unwinding.

yep, I plan to check on this ;-)

>
> Signed-off-by: Milian Wolff <milian.wolff@xxxxxxxx>
> Cc: Arnaldo Carvalho de Melo <acme@xxxxxxxxxx>
> ---
> tools/perf/builtin-script.c | 3 +++
> 1 file changed, 3 insertions(+)
>
> diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
> index bd468b90801b..ca09b7d2adb7 100644
> --- a/tools/perf/builtin-script.c
> +++ b/tools/perf/builtin-script.c
> @@ -1737,6 +1737,9 @@ static void process_event(struct perf_script *script,
>
> if (PRINT_FIELD(METRIC))
> perf_sample__fprint_metric(script, thread, evsel, sample, fp);
> +
> + if (verbose)
> + fflush(fp);

should we call fflush(NULL) to dump all the streams?

the verbose goes to stderr and fp seems to be stdout byt default

jirka