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

[Jiri Olsa]

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?

thanks,
jirka