Re: [PATCH] perf arm-spe: Fix incorrect sample timestamp in perf script
From: Yang Jihong
Date: Sun Jun 27 2021 - 23:45:19 EST
Hello Leo,
On 2021/6/28 9:49, Leo Yan wrote:
Hi Jihong,
On Sat, Jun 26, 2021 at 11:21:15AM +0800, Yang Jihong wrote:
When use perf script to parse ARM SPE data, sample timestamp does not match
the timestamp stored in the AUX buffer, arm_spe_prep_sample function set
"samlpe->time = speq->timestamp", "speq->timestamp" is the timestamp of first
packet in auxtrace buffer. As a result, the time of all samples in a auxtrace
buffer uses the same timestamp.
Could you confirm if the patch set [1] can fix your issue?
After I apply this patch set, and verify it as follows:
# ./perf/perf record -e arm_spe_0/ts_enable=1,branch_filter=1/ ls
accounting bootconfig build debugging elf.s firmware hv
include kvm leds Makefile objtool pcmcia perf.data
scripts testing time usb vm
arch bpf cgroup edid firewire gpio iio
io_uring laptop lib memory-model pci perf power spi
thermal tracing virtio wmi
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.031 MB perf.data ]
# ./perf/perf script --ns
ls 23104 [030] 314938.859071370: 1
branch-miss: ffffb7ee2a20e100 __pi_memcpy+0x80
([kernel.kallsyms])
ls 23104 [030] 314938.859753820: 1
branch-miss: ffffb7ee29f360e0 __split_vma+0x110
([kernel.kallsyms])
ls 23104 [030] 314938.859820430: 1
branch-miss: fffe85dd87e0 [unknown]
(/usr/lib64/ld-2.28.so)
ls 23104 [030] 314938.859941110: 1
branch-miss: fffe85dd7a28 [unknown]
(/usr/lib64/ld-2.28.so)
ls 23104 [030] 314938.859948890: 1
branch-miss: fffe85dd7a28 [unknown]
(/usr/lib64/ld-2.28.so)
ls 23104 [030] 314938.859953610: 1
branch-miss: fffe85dc8f58 [unknown]
(/usr/lib64/ld-2.28.so)
ls 23104 [030] 314938.859955730: 1
branch-miss: ffffb7ee2a12856c common_mmap.part.23+0x34
([kernel.kallsyms])
ls 23104 [030] 314938.860059900: 1
branch-miss: fffe85dc8f58 [unknown]
(/usr/lib64/ld-2.28.so)
ls 23104 [030] 314938.860095470: 1
branch-miss: fffe85dc8f58 [unknown]
(/usr/lib64/ld-2.28.so)
ls 23104 [030] 314938.860105460: 1
branch-miss: fffe85dc8f58 [unknown]
(/usr/lib64/ld-2.28.so)
ls 23104 [030] 314938.860111870: 1
branch-miss: fffe85dd7a20 [unknown]
(/usr/lib64/ld-2.28.so)
ls 23104 [030] 314938.860237310: 1
branch-miss: fffe85bc8e00 [unknown]
(/usr/lib64/libc-2.28.so)
ls 23104 [030] 314938.860419000: 1
branch-miss: fffe85bd4638 __strcoll_l+0xc58
(/usr/lib64/libc-2.28.so)
ls 23104 [030] 314938.860455790: 1
branch-miss: ffffb7ee2a20e10c __pi_memcpy+0x8c
([kernel.kallsyms])
ls 23104 [030] 314938.860473730: 1
branch-miss: ffffb7ee29d0af50 __queue_work+0x1a8
([kernel.kallsyms])
ls 23104 [030] 314938.860485020: 1
branch-miss: ffffb7ee2a20e0c0 __pi_memcpy+0x40
([kernel.kallsyms])
ls 23104 [030] 314938.860533380: 1
branch-miss: ffffb7ee29f39158 tlb_flush+0x30
([kernel.kallsyms])
# ./perf/perf script -D
[...]
. 00000a7c: b0 00 e1 20 2a ee b7 ff c0 PC
0xffb7ee2a20e100 el2 ns=1
. 00000a85: 99 02 00 LAT 2 ISSUE
. 00000a88: 98 03 00 LAT 3 TOT
. 00000a8b: 52 c2 00 EV RETIRED
NOT-TAKEN MISPRED
. 00000a8e: 4a 01 B COND
. 00000a90: b1 04 e1 20 2a ee b7 ff c0 TGT
0xffb7ee2a20e104 el2 ns=1
. 00000a99: 00 00 00 00 00 00 PAD
. 00000a9f: 71 3f e9 51 b9 a9 1c 00 00 TS
31515284203839
[...]
. 000018c0: b0 e0 60 f3 29 ee b7 ff c0 PC
0xffb7ee29f360e0 el2 ns=1
. 000018c9: 99 02 00 LAT 2 ISSUE
. 000018cc: 98 03 00 LAT 3 TOT
. 000018cf: 52 82 00 EV RETIRED
MISPRED
. 000018d2: 4a 01 B COND
. 000018d4: b1 68 61 f3 29 ee b7 ff c0 TGT
0xffb7ee29f36168 el2 ns=1
. 000018dd: 00 00 00 00 00 00 PAD
. 000018e3: 71 d4 f3 52 b9 a9 1c 00 00 TS
31515284272084
[...]
. 000019f4: b0 e0 87 dd 85 fe ff 00 80 PC
0xfffe85dd87e0 el0 ns=1
. 000019fd: 99 02 00 LAT 2 ISSUE
. 00001a00: 98 03 00 LAT 3 TOT
. 00001a03: 52 c2 00 EV RETIRED
NOT-TAKEN MISPRED
. 00001a06: 4a 01 B COND
. 00001a08: b1 e4 87 dd 85 fe ff 00 80 TGT
0xfffe85dd87e4 el0 ns=1
. 00001a11: 00 00 00 00 00 00 PAD
. 00001a17: 71 d9 0d 53 b9 a9 1c 00 00 TS
31515284278745
[...]
. 00001f48: b0 28 7a dd 85 fe ff 00 80 PC
0xfffe85dd7a28 el0 ns=1
. 00001f51: 99 07 00 LAT 7 ISSUE
. 00001f54: 98 08 00 LAT 8 TOT
. 00001f57: 52 c2 00 EV RETIRED
NOT-TAKEN MISPRED
. 00001f5a: 4a 01 B COND
. 00001f5c: b1 2c 7a dd 85 fe ff 00 80 TGT
0xfffe85dd7a2c el0 ns=1
. 00001f65: 00 00 00 00 00 00 PAD
. 00001f6b: 71 fd 3c 53 b9 a9 1c 00 00 TS
31515284290813
[...]
. 00001fcc: b0 28 7a dd 85 fe ff 00 80 PC
0xfffe85dd7a28 el0 ns=1
. 00001fd5: 99 08 00 LAT 8 ISSUE
. 00001fd8: 98 09 00 LAT 9 TOT
. 00001fdb: 52 82 00 EV RETIRED
MISPRED
. 00001fde: 4a 01 B COND
. 00001fe0: b1 10 7a dd 85 fe ff 00 80 TGT
0xfffe85dd7a10 el0 ns=1
. 00001fe9: 00 00 00 00 00 00 PAD
. 00001fef: 71 07 40 53 b9 a9 1c 00 00 TS
31515284291591
[...]
. 00002050: b0 58 8f dc 85 fe ff 00 80 PC
0xfffe85dc8f58 el0 ns=1
. 00002059: 99 22 00 LAT 34 ISSUE
. 0000205c: 98 23 00 LAT 35 TOT
. 0000205f: 52 82 00 EV RETIRED
MISPRED
. 00002062: 4a 01 B COND
. 00002064: b1 40 8f dc 85 fe ff 00 80 TGT
0xfffe85dc8f40 el0 ns=1
. 0000206d: 00 00 00 00 00 00 PAD
. 00002073: 71 df 41 53 b9 a9 1c 00 00 TS
31515284292063
[...]
The timestamp does not match. Each timestamp has a difference of
213.98296702 seconds. Is the command I executed wrong?
|symbol_address|perf script| perf script -D|
|ffffb7ee2a20e100|314938.859071370|31515284203839|
|ffffb7ee29f360e0|314938.859753820|31515284272084|
|fffe85dd87e0|314938.859820430|31515284278745|
|fffe85dd7a28|314938.859941110|31515284290813|
|fffe85dd7a28|314938.859948890|31515284291591|
|fffe85dc8f58|314938.859953610|31515284292063|
Thanks,
Jihong
Thanks,
Leo
[1] https://lore.kernel.org/patchwork/cover/1431624/
.