Problem running perf using Intel-PT with snapshots

Problem running perf using Intel-PT with snapshots

[Nadav Amit]

Hello perf masters,

I am running perf with Intel PT with snapshot mode and the result makes no
sense. I tried to figure it out myself but failed.

Excluding the first data file, the rest seem messed up in various ways. The
only thing that repeatedly shows are calls to __fentry__+0x0. I would note
that ftrace is not enabled, and I turned off mitigations as I thought it
might somehow be related, but it did not help.

Here is an example for execution and output. In between I ran
`kill -SIGUSR2 [perf-pid]`. To dump some traces.

Any ideas what it might be?

Thanks,
Nadav

--

$ perf record -e intel_pt/noretcomp=1/k --kcore --timestamp -a --snapshot=e262144 --switch-output -m,64
[ perf record: dump data: Woken up 2 times ]
[ perf record: Dump perf.data.2023051804132358 ]
[ perf record: dump data: Woken up 1 times ]
[ perf record: Dump perf.data.2023051804132537 ]
[ perf record: dump data: Woken up 1 times ]
[ perf record: Dump perf.data.2023051804132689 ]
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Dump perf.data.2023051804132829 ]
[ perf record: Captured and wrote 14.330 MB perf.data.<timestamp> ]


$ sudo perf script -i  perf.data.2023051804004293

             :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff81096125 ept_page_fault+0x3f5 ([kernel.kallsyms]) => ffffffff8108f1d0 kvm_mmu_get_child_sp+0x0 ([kernel.kallsyms])
             :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff8108f1d0 kvm_mmu_get_child_sp+0x0 ([kernel.kallsyms]) => ffffffff81131190 __fentry__+0x0 ([kernel.kallsyms])
 instruction trace error type 1 time 78.287624064 cpu 6 pid -1 tid -1 ip 0xffffffff8101c4fd code 6: Trace doesn't match instruction
             :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff81296e14 futex_unlock_pi+0x184 ([kernel.kallsyms]) => ffffffff81294120 futex_cmpxchg_value_locked+0x0 ([kernel.kallsyms])
             :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff81294124 futex_cmpxchg_value_locked+0x4 ([kernel.kallsyms]) => ffffffff81131190 __fentry__+0x0 ([kernel.kallsyms])
 instruction trace error type 1 time 78.287624104 cpu 6 pid -1 tid -1 ip 0xffffffff824c7a44 code 6: Trace doesn't match instruction
             :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff812909c4 __tick_broadcast_oneshot_control+0x1d4 ([kernel.kallsyms]) => ffffffff8128f720 tick_broadcast_set_event+0x0 ([kernel.kallsyms])
             :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff8128f720 tick_broadcast_set_event+0x0 ([kernel.kallsyms]) => ffffffff81131190 __fentry__+0x0 ([kernel.kallsyms])
             :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff81296e8e futex_unlock_pi+0x1fe ([kernel.kallsyms]) => ffffffff812961d0 put_pi_state+0x0 ([kernel.kallsyms])
             :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff812961d4 put_pi_state+0x4 ([kernel.kallsyms]) => ffffffff81131190 __fentry__+0x0 ([kernel.kallsyms])
 instruction trace error type 1 time 78.287624208 cpu 6 pid -1 tid -1 ip 0xffffffff824c7a44 code 6: Trace doesn't match instruction

Re: Problem running perf using Intel-PT with snapshots

[Adrian Hunter]

On 18/05/23 07:26, Nadav Amit wrote:
> Hello perf masters,
> 
> I am running perf with Intel PT with snapshot mode and the result makes no
> sense. I tried to figure it out myself but failed.
> 
> Excluding the first data file, the rest seem messed up in various ways. The
> only thing that repeatedly shows are calls to __fentry__+0x0. I would note
> that ftrace is not enabled, and I turned off mitigations as I thought it
> might somehow be related, but it did not help.
> 
> Here is an example for execution and output. In between I ran
> `kill -SIGUSR2 [perf-pid]`. To dump some traces.
> 
> Any ideas what it might be?
> 
> Thanks,
> Nadav
> 
> --
> 
> $ perf record -e intel_pt/noretcomp=1/k --kcore --timestamp -a --snapshot=e262144 --switch-output -m,64

--switch-output does not work well with Intel PT.  Intel PT needs all of the sideband event information from all files, so decoding errors result from splitting files.

If you need separate files, consider stopping and restarting 'perf record' instead.  If you do that, you may want to look at options like -B and -N and --no-bpf-event which can affect how long it takes to stop perf record.

If you don't need separate files, you can use --time to look at time ranges within the resulting perf.data file.

> [ perf record: dump data: Woken up 2 times ]
> [ perf record: Dump perf.data.2023051804132358 ]
> [ perf record: dump data: Woken up 1 times ]
> [ perf record: Dump perf.data.2023051804132537 ]
> [ perf record: dump data: Woken up 1 times ]
> [ perf record: Dump perf.data.2023051804132689 ]
> ^C[ perf record: Woken up 1 times to write data ]
> [ perf record: Dump perf.data.2023051804132829 ]
> [ perf record: Captured and wrote 14.330 MB perf.data.<timestamp> ]
> 
> 
> $ sudo perf script -i  perf.data.2023051804004293
> 
>              :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff81096125 ept_page_fault+0x3f5 ([kernel.kallsyms]) => ffffffff8108f1d0 kvm_mmu_get_child_sp+0x0 ([kernel.kallsyms])
>              :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff8108f1d0 kvm_mmu_get_child_sp+0x0 ([kernel.kallsyms]) => ffffffff81131190 __fentry__+0x0 ([kernel.kallsyms])
>  instruction trace error type 1 time 78.287624064 cpu 6 pid -1 tid -1 ip 0xffffffff8101c4fd code 6: Trace doesn't match instruction
>              :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff81296e14 futex_unlock_pi+0x184 ([kernel.kallsyms]) => ffffffff81294120 futex_cmpxchg_value_locked+0x0 ([kernel.kallsyms])
>              :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff81294124 futex_cmpxchg_value_locked+0x4 ([kernel.kallsyms]) => ffffffff81131190 __fentry__+0x0 ([kernel.kallsyms])
>  instruction trace error type 1 time 78.287624104 cpu 6 pid -1 tid -1 ip 0xffffffff824c7a44 code 6: Trace doesn't match instruction
>              :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff812909c4 __tick_broadcast_oneshot_control+0x1d4 ([kernel.kallsyms]) => ffffffff8128f720 tick_broadcast_set_event+0x0 ([kernel.kallsyms])
>              :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff8128f720 tick_broadcast_set_event+0x0 ([kernel.kallsyms]) => ffffffff81131190 __fentry__+0x0 ([kernel.kallsyms])
>              :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff81296e8e futex_unlock_pi+0x1fe ([kernel.kallsyms]) => ffffffff812961d0 put_pi_state+0x0 ([kernel.kallsyms])
>              :-1    -1 [006]    78.287624:          1             branches:k:  ffffffff812961d4 put_pi_state+0x4 ([kernel.kallsyms]) => ffffffff81131190 __fentry__+0x0 ([kernel.kallsyms])
>  instruction trace error type 1 time 78.287624208 cpu 6 pid -1 tid -1 ip 0xffffffff824c7a44 code 6: Trace doesn't match instruction
> 

Re: Problem running perf using Intel-PT with snapshots

[Nadav Amit]

> On May 18, 2023, at 12:52 AM, Adrian Hunter <adrian.hunter@intel.com> wrote:
> 
> On 18/05/23 07:26, Nadav Amit wrote:
>> Hello perf masters,
>> 
>> I am running perf with Intel PT with snapshot mode and the result makes no
>> sense. I tried to figure it out myself but failed.
>> 
>> Excluding the first data file, the rest seem messed up in various ways. The
>> only thing that repeatedly shows are calls to __fentry__+0x0. I would note
>> that ftrace is not enabled, and I turned off mitigations as I thought it
>> might somehow be related, but it did not help.
>> 
>> Here is an example for execution and output. In between I ran
>> `kill -SIGUSR2 [perf-pid]`. To dump some traces.
>> 
>> Any ideas what it might be?
>> 
>> Thanks,
>> Nadav
>> 
>> --
>> 
>> $ perf record -e intel_pt/noretcomp=1/k --kcore --timestamp -a --snapshot=e262144 --switch-output -m,64
> 
> --switch-output does not work well with Intel PT.  Intel PT needs all of the sideband event information from all files, so decoding errors result from splitting files.
> 
> If you need separate files, consider stopping and restarting 'perf record' instead.  If you do that, you may want to look at options like -B and -N and --no-bpf-event which can affect how long it takes to stop perf record.
> 
> If you don't need separate files, you can use --time to look at time ranges within the resulting perf.data file.

Thank you Adrian. It was driving me crazy and I was sure I am somehow not
accounting for some ftrace/rethunk or some other binary rewriting event.

These ideas for workarounds should suffice.

Thanks again,
Nadav