perf script: how to print user-space backtrace?

perf script: how to print user-space backtrace?

[Milian Wolff]

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

Hey all,

I recorded a perf data file using

perf record --call-graph dwarf kwrite <some large file>

when I report it I see backtraces pointing to the user space code:

perf report --stdio -g graph --no-children
    16.36%  kwrite           libKF5TextEditor.so.5.13.0     [.] 
QArrayData::data                                                                                               
                     |
                     ---QArrayData::data
                        |          
                        |--15.46%-- QTypedArrayData<unsigned short>::data

but when I run perf script, I do not see _any_ backtraces into user space. 

perf script -F comm,tid,time,event,ip,sym,trace,period
:4898  4898 17486.943365:          1 cycles: 
                  25f83a native_write_msr_safe
                  234f8a __intel_pmu_enable_all
                  235010 intel_pmu_enable_all
                  22e1ec x86_pmu_enable
                  356fb7 perf_pmu_enable.part.53
                  35824d perf_event_context_sched_in.isra.64
                  358e0b perf_event_exec
                  3e8c93 setup_new_exec
                  439a9f load_elf_binary
                  3e7f48 search_binary_handler
                  3e89cf do_execveat_common.isra.15
                  3e8e4a sys_execve
                  78b895 return_from_execve

kwrite  4898 17486.943893:          1 cycles: 
kwrite  4898 17486.944211:          1 cycles: 
...
kwrite  4898 17486.953664:     461703 cycles: 
kwrite  4898 17486.953838:     490150 cycles: 
                  78d4c0 page_fault
kwrite  4898 17486.954009:     516694 cycles: 
...
kwrite  4898 17510.765568:     766937 cycles: 
                  78979b down_write
                  39bd82 unlink_file_vma
                  3944d0 free_pgtables
                  39eef6 exit_mmap
                  275d45 mmput
                  27b514 do_exit
                  27bdfb do_group_exit
                  27be84 [unknown]
                  78b56e system_call

So it looks to me as if only kernel-space call stacks are unwound in perf 
script. Is there a magic switch that I'm missing to get user-space stacks 
unwound? Note I'm using perf 4.1.0 on a Linux 4.1.2 system.

Thanks

-- 
Milian Wolff
mail@milianw.de
http://milianw.de

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

[PATCH] perf script: Initialize callchain_param.record_mode

[Jiri Olsa]

On Wed, Jul 22, 2015 at 08:48:40PM +0200, Milian Wolff wrote:
> Hey all,
> 
> I recorded a perf data file using
> 
> perf record --call-graph dwarf kwrite <some large file>
> 
> when I report it I see backtraces pointing to the user space code:
> 
> perf report --stdio -g graph --no-children
>     16.36%  kwrite           libKF5TextEditor.so.5.13.0     [.] 
> QArrayData::data                                                                                               
>                      |
>                      ---QArrayData::data
>                         |          
>                         |--15.46%-- QTypedArrayData<unsigned short>::data
> 
> but when I run perf script, I do not see _any_ backtraces into user space. 
> 
> perf script -F comm,tid,time,event,ip,sym,trace,period
> :4898  4898 17486.943365:          1 cycles: 
>                   25f83a native_write_msr_safe
>                   234f8a __intel_pmu_enable_all
>                   235010 intel_pmu_enable_all
>                   22e1ec x86_pmu_enable
>                   356fb7 perf_pmu_enable.part.53
>                   35824d perf_event_context_sched_in.isra.64
>                   358e0b perf_event_exec
>                   3e8c93 setup_new_exec
>                   439a9f load_elf_binary
>                   3e7f48 search_binary_handler
>                   3e89cf do_execveat_common.isra.15
>                   3e8e4a sys_execve
>                   78b895 return_from_execve
> 
> kwrite  4898 17486.943893:          1 cycles: 
> kwrite  4898 17486.944211:          1 cycles: 
> ...
> kwrite  4898 17486.953664:     461703 cycles: 
> kwrite  4898 17486.953838:     490150 cycles: 
>                   78d4c0 page_fault
> kwrite  4898 17486.954009:     516694 cycles: 
> ...
> kwrite  4898 17510.765568:     766937 cycles: 
>                   78979b down_write
>                   39bd82 unlink_file_vma
>                   3944d0 free_pgtables
>                   39eef6 exit_mmap
>                   275d45 mmput
>                   27b514 do_exit
>                   27bdfb do_group_exit
>                   27be84 [unknown]
>                   78b56e system_call
> 
> So it looks to me as if only kernel-space call stacks are unwound in perf 
> script. Is there a magic switch that I'm missing to get user-space stacks 
> unwound? Note I'm using perf 4.1.0 on a Linux 4.1.2 system.

hi,
right you are.. does attached patch help?

thanks,
jirka


---
Milian Wolff reported non functional DWARF unwind under perf
script. The reason is that perf script does not properly configure
callchain_param.record_mode, which is needed by unwind code.

Stealing the code from report and leaving the place for
more initialization code in a hope we could merge it with
report__setup_sample_type one day.

Reported-by: Milian Wolff <mail@milianw.de>
Link: http://lkml.kernel.org/n/tip-vtgxy0tv3gogvomyhc2c50rm@git.kernel.org
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
---
 tools/perf/builtin-script.c | 17 +++++++++++++++++
 1 file changed, 17 insertions(+)

diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index 7b376d215e94..105332e950a9 100644
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -1561,6 +1561,22 @@ static int have_cmd(int argc, const char **argv)
 	return 0;
 }
 
+static void script__setup_sample_type(struct perf_script *script)
+{
+	struct perf_session *session = script->session;
+	u64 sample_type = perf_evlist__combined_sample_type(session->evlist);
+
+	if (symbol_conf.use_callchain || symbol_conf.cumulate_callchain) {
+		if ((sample_type & PERF_SAMPLE_REGS_USER) &&
+		    (sample_type & PERF_SAMPLE_STACK_USER))
+			callchain_param.record_mode = CALLCHAIN_DWARF;
+		else if (sample_type & PERF_SAMPLE_BRANCH_STACK)
+			callchain_param.record_mode = CALLCHAIN_LBR;
+		else
+			callchain_param.record_mode = CALLCHAIN_FP;
+	}
+}
+
 int cmd_script(int argc, const char **argv, const char *prefix __maybe_unused)
 {
 	bool show_full_info = false;
@@ -1849,6 +1865,7 @@ int cmd_script(int argc, const char **argv, const char *prefix __maybe_unused)
 		goto out_delete;
 
 	script.session = session;
+	script__setup_sample_type(&script);
 
 	session->itrace_synth_opts = &itrace_synth_opts;
 
-- 
2.4.3

Re: [PATCH] perf script: Initialize callchain_param.record_mode

[Milian Wolff]

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

On Thursday, August 13, 2015 09:17:24 AM Jiri Olsa wrote:
> On Wed, Jul 22, 2015 at 08:48:40PM +0200, Milian Wolff wrote:
> > Hey all,
> > 
> > I recorded a perf data file using
> > 
> > perf record --call-graph dwarf kwrite <some large file>
> > 
> > when I report it I see backtraces pointing to the user space code:
> > 
> > perf report --stdio -g graph --no-children
> > 
> >     16.36%  kwrite           libKF5TextEditor.so.5.13.0     [.]
> > 
> > QArrayData::data
> > 
> >                      ---QArrayData::data
> >                      
> >                         |--15.46%-- QTypedArrayData<unsigned short>::data
> > 
> > but when I run perf script, I do not see _any_ backtraces into user space.
> > 
> > perf script -F comm,tid,time,event,ip,sym,trace,period
> > 
> > :4898  4898 17486.943365:          1 cycles:
> >                   25f83a native_write_msr_safe
> >                   234f8a __intel_pmu_enable_all
> >                   235010 intel_pmu_enable_all
> >                   22e1ec x86_pmu_enable
> >                   356fb7 perf_pmu_enable.part.53
> >                   35824d perf_event_context_sched_in.isra.64
> >                   358e0b perf_event_exec
> >                   3e8c93 setup_new_exec
> >                   439a9f load_elf_binary
> >                   3e7f48 search_binary_handler
> >                   3e89cf do_execveat_common.isra.15
> >                   3e8e4a sys_execve
> >                   78b895 return_from_execve
> > 
> > kwrite  4898 17486.943893:          1 cycles:
> > kwrite  4898 17486.944211:          1 cycles:
> > ...
> > kwrite  4898 17486.953664:     461703 cycles:
> > 
> > kwrite  4898 17486.953838:     490150 cycles:
> >                   78d4c0 page_fault
> > 
> > kwrite  4898 17486.954009:     516694 cycles:
> > ...
> > 
> > kwrite  4898 17510.765568:     766937 cycles:
> >                   78979b down_write
> >                   39bd82 unlink_file_vma
> >                   3944d0 free_pgtables
> >                   39eef6 exit_mmap
> >                   275d45 mmput
> >                   27b514 do_exit
> >                   27bdfb do_group_exit
> >                   27be84 [unknown]
> >                   78b56e system_call
> > 
> > So it looks to me as if only kernel-space call stacks are unwound in perf
> > script. Is there a magic switch that I'm missing to get user-space stacks
> > unwound? Note I'm using perf 4.1.0 on a Linux 4.1.2 system.
> 
> hi,
> right you are.. does attached patch help?

<snip>

Hey Jiri,

it works a treat!

Many thanks, much appreciated.

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

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

Re: [PATCH] perf script: Initialize callchain_param.record_mode

[Arnaldo Carvalho de Melo]

Em Thu, Aug 13, 2015 at 10:53:36AM +0200, Milian Wolff escreveu:
> On Thursday, August 13, 2015 09:17:24 AM Jiri Olsa wrote:
> > right you are.. does attached patch help?
> 
> <snip>
> 
> Hey Jiri,
> 
> it works a treat!
> 
> Many thanks, much appreciated.

Adding a "Tested-by: Milian", Ok?

- Arnaldo

Re: [PATCH] perf script: Initialize callchain_param.record_mode

[Milian Wolff]

On Monday, August 17, 2015 10:47:50 AM CEST Arnaldo Carvalho de Melo wrote:
> Em Thu, Aug 13, 2015 at 10:53:36AM +0200, Milian Wolff escreveu:
> > On Thursday, August 13, 2015 09:17:24 AM Jiri Olsa wrote:
> > > right you are.. does attached patch help?
> > 
> > <snip>
> > 
> > Hey Jiri,
> > 
> > it works a treat!
> > 
> > Many thanks, much appreciated.
> 
> Adding a "Tested-by: Milian", Ok?

Sure, please go ahead.

Thanks
-- 
Milian Wolff | milian.wolff@kdab.com | Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts