* [PATCH 1/2] perf script: allow extended console debug output @ 2018-10-21 19:14 Milian Wolff 2018-10-21 19:14 ` [PATCH 2/2] perf script: flush output stream after events in verbose mode Milian Wolff ` (2 more replies) 0 siblings, 3 replies; 12+ messages in thread From: Milian Wolff @ 2018-10-21 19:14 UTC (permalink / raw) To: acme, jolsa; +Cc: Linux-kernel, linux-perf-users, 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 ^ permalink raw reply related [flat|nested] 12+ messages in thread
* [PATCH 2/2] perf script: flush output stream after events in verbose mode 2018-10-21 19:14 [PATCH 1/2] perf script: allow extended console debug output Milian Wolff @ 2018-10-21 19:14 ` Milian Wolff 2018-10-22 9:43 ` Jiri Olsa 2018-10-26 7:35 ` [tip:perf/urgent] perf script: Flush " tip-bot for Milian Wolff 2018-10-22 9:40 ` [PATCH 1/2] perf script: allow extended console debug output Jiri Olsa 2018-10-26 7:34 ` [tip:perf/urgent] perf script: Allow " tip-bot for Milian Wolff 2 siblings, 2 replies; 12+ messages in thread From: Milian Wolff @ 2018-10-21 19:14 UTC (permalink / raw) To: acme, jolsa; +Cc: Linux-kernel, linux-perf-users, 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 ^ permalink raw reply related [flat|nested] 12+ messages in thread
* Re: [PATCH 2/2] perf script: flush output stream after events in verbose mode 2018-10-21 19:14 ` [PATCH 2/2] perf script: flush output stream after events in verbose mode Milian Wolff @ 2018-10-22 9:43 ` Jiri Olsa 2018-10-22 10:09 ` Milian Wolff 2018-10-26 7:35 ` [tip:perf/urgent] perf script: Flush " tip-bot for Milian Wolff 1 sibling, 1 reply; 12+ messages in thread From: Jiri Olsa @ 2018-10-22 9:43 UTC (permalink / raw) To: Milian Wolff; +Cc: acme, jolsa, Linux-kernel, linux-perf-users 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 ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [PATCH 2/2] perf script: flush output stream after events in verbose mode 2018-10-22 9:43 ` Jiri Olsa @ 2018-10-22 10:09 ` Milian Wolff 2018-10-22 10:16 ` Jiri Olsa 0 siblings, 1 reply; 12+ messages in thread From: Milian Wolff @ 2018-10-22 10:09 UTC (permalink / raw) To: Jiri Olsa; +Cc: acme, jolsa, Linux-kernel, linux-perf-users [-- 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 --] ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [PATCH 2/2] perf script: flush output stream after events in verbose mode 2018-10-22 10:09 ` Milian Wolff @ 2018-10-22 10:16 ` Jiri Olsa 2018-10-22 10:38 ` Milian Wolff 0 siblings, 1 reply; 12+ messages in thread From: Jiri Olsa @ 2018-10-22 10:16 UTC (permalink / raw) To: Milian Wolff; +Cc: acme, jolsa, Linux-kernel, linux-perf-users 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 ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [PATCH 2/2] perf script: flush output stream after events in verbose mode 2018-10-22 10:16 ` Jiri Olsa @ 2018-10-22 10:38 ` Milian Wolff 2018-10-22 13:54 ` Jiri Olsa 0 siblings, 1 reply; 12+ messages in thread From: Milian Wolff @ 2018-10-22 10:38 UTC (permalink / raw) To: Jiri Olsa; +Cc: acme, jolsa, Linux-kernel, linux-perf-users [-- 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 --] ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [PATCH 2/2] perf script: flush output stream after events in verbose mode 2018-10-22 10:38 ` Milian Wolff @ 2018-10-22 13:54 ` Jiri Olsa 2018-10-22 17:25 ` Arnaldo Carvalho de Melo 0 siblings, 1 reply; 12+ messages in thread From: Jiri Olsa @ 2018-10-22 13:54 UTC (permalink / raw) To: Milian Wolff; +Cc: acme, jolsa, Linux-kernel, linux-perf-users 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 ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [PATCH 2/2] perf script: flush output stream after events in verbose mode 2018-10-22 13:54 ` Jiri Olsa @ 2018-10-22 17:25 ` Arnaldo Carvalho de Melo 0 siblings, 0 replies; 12+ messages in thread From: Arnaldo Carvalho de Melo @ 2018-10-22 17:25 UTC (permalink / raw) To: Jiri Olsa; +Cc: Milian Wolff, jolsa, Linux-kernel, linux-perf-users 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 ^ permalink raw reply [flat|nested] 12+ messages in thread
* [tip:perf/urgent] perf script: Flush output stream after events in verbose mode 2018-10-21 19:14 ` [PATCH 2/2] perf script: flush output stream after events in verbose mode Milian Wolff 2018-10-22 9:43 ` Jiri Olsa @ 2018-10-26 7:35 ` tip-bot for Milian Wolff 1 sibling, 0 replies; 12+ messages in thread From: tip-bot for Milian Wolff @ 2018-10-26 7:35 UTC (permalink / raw) To: linux-tip-commits Cc: acme, tglx, milian.wolff, mingo, hpa, linux-kernel, jolsa 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; ^ permalink raw reply related [flat|nested] 12+ messages in thread
* Re: [PATCH 1/2] perf script: allow extended console debug output 2018-10-21 19:14 [PATCH 1/2] perf script: allow extended console debug output Milian Wolff 2018-10-21 19:14 ` [PATCH 2/2] perf script: flush output stream after events in verbose mode Milian Wolff @ 2018-10-22 9:40 ` Jiri Olsa 2018-10-22 15:09 ` Arnaldo Carvalho de Melo 2018-10-26 7:34 ` [tip:perf/urgent] perf script: Allow " tip-bot for Milian Wolff 2 siblings, 1 reply; 12+ messages in thread From: Jiri Olsa @ 2018-10-22 9:40 UTC (permalink / raw) To: Milian Wolff; +Cc: acme, jolsa, Linux-kernel, linux-perf-users 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 ^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [PATCH 1/2] perf script: allow extended console debug output 2018-10-22 9:40 ` [PATCH 1/2] perf script: allow extended console debug output Jiri Olsa @ 2018-10-22 15:09 ` Arnaldo Carvalho de Melo 0 siblings, 0 replies; 12+ messages in thread From: Arnaldo Carvalho de Melo @ 2018-10-22 15:09 UTC (permalink / raw) To: Jiri Olsa; +Cc: Milian Wolff, jolsa, Linux-kernel, linux-perf-users 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 ^ permalink raw reply [flat|nested] 12+ messages in thread
* [tip:perf/urgent] perf script: Allow extended console debug output 2018-10-21 19:14 [PATCH 1/2] perf script: allow extended console debug output Milian Wolff 2018-10-21 19:14 ` [PATCH 2/2] perf script: flush output stream after events in verbose mode Milian Wolff 2018-10-22 9:40 ` [PATCH 1/2] perf script: allow extended console debug output Jiri Olsa @ 2018-10-26 7:34 ` tip-bot for Milian Wolff 2 siblings, 0 replies; 12+ messages in thread From: tip-bot for Milian Wolff @ 2018-10-26 7:34 UTC (permalink / raw) To: linux-tip-commits Cc: jolsa, milian.wolff, linux-kernel, acme, hpa, mingo, tglx 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) ^ permalink raw reply related [flat|nested] 12+ messages in thread
end of thread, other threads:[~2018-10-26 7:35 UTC | newest] Thread overview: 12+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2018-10-21 19:14 [PATCH 1/2] perf script: allow extended console debug output Milian Wolff 2018-10-21 19:14 ` [PATCH 2/2] perf script: flush output stream after events in verbose mode Milian Wolff 2018-10-22 9:43 ` Jiri Olsa 2018-10-22 10:09 ` Milian Wolff 2018-10-22 10:16 ` Jiri Olsa 2018-10-22 10:38 ` Milian Wolff 2018-10-22 13:54 ` Jiri Olsa 2018-10-22 17:25 ` Arnaldo Carvalho de Melo 2018-10-26 7:35 ` [tip:perf/urgent] perf script: Flush " tip-bot for Milian Wolff 2018-10-22 9:40 ` [PATCH 1/2] perf script: allow extended console debug output Jiri Olsa 2018-10-22 15:09 ` Arnaldo Carvalho de Melo 2018-10-26 7:34 ` [tip:perf/urgent] perf script: Allow " tip-bot for Milian Wolff
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).