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.
Before:
# perf record -e arm_spe_0/ts_enable=1,branch_filter=1/ ls
perf.data
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.029 MB perf.data ]
[ perf record: Captured and wrote 1.429 MB perf.data ]
# perf script -D
[...]
0 0 0x31b0 [0x30]: PERF_RECORD_AUXTRACE size: 0x44f0 offset: 0 ref: 0x3a50d idx: 5 tid: 107690 cpu: 5
.
[...]
. 00000108: b0 00 82 f3 29 ee b7 ff c0 PC 0xffb7ee29f38200 el2 ns=1
. 00000111: 99 02 00 LAT 2 ISSUE
. 00000114: 98 03 00 LAT 3 TOT
. 00000117: 52 82 00 EV RETIRED MISPRED
. 0000011a: 4a 01 B COND
. 0000011c: b1 24 82 f3 29 ee b7 ff c0 TGT 0xffb7ee29f38224 el2 ns=1
. 00000125: 00 00 00 00 00 00 PAD
. 0000012b: 71 32 a0 d6 78 3f 07 00 00 TS 7969191665714
[...]
. 0000018c: b0 0c e1 20 2a ee b7 ff c0 PC 0xffb7ee2a20e10c el2 ns=1
. 00000195: 99 02 00 LAT 2 ISSUE
. 00000198: 98 03 00 LAT 3 TOT
. 0000019b: 52 c2 00 EV RETIRED NOT-TAKEN MISPRED
. 0000019e: 4a 01 B COND
. 000001a0: b1 10 e1 20 2a ee b7 ff c0 TGT 0xffb7ee2a20e110 el2 ns=1
. 000001a9: 00 00 00 00 00 00 PAD
. 000001af: 71 bc a4 d6 78 3f 07 00 00 TS 7969191666876
[...]
. 00000ef4: b0 44 3a fe 29 ee b7 ff c0 PC 0xffb7ee29fe3a44 el2 ns=1
. 00000efd: 99 07 00 LAT 7 ISSUE
. 00000f00: 98 08 00 LAT 8 TOT
. 00000f03: 52 82 00 EV RETIRED MISPRED
. 00000f06: 4a 01 B COND
. 00000f08: b1 20 3a fe 29 ee b7 ff c0 TGT 0xffb7ee29fe3a20 el2 ns=1
. 00000f11: 00 00 00 00 00 00 PAD
. 00000f17: 71 1e 06 d7 78 3f 07 00 00 TS 7969191691806
[...]
. 00000f20: b0 fc 87 fc 29 ee b7 ff c0 PC 0xffb7ee29fc87fc el2 ns=1
. 00000f29: 99 06 00 LAT 6 ISSUE
. 00000f2c: 98 07 00 LAT 7 TOT
. 00000f2f: 52 82 00 EV RETIRED MISPRED
. 00000f32: 4a 01 B COND
. 00000f34: b1 08 88 fc 29 ee b7 ff c0 TGT 0xffb7ee29fc8808 el2 ns=1
. 00000f3d: 00 00 00 00 00 00 PAD
. 00000f43: 71 e1 07 d7 78 3f 07 00 00 TS 7969191692257
[...]
. 00000ffc: b0 18 24 fd 29 ee b7 ff c0 PC 0xffb7ee29fd2418 el2 ns=1
. 00001005: 99 02 00 LAT 2 ISSUE
. 00001008: 98 03 00 LAT 3 TOT
. 0000100b: 52 c2 00 EV RETIRED NOT-TAKEN MISPRED
. 0000100e: 4a 01 B COND
. 00001010: b1 1c 24 fd 29 ee b7 ff c0 TGT 0xffb7ee29fd241c el2 ns=1
. 00001019: 00 00 00 00 00 00 PAD
. 0000101f: 71 e9 11 d7 78 3f 07 00 00 TS 7969191694825
[...]
. 00001188: b0 c0 e0 20 2a ee b7 ff c0 PC 0xffb7ee2a20e0c0 el2 ns=1
. 00001191: 99 02 00 LAT 2 ISSUE
. 00001194: 98 03 00 LAT 3 TOT
. 00001197: 52 c2 00 EV RETIRED NOT-TAKEN MISPRED
. 0000119a: 4a 01 B COND
. 0000119c: b1 c4 e0 20 2a ee b7 ff c0 TGT 0xffb7ee2a20e0c4 el2 ns=1
. 000011a5: 00 00 00 00 00 00 PAD
. 000011ab: 71 40 1e d7 78 3f 07 00 00 TS 7969191697984
[...]
. 00001c5c: b0 2c 8c fd 6c fd ff 00 80 PC 0xfffd6cfd8c2c el0 ns=1
. 00001c65: 99 02 00 LAT 2 ISSUE
. 00001c68: 98 03 00 LAT 3 TOT
. 00001c6b: 52 c2 00 EV RETIRED NOT-TAKEN MISPRED
. 00001c6e: 4a 01 B COND
. 00001c70: b1 30 8c fd 6c fd ff 00 80 TGT 0xfffd6cfd8c30 el0 ns=1
. 00001c79: 00 00 00 00 00 00 PAD
. 00001c7f: 71 36 03 d8 78 3f 07 00 00 TS 7969191756598
[...]
. 00001e40: b0 00 0b de 6c fd ff 00 80 PC 0xfffd6cde0b00 el0 ns=1
. 00001e49: 99 02 00 LAT 2 ISSUE
. 00001e4c: 98 03 00 LAT 3 TOT
. 00001e4f: 52 82 00 EV RETIRED MISPRED
. 00001e52: 4a 01 B COND
. 00001e54: b1 50 0b de 6c fd ff 00 80 TGT 0xfffd6cde0b50 el0 ns=1
. 00001e5d: 00 00 00 00 00 00 PAD
. 00001e63: 71 0f 1d d8 78 3f 07 00 00 TS 7969191763215
[...]
. 00002234: b0 e0 60 f3 29 ee b7 ff c0 PC 0xffb7ee29f360e0 el2 ns=1
. 0000223d: 99 02 00 LAT 2 ISSUE
. 00002240: 98 03 00 LAT 3 TOT
. 00002243: 52 82 00 EV RETIRED MISPRED
. 00002246: 4a 01 B COND
. 00002248: b1 68 61 f3 29 ee b7 ff c0 TGT 0xffb7ee29f36168 el2 ns=1
. 00002251: 00 00 00 00 00 00 PAD
. 00002257: 71 7d 27 d8 78 3f 07 00 00 TS 7969191765885
[...]
. 0000228c: b0 60 b0 fd 6c fd ff 00 80 PC 0xfffd6cfdb060 el0 ns=1
. 00002295: 99 0e 00 LAT 14 ISSUE
. 00002298: 98 0f 00 LAT 15 TOT
. 0000229b: 52 c2 00 EV RETIRED NOT-TAKEN MISPRED
. 0000229e: 4a 01 B COND
. 000022a0: b1 64 b0 fd 6c fd ff 00 80 TGT 0xfffd6cfdb064 el0 ns=1
. 000022a9: 00 00 00 00 00 00 PAD
. 000022af: 71 af 2b d8 78 3f 07 00 00 TS 7969191766959
[...]
. 00002af8: b0 28 7a fe 6c fd ff 00 80 PC 0xfffd6cfe7a28 el0 ns=1
. 00002b01: 99 03 00 LAT 3 ISSUE
. 00002b04: 98 04 00 LAT 4 TOT
. 00002b07: 52 c2 00 EV RETIRED NOT-TAKEN MISPRED
. 00002b0a: 4a 01 B COND
. 00002b0c: b1 2c 7a fe 6c fd ff 00 80 TGT 0xfffd6cfe7a2c el0 ns=1
. 00002b15: 00 00 00 00 00 00 PAD
. 00002b1b: 71 95 50 d8 78 3f 07 00 00 TS 7969191776405
[...]
. 00002b50: b0 28 7a fe 6c fd ff 00 80 PC 0xfffd6cfe7a28 el0 ns=1
. 00002b59: 99 05 00 LAT 5 ISSUE
. 00002b5c: 98 06 00 LAT 6 TOT
. 00002b5f: 52 02 00 EV RETIRED
. 00002b62: 4a 01 B COND
. 00002b64: b1 10 7a fe 6c fd ff 00 80 TGT 0xfffd6cfe7a10 el0 ns=1
. 00002b6d: 00 00 00 00 00 00 PAD
. 00002b73: 71 f3 51 d8 78 3f 07 00 00 TS 7969191776755
[...]
. 00003498: b0 30 29 e7 6c fd ff 00 80 PC 0xfffd6ce72930 el0 ns=1
. 000034a1: 99 0b 00 LAT 11 ISSUE
. 000034a4: 98 0c 00 LAT 12 TOT
. 000034a7: 52 42 00 EV RETIRED NOT-TAKEN
. 000034aa: 4a 01 B COND
. 000034ac: b1 34 29 e7 6c fd ff 00 80 TGT 0xfffd6ce72934 el0 ns=1
. 000034b5: 00 00 00 00 00 00 PAD
. 000034bb: 71 ea 86 d8 78 3f 07 00 00 TS 7969191790314
[...]
. 00003ba4: b0 78 95 fe 29 ee b7 ff c0 PC 0xffb7ee29fe9578 el2 ns=1
. 00003bad: 99 02 00 LAT 2 ISSUE
. 00003bb0: 98 03 00 LAT 3 TOT
. 00003bb3: 52 82 00 EV RETIRED MISPRED
. 00003bb6: 4a 01 B COND
. 00003bb8: b1 2c 95 fe 29 ee b7 ff c0 TGT 0xffb7ee29fe952c el2 ns=1
. 00003bc1: 00 00 00 00 00 00 PAD
. 00003bc7: 71 3a b0 d8 78 3f 07 00 00 TS 7969191800890
[...]
. 00003d04: b0 14 c0 d8 6c fd ff 00 80 PC 0xfffd6cd8c014 el0 ns=1
. 00003d0d: 99 02 00 LAT 2 ISSUE
. 00003d10: 98 03 00 LAT 3 TOT
. 00003d13: 52 82 00 EV RETIRED MISPRED
. 00003d16: 4a 01 B COND
. 00003d18: b1 e8 c0 d8 6c fd ff 00 80 TGT 0xfffd6cd8c0e8 el0 ns=1
. 00003d21: 00 00 00 00 00 00 PAD
. 00003d27: 71 51 ba d8 78 3f 07 00 00 TS 7969191803473
[...]
. 00003ff0: b0 60 0e dd 6c fd ff 00 80 PC 0xfffd6cdd0e60 el0 ns=1
. 00003ff9: 99 03 00 LAT 3 ISSUE
. 00003ffc: 98 04 00 LAT 4 TOT
. 00003fff: 52 82 00 EV RETIRED MISPRED
. 00004002: 4a 01 B COND
. 00004004: b1 d8 0e dd 6c fd ff 00 80 TGT 0xfffd6cdd0ed8 el0 ns=1
. 0000400d: 00 00 00 00 00 00 PAD
. 00004013: 71 e0 d2 d8 78 3f 07 00 00 TS 7969191809760
[...]
# perf script
ls 107690 [005] 7969.191661: 1 branch-miss: ffffb7ee29f38200 do_mmap+0x60 ([kernel.kallsyms])
ls 107690 [005] 7969.191661: 1 branch-miss: ffffb7ee2a20e10c __pi_memcpy+0x8c ([kernel.kallsyms])
ls 107690 [005] 7969.191661: 1 branch-miss: ffffb7ee29fe3a44 __d_lookup_rcu+0xe4 ([kernel.kallsyms])
ls 107690 [005] 7969.191661: 1 branch-miss: ffffb7ee29fc87fc cp_new_stat+0x11c ([kernel.kallsyms])
ls 107690 [005] 7969.191661: 1 branch-miss: ffffb7ee29fd2418 link_path_walk.part.35+0x198 ([kernel.kallsyms])
ls 107690 [005] 7969.191661: 1 branch-miss: ffffb7ee2a20e0c0 __pi_memcpy+0x40 ([kernel.kallsyms])
ls 107690 [005] 7969.191661: 1 branch-miss: fffd6cfd8c2c [unknown] (/usr/lib64/ld-2.28.so)
ls 107690 [005] 7969.191661: 1 branch-miss: fffd6cde0b00 memset+0x18 (/usr/lib64/libc-2.28.so)
ls 107690 [005] 7969.191661: 1 branch-miss: ffffb7ee29f360e0 __split_vma+0x110 ([kernel.kallsyms])
ls 107690 [005] 7969.191661: 1 branch-miss: fffd6cfdb060 [unknown] (/usr/lib64/ld-2.28.so)
ls 107690 [005] 7969.191661: 1 branch-miss: fffd6cfe7a28 [unknown] (/usr/lib64/ld-2.28.so)
ls 107690 [005] 7969.191661: 1 branch-miss: fffd6cfe7a28 [unknown] (/usr/lib64/ld-2.28.so)
ls 107690 [005] 7969.191661: 1 branch-miss: fffd6ce72930 _dl_addr+0x110 (/usr/lib64/libc-2.28.so)
ls 107690 [005] 7969.191661: 1 branch-miss: ffffb7ee29fe9578 atime_needs_update+0x120 ([kernel.kallsyms])
ls 107690 [005] 7969.191661: 1 branch-miss: fffd6cd8c014 [unknown] (/usr/lib64/libc-2.28.so)
ls 107690 [005] 7969.191661: 1 branch-miss: fffd6cdd0e60 [unknown] (/usr/lib64/libc-2.28.so)
Solution:
Set "sample->time" to the timestamp corresponding to each packet in auxtrace.
After:
# perf script
ls 107690 [005] 7969.191665: 1 branch-miss: ffffb7ee29f38200 do_mmap+0x60 ([kernel.kallsyms])
ls 107690 [005] 7969.191666: 1 branch-miss: ffffb7ee2a20e10c __pi_memcpy+0x8c ([kernel.kallsyms])
ls 107690 [005] 7969.191691: 1 branch-miss: ffffb7ee29fe3a44 __d_lookup_rcu+0xe4 ([kernel.kallsyms])
ls 107690 [005] 7969.191692: 1 branch-miss: ffffb7ee29fc87fc cp_new_stat+0x11c ([kernel.kallsyms])
ls 107690 [005] 7969.191694: 1 branch-miss: ffffb7ee29fd2418 link_path_walk.part.35+0x198 ([kernel.kallsyms])
ls 107690 [005] 7969.191697: 1 branch-miss: ffffb7ee2a20e0c0 __pi_memcpy+0x40 ([kernel.kallsyms])
ls 107690 [005] 7969.191756: 1 branch-miss: fffd6cfd8c2c [unknown] (/usr/lib64/ld-2.28.so)
ls 107690 [005] 7969.191763: 1 branch-miss: fffd6cde0b00 memset+0x18 (/usr/lib64/libc-2.28.so)
ls 107690 [005] 7969.191765: 1 branch-miss: ffffb7ee29f360e0 __split_vma+0x110 ([kernel.kallsyms])
ls 107690 [005] 7969.191766: 1 branch-miss: fffd6cfdb060 [unknown] (/usr/lib64/ld-2.28.so)
ls 107690 [005] 7969.191776: 1 branch-miss: fffd6cfe7a28 [unknown] (/usr/lib64/ld-2.28.so)
ls 107690 [005] 7969.191782: 1 branch-miss: fffd6cfe7a28 [unknown] (/usr/lib64/ld-2.28.so)
ls 107690 [005] 7969.191791: 1 branch-miss: fffd6ce72930 _dl_addr+0x110 (/usr/lib64/libc-2.28.so)
ls 107690 [005] 7969.191800: 1 branch-miss: ffffb7ee29fe9578 atime_needs_update+0x120 ([kernel.kallsyms])
ls 107690 [005] 7969.191803: 1 branch-miss: fffd6cd8c014 [unknown] (/usr/lib64/libc-2.28.so)
ls 107690 [005] 7969.191809: 1 branch-miss: fffd6cdd0e60 [unknown] (/usr/lib64/libc-2.28.so)
Signed-off-by: Yang Jihong <[email protected]>
---
tools/perf/util/arm-spe.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/tools/perf/util/arm-spe.c b/tools/perf/util/arm-spe.c
index 2539d4baec44..c4550cc1b248 100644
--- a/tools/perf/util/arm-spe.c
+++ b/tools/perf/util/arm-spe.c
@@ -231,7 +231,7 @@ static void arm_spe_prep_sample(struct arm_spe *spe,
struct arm_spe_record *record = &speq->decoder->record;
if (!spe->timeless_decoding)
- sample->time = speq->timestamp;
+ sample->time = record->timestamp;
sample->ip = record->from_ip;
sample->cpumode = arm_spe_cpumode(spe, sample->ip);
--
2.30.GIT
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?
Thanks,
Leo
[1] https://lore.kernel.org/patchwork/cover/1431624/
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/
> .
>
On Mon, Jun 28, 2021 at 11:45:07AM +0800, Yang Jihong wrote:
[...]
> The timestamp does not match. Each timestamp has a difference of
> 213.98296702 seconds. Is the command I executed wrong?
I don't understand what's your meaning "a difference of 213.98296702
seconds".
But let me give an explaination with your below examples. You could
the command "perf script" outputs the timestamp 314938.859071370 which
is the kernel's timestamp, if using the command "perf script -D", it
outputs the value 31515284203839 which is the Arch timer's raw counter
value.
In theory, the arch timer's counter is enabled at the very early
time before kernel's booting (e.g. bootloaders, UEFI, etc...). So for
the kernel's timestamp, it should calibrate the timestamp and reduce
the offset prior to the kernel's booting. I think this is the reason
why you observed 213.98296702 seconds difference (if compared with
your own patch?)
If still see any issue, please let me know. Thanks a lot for the
testing!
Leo
> |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|
Hello Leo,
On 2021/6/28 12:07, Leo Yan wrote:
> On Mon, Jun 28, 2021 at 11:45:07AM +0800, Yang Jihong wrote:
>
> [...]
>
>> The timestamp does not match. Each timestamp has a difference of
>> 213.98296702 seconds. Is the command I executed wrong?
>
> I don't understand what's your meaning "a difference of 213.98296702
> seconds".
>
> But let me give an explaination with your below examples. You could
> the command "perf script" outputs the timestamp 314938.859071370 which
> is the kernel's timestamp, if using the command "perf script -D", it
> outputs the value 31515284203839 which is the Arch timer's raw counter
> value.
>
> In theory, the arch timer's counter is enabled at the very early
> time before kernel's booting (e.g. bootloaders, UEFI, etc...). So for
> the kernel's timestamp, it should calibrate the timestamp and reduce
> the offset prior to the kernel's booting. I think this is the reason
> why you observed 213.98296702 seconds difference (if compared with
> your own patch?)
>
> If still see any issue, please let me know. Thanks a lot for the
> testing!
>
Thanks for the very detailed explanation.
To keep the correct relative time sequence between events in SPE and
other events, we should use kernel timestamp instead of arch time.
Therefore, we need to calibrate the time. Is this correct?
Thanks,
Jihong.
> Leo
>
>> |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|
> .
>
On Mon, Jun 28, 2021 at 02:30:56PM +0800, Yang Jihong wrote:
> Hello Leo,
>
> On 2021/6/28 12:07, Leo Yan wrote:
> > On Mon, Jun 28, 2021 at 11:45:07AM +0800, Yang Jihong wrote:
> >
> > [...]
> >
> > > The timestamp does not match. Each timestamp has a difference of
> > > 213.98296702 seconds. Is the command I executed wrong?
> >
> > I don't understand what's your meaning "a difference of 213.98296702
> > seconds".
> >
> > But let me give an explaination with your below examples. You could
> > the command "perf script" outputs the timestamp 314938.859071370 which
> > is the kernel's timestamp, if using the command "perf script -D", it
> > outputs the value 31515284203839 which is the Arch timer's raw counter
> > value.
> >
> > In theory, the arch timer's counter is enabled at the very early
> > time before kernel's booting (e.g. bootloaders, UEFI, etc...). So for
> > the kernel's timestamp, it should calibrate the timestamp and reduce
> > the offset prior to the kernel's booting. I think this is the reason
> > why you observed 213.98296702 seconds difference (if compared with
> > your own patch?)
> >
> > If still see any issue, please let me know. Thanks a lot for the
> > testing!
> >
> Thanks for the very detailed explanation.
> To keep the correct relative time sequence between events in SPE and other
> events, we should use kernel timestamp instead of arch time. Therefore, we
> need to calibrate the time. Is this correct?
Yes, correct!
Hello Leo,
On 2021/6/28 15:29, Leo Yan wrote:
> On Mon, Jun 28, 2021 at 02:30:56PM +0800, Yang Jihong wrote:
>> Hello Leo,
>>
>> On 2021/6/28 12:07, Leo Yan wrote:
>>> On Mon, Jun 28, 2021 at 11:45:07AM +0800, Yang Jihong wrote:
>>>
>>> [...]
>>>
>>>> The timestamp does not match. Each timestamp has a difference of
>>>> 213.98296702 seconds. Is the command I executed wrong?
>>>
>>> I don't understand what's your meaning "a difference of 213.98296702
>>> seconds".
>>>
>>> But let me give an explaination with your below examples. You could
>>> the command "perf script" outputs the timestamp 314938.859071370 which
>>> is the kernel's timestamp, if using the command "perf script -D", it
>>> outputs the value 31515284203839 which is the Arch timer's raw counter
>>> value.
>>>
>>> In theory, the arch timer's counter is enabled at the very early
>>> time before kernel's booting (e.g. bootloaders, UEFI, etc...). So for
>>> the kernel's timestamp, it should calibrate the timestamp and reduce
>>> the offset prior to the kernel's booting. I think this is the reason
>>> why you observed 213.98296702 seconds difference (if compared with
>>> your own patch?)
>>>
>>> If still see any issue, please let me know. Thanks a lot for the
>>> testing!
>>>
>> Thanks for the very detailed explanation.
>> To keep the correct relative time sequence between events in SPE and other
>> events, we should use kernel timestamp instead of arch time. Therefore, we
>> need to calibrate the time. Is this correct?
>
> Yes, correct!
I see. Thank you for your answer.:)
Jihong
> .
>