Re: [PATCH v2 10/10] tools, perf, script: Implement --graph-function

[Andi Kleen]

On Mon, Sep 03, 2018 at 09:51:28AM +0200, Jiri Olsa wrote:
> On Fri, Aug 31, 2018 at 03:02:06PM -0700, Andi Kleen wrote:
> > From: Andi Kleen <ak@xxxxxxxxxxxxxxx>
> > 
> > Add a ftrace style --graph-function argument to perf script that allows
> > to print itrace function calls only below a given function. This
> > makes it easier to find the code of interest in a large trace.
> > 
> > % perf record -e intel_pt//k -a sleep 1
> > % perf script --graph-function group_sched_in --call-trace
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])          group_sched_in
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])              __x86_indirect_thunk_rax
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])              event_sched_in.isra.107
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                  perf_event_set_state.part.71
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                      perf_event_update_time
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                  perf_pmu_disable
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                  perf_log_itrace_start
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                  __x86_indirect_thunk_rax
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                      perf_event_update_userpage
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                          calc_timer_values
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                              sched_clock_cpu
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                          __x86_indirect_thunk_rax
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                          arch_perf_update_userpage
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                              __fentry__
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                              using_native_sched_clock
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                              sched_clock_stable
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])                  perf_pmu_enable
> >             perf   900 [000] 194167.205652203: ([kernel.kallsyms])              __x86_indirect_thunk_rax
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])          group_sched_in
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])              __x86_indirect_thunk_rax
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])              event_sched_in.isra.107
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                  perf_event_set_state.part.71
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                      perf_event_update_time
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                  perf_pmu_disable
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                  perf_log_itrace_start
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                  __x86_indirect_thunk_rax
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                      perf_event_update_userpage
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                          calc_timer_values
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                              sched_clock_cpu
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                          __x86_indirect_thunk_rax
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                          arch_perf_update_userpage
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                              __fentry__
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                              using_native_sched_clock
> >          swapper     0 [001] 194167.205660693: ([kernel.kallsyms])                              sched_clock_stable
> 
> nice, but I'm also getting a lot of these lines:
> 
>  instruction trace error type 1 cpu 0 pid 0 tid 0 ip 0xffffffffb3a017a0 code 6: Trace doesn't match instruction
>  instruction trace error type 1 cpu 0 pid 0 tid 0 ip 0xffffffffb3a017a0 code 6: Trace doesn't match instruction
>  instruction trace error type 1 cpu 0 pid 0 tid 0 ip 0xffffffffb3a017a0 code 6: Trace doesn't match instruction
> 
> any idea where are those comming from?

PT decoder didn't see the same instructions as during the trace collection.

There are many reasons which can cause this, usually (but not always) some form of
self modifying code.  The Linux kernel does a lot of self modification these days,
which is a challenge for PT.

If you run the decoder as root it will decode from /proc/kcore, which helps, but
only if no jump label has changed state since the collection. 

The perf PT decoder tends to resync relatively quickly, so usually not too much
is lost.

-Andi