[PATCH 1/2] perf script: allow extended console debug output

[PATCH 1/2] perf script: allow extended console debug output

[Milian Wolff]

The script tool isn't using a browser, yet use_browser
wasn't set explicitly to zero. This in turn lead to confusing
output such as:

```
$ perf script -vvv ...
...
overlapping maps in /home/milian/foobar (disable tui for more info)
...
```

Explicitly set use_browser to 0 now, which gives us the extended
debug information now in perf script as expected.

Signed-off-by: Milian Wolff <milian.wolff@kdab.com>
Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
---
 tools/perf/builtin-script.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index 4da5e32b9e03..bd468b90801b 100644
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -3417,8 +3417,10 @@ int cmd_script(int argc, const char **argv)
 		exit(-1);
 	}
 
-	if (!script_name)
+	if (!script_name) {
 		setup_pager();
+		use_browser = 0;
+	}
 
 	session = perf_session__new(&data, false, &script.tool);
 	if (session == NULL)
-- 
2.19.1

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

[Milian Wolff]

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.

Signed-off-by: Milian Wolff <milian.wolff@kdab.com>
Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
---
 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);
 }
 
 static struct scripting_ops	*scripting_ops;
-- 
2.19.1

Re: [PATCH 1/2] perf script: allow extended console debug output

[Jiri Olsa]

On Sun, Oct 21, 2018 at 09:14:23PM +0200, Milian Wolff wrote:
> The script tool isn't using a browser, yet use_browser
> wasn't set explicitly to zero. This in turn lead to confusing
> output such as:
> 
> ```
> $ perf script -vvv ...
> ...
> overlapping maps in /home/milian/foobar (disable tui for more info)
> ...
> ```
> 
> Explicitly set use_browser to 0 now, which gives us the extended
> debug information now in perf script as expected.
> 
> Signed-off-by: Milian Wolff <milian.wolff@kdab.com>
> Cc: Arnaldo Carvalho de Melo <acme@kernel.org>

Acked-by: Jiri Olsa <jolsa@redhat.com>

thanks,
jirka

> ---
>  tools/perf/builtin-script.c | 4 +++-
>  1 file changed, 3 insertions(+), 1 deletion(-)
> 
> diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
> index 4da5e32b9e03..bd468b90801b 100644
> --- a/tools/perf/builtin-script.c
> +++ b/tools/perf/builtin-script.c
> @@ -3417,8 +3417,10 @@ int cmd_script(int argc, const char **argv)
>  		exit(-1);
>  	}
>  
> -	if (!script_name)
> +	if (!script_name) {
>  		setup_pager();
> +		use_browser = 0;
> +	}
>  
>  	session = perf_session__new(&data, false, &script.tool);
>  	if (session == NULL)
> -- 
> 2.19.1

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

[Jiri Olsa]

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@kdab.com>
> Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
> ---
>  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

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

[Milian Wolff]

[-- Attachment #1: Type: text/plain, Size: 3660 bytes --]

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@kdab.com>
> > Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
> > ---
> > 
> >  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?

Thanks

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

[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 3826 bytes --]

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

[Jiri Olsa]

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@kdab.com>
> > > Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
> > > ---
> > > 
> > >  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

jirka

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

[Milian Wolff]

[-- Attachment #1: Type: text/plain, Size: 4564 bytes --]

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@kdab.com>
> > > > Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
> > > > ---
> > > > 
> > > >  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@kdab.com | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 3826 bytes --]

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

[Jiri Olsa]

On Mon, Oct 22, 2018 at 12:38:57PM +0200, Milian Wolff wrote:

SNIP

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

I think your solution is ok

Acked-by: Jiri Olsa <jolsa@redhat.com>

thanks,
jirka

Re: [PATCH 1/2] perf script: allow extended console debug output

[Arnaldo Carvalho de Melo]

Em Mon, Oct 22, 2018 at 11:40:33AM +0200, Jiri Olsa escreveu:
> On Sun, Oct 21, 2018 at 09:14:23PM +0200, Milian Wolff wrote:
> > The script tool isn't using a browser, yet use_browser
> > wasn't set explicitly to zero. This in turn lead to confusing
> > output such as:
> > 
> > ```
> > $ perf script -vvv ...
> > ...
> > overlapping maps in /home/milian/foobar (disable tui for more info)
> > ...
> > ```
> > 
> > Explicitly set use_browser to 0 now, which gives us the extended
> > debug information now in perf script as expected.
> > 
> > Signed-off-by: Milian Wolff <milian.wolff@kdab.com>
> > Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
> 
> Acked-by: Jiri Olsa <jolsa@redhat.com>

Thanks, applied.

- Arnaldo

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

[Arnaldo Carvalho de Melo]

Em Mon, Oct 22, 2018 at 03:54:30PM +0200, Jiri Olsa escreveu:
> On Mon, Oct 22, 2018 at 12:38:57PM +0200, Milian Wolff wrote:
> 
> SNIP
> 
> > > > > > 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?
> 
> I think your solution is ok
> 
> Acked-by: Jiri Olsa <jolsa@redhat.com>

Thanks, applied.

- Arnaldo

[tip:perf/urgent] perf script: Allow extended console debug output

[tip-bot for Milian Wolff]

Commit-ID:  c1c9b9695cc8868048f45c7e2559f65bc0be7382
Gitweb:     https://git.kernel.org/tip/c1c9b9695cc8868048f45c7e2559f65bc0be7382
Author:     Milian Wolff <milian.wolff@kdab.com>
AuthorDate: Sun, 21 Oct 2018 21:14:23 +0200
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Mon, 22 Oct 2018 12:37:53 -0300

perf script: Allow extended console debug output

The script tool isn't using a browser, yet use_browser wasn't set
explicitly to zero. This in turn lead to confusing output such as:

  ```
  $ perf script -vvv ...
  ...
  overlapping maps in /home/milian/foobar (disable tui for more info)
  ...
  ```

Explicitly set use_browser to 0 now, which gives us the extended
debug information now in perf script as expected.

Signed-off-by: Milian Wolff <milian.wolff@kdab.com>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Link: http://lkml.kernel.org/r/20181021191424.16183-1-milian.wolff@kdab.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-script.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index 4da5e32b9e03..bd468b90801b 100644
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -3417,8 +3417,10 @@ int cmd_script(int argc, const char **argv)
 		exit(-1);
 	}
 
-	if (!script_name)
+	if (!script_name) {
 		setup_pager();
+		use_browser = 0;
+	}
 
 	session = perf_session__new(&data, false, &script.tool);
 	if (session == NULL)

[tip:perf/urgent] perf script: Flush output stream after events in verbose mode

[tip-bot for Milian Wolff]

Commit-ID:  7ee40678af935fb489b0c6cf0f75808175214cd7
Gitweb:     https://git.kernel.org/tip/7ee40678af935fb489b0c6cf0f75808175214cd7
Author:     Milian Wolff <milian.wolff@kdab.com>
AuthorDate: Sun, 21 Oct 2018 21:14:24 +0200
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Mon, 22 Oct 2018 14:27:11 -0300

perf script: Flush output stream after events in verbose mode

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.

Signed-off-by: Milian Wolff <milian.wolff@kdab.com>
Acked-by: Jiri Olsa <jolsa@kernel.org>
Link: http://lkml.kernel.org/r/20181021191424.16183-2-milian.wolff@kdab.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 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);
 }
 
 static struct scripting_ops	*scripting_ops;