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

[Milian Wolff]

On Montag, 22. Oktober 2018 12:16:18 CEST Jiri Olsa wrote:
> On Mon, Oct 22, 2018 at 12:09:22PM +0200, Milian Wolff wrote:
> > On Montag, 22. Oktober 2018 11:43:17 CEST Jiri Olsa wrote:
> > > 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
> > 
> > stderr isn't buffered, so we don't need to flush it. So personally, I
> > don't
> > see a need to dump all streams - fp should be enough? Can you maybe
> > explain
> > where it would be required to flush more buffers?
> 
> hum, did not know stderr wasn't buffer
>
> I think there's perf script feature to store the events data to
> separate files per each event.. but I guess we don't need to
> flush them.. we just need to have stdout and stderr in sync IIUC

Exactly, and that's achieved with this patch form what I see :) Or should we 
maybe instead call 

setbuf(fp, NULL);

in verbose mode?

Thanks

-- 
Milian Wolff | milian.wolff@xxxxxxxx | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

Attachment: smime.p7s
Description: S/MIME cryptographic signature