diff options
Diffstat (limited to 'tools/perf/Documentation/perf-intel-pt.txt')
| -rw-r--r-- | tools/perf/Documentation/perf-intel-pt.txt | 119 |
1 files changed, 115 insertions, 4 deletions
diff --git a/tools/perf/Documentation/perf-intel-pt.txt b/tools/perf/Documentation/perf-intel-pt.txt index bcf3eca5afbe..184ba62420f0 100644 --- a/tools/perf/Documentation/perf-intel-pt.txt +++ b/tools/perf/Documentation/perf-intel-pt.txt @@ -174,7 +174,11 @@ Refer to script export-to-sqlite.py or export-to-postgresql.py for more details, and to script exported-sql-viewer.py for an example of using the database. There is also script intel-pt-events.py which provides an example of how to -unpack the raw data for power events and PTWRITE. +unpack the raw data for power events and PTWRITE. The script also displays +branches, and supports 2 additional modes selected by option: + + --insn-trace - instruction trace + --src-trace - source trace As mentioned above, it is easy to capture too much data. One way to limit the data captured is to use 'snapshot' mode which is explained further below. @@ -869,6 +873,7 @@ The letters are: L synthesize last branch entries on existing event records s skip initial number of events q quicker (less detailed) decoding + Z prefer to ignore timestamps (so-called "timeless" decoding) "Instructions" events look like they were recorded by "perf record -e instructions". @@ -1062,6 +1067,10 @@ What *will* be decoded with the qq option: - instruction pointer associated with PSB packets +The Z option is equivalent to having recorded a trace without TSC +(i.e. config term tsc=0). It can be useful to avoid timestamp issues when +decoding a trace of a virtual machine. + dump option ~~~~~~~~~~~ @@ -1150,8 +1159,9 @@ include::build-xed.txt[] Tracing Virtual Machines ------------------------ -Currently, only kernel tracing is supported and only with "timeless" decoding -i.e. no TSC timestamps +Currently, only kernel tracing is supported and only with either "timeless" decoding +(i.e. no TSC timestamps) or VM Time Correlation. VM Time Correlation is an extra step +using 'perf inject' and requires unchanging VMX TSC Offset and no VMX TSC Scaling. Other limitations and caveats @@ -1162,7 +1172,7 @@ Other limitations and caveats Guest VCPU is unknown but may be able to be inferred from the host thread Callchains are not supported -Example +Example using "timeless" decoding Start VM @@ -1226,6 +1236,107 @@ perf script can be used to provide an instruction trace :1440 1440 ffffffffbb74603c clockevents_program_event+0x4c ([guest.kernel.kallsyms]) popq %rbx :1440 1440 ffffffffbb74603d clockevents_program_event+0x4d ([guest.kernel.kallsyms]) popq %r12 +Example using VM Time Correlation + +Start VM + + $ sudo virsh start kubuntu20.04 + Domain kubuntu20.04 started + +Mount the guest file system. Note sshfs needs -o direct_io to enable reading of proc files. root access is needed to read /proc/kcore. + + $ mkdir -p vm0 + $ sshfs -o direct_io root@vm0:/ vm0 + +Copy the guest /proc/kallsyms, /proc/modules and /proc/kcore + + $ perf buildid-cache -v --kcore vm0/proc/kcore + same kcore found in /home/user/.debug/[kernel.kcore]/cc9c55a98c5e4ec0aeda69302554aabed5cd6491/2021021312450777 + $ KALLSYMS=/home/user/.debug/\[kernel.kcore\]/cc9c55a98c5e4ec0aeda69302554aabed5cd6491/2021021312450777/kallsyms + +Find the VM process + + $ ps -eLl | grep 'KVM\|PID' + F S UID PID PPID LWP C PRI NI ADDR SZ WCHAN TTY TIME CMD + 3 S 64055 16998 1 17005 13 80 0 - 1818189 - ? 00:00:16 CPU 0/KVM + 3 S 64055 16998 1 17006 4 80 0 - 1818189 - ? 00:00:05 CPU 1/KVM + 3 S 64055 16998 1 17007 3 80 0 - 1818189 - ? 00:00:04 CPU 2/KVM + 3 S 64055 16998 1 17008 4 80 0 - 1818189 - ? 00:00:05 CPU 3/KVM + +Start an open-ended perf record, tracing the VM process, do something on the VM, and then ctrl-C to stop. +IPC can be determined, hence cyc=1 can be added. +Only kernel decoding is supported, so 'k' must be specified. +Intel PT traces both the host and the guest so --guest and --host need to be specified. + + $ sudo perf kvm --guest --host --guestkallsyms $KALLSYMS record --kcore -e intel_pt/cyc=1/k -p 16998 + ^C[ perf record: Woken up 1 times to write data ] + [ perf record: Captured and wrote 9.041 MB perf.data.kvm ] + +Now 'perf inject' can be used to determine the VMX TCS Offset. Note, Intel PT TSC packets are +only 7-bytes, so the TSC Offset might differ from the actual value in the 8th byte. That will +have no effect i.e. the resulting timestamps will be correct anyway. + + $ perf inject -i perf.data.kvm --vm-time-correlation=dry-run + ERROR: Unknown TSC Offset for VMCS 0x1bff6a + VMCS: 0x1bff6a TSC Offset 0xffffe42722c64c41 + ERROR: Unknown TSC Offset for VMCS 0x1cbc08 + VMCS: 0x1cbc08 TSC Offset 0xffffe42722c64c41 + ERROR: Unknown TSC Offset for VMCS 0x1c3ce8 + VMCS: 0x1c3ce8 TSC Offset 0xffffe42722c64c41 + ERROR: Unknown TSC Offset for VMCS 0x1cbce9 + VMCS: 0x1cbce9 TSC Offset 0xffffe42722c64c41 + +Each virtual CPU has a different Virtual Machine Control Structure (VMCS) +shown above with the calculated TSC Offset. For an unchanging TSC Offset +they should all be the same for the same virtual machine. + +Now that the TSC Offset is known, it can be provided to 'perf inject' + + $ perf inject -i perf.data.kvm --vm-time-correlation="dry-run 0xffffe42722c64c41" + +Note the options for 'perf inject' --vm-time-correlation are: + + [ dry-run ] [ <TSC Offset> [ : <VMCS> [ , <VMCS> ]... ] ]... + +So it is possible to specify different TSC Offsets for different VMCS. +The option "dry-run" will cause the file to be processed but without updating it. +Note it is also possible to get a intel_pt.log file by adding option --itrace=d + +There were no errors so, do it for real + + $ perf inject -i perf.data.kvm --vm-time-correlation=0xffffe42722c64c41 --force + +'perf script' can be used to see if there are any decoder errors + + $ perf script -i perf.data.kvm --guestkallsyms $KALLSYMS --itrace=e-o + +There were none. + +'perf script' can be used to provide an instruction trace showing timestamps + + $ perf script -i perf.data.kvm --guestkallsyms $KALLSYMS --insn-trace --xed -F+ipc | grep -C10 vmresume | head -21 + CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cdd __vmx_vcpu_run+0x3d ([kernel.kallsyms]) movq 0x48(%rax), %r9 + CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133ce1 __vmx_vcpu_run+0x41 ([kernel.kallsyms]) movq 0x50(%rax), %r10 + CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133ce5 __vmx_vcpu_run+0x45 ([kernel.kallsyms]) movq 0x58(%rax), %r11 + CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133ce9 __vmx_vcpu_run+0x49 ([kernel.kallsyms]) movq 0x60(%rax), %r12 + CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133ced __vmx_vcpu_run+0x4d ([kernel.kallsyms]) movq 0x68(%rax), %r13 + CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cf1 __vmx_vcpu_run+0x51 ([kernel.kallsyms]) movq 0x70(%rax), %r14 + CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cf5 __vmx_vcpu_run+0x55 ([kernel.kallsyms]) movq 0x78(%rax), %r15 + CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cf9 __vmx_vcpu_run+0x59 ([kernel.kallsyms]) movq (%rax), %rax + CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cfc __vmx_vcpu_run+0x5c ([kernel.kallsyms]) callq 0xffffffff82133c40 + CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133c40 vmx_vmenter+0x0 ([kernel.kallsyms]) jz 0xffffffff82133c46 + CPU 1/KVM 17006 [001] 11500.262866075: ffffffff82133c42 vmx_vmenter+0x2 ([kernel.kallsyms]) vmresume IPC: 0.05 (40/769) + :17006 17006 [001] 11500.262869216: ffffffff82200cb0 asm_sysvec_apic_timer_interrupt+0x0 ([guest.kernel.kallsyms]) clac + :17006 17006 [001] 11500.262869216: ffffffff82200cb3 asm_sysvec_apic_timer_interrupt+0x3 ([guest.kernel.kallsyms]) pushq $0xffffffffffffffff + :17006 17006 [001] 11500.262869216: ffffffff82200cb5 asm_sysvec_apic_timer_interrupt+0x5 ([guest.kernel.kallsyms]) callq 0xffffffff82201160 + :17006 17006 [001] 11500.262869216: ffffffff82201160 error_entry+0x0 ([guest.kernel.kallsyms]) cld + :17006 17006 [001] 11500.262869216: ffffffff82201161 error_entry+0x1 ([guest.kernel.kallsyms]) pushq %rsi + :17006 17006 [001] 11500.262869216: ffffffff82201162 error_entry+0x2 ([guest.kernel.kallsyms]) movq 0x8(%rsp), %rsi + :17006 17006 [001] 11500.262869216: ffffffff82201167 error_entry+0x7 ([guest.kernel.kallsyms]) movq %rdi, 0x8(%rsp) + :17006 17006 [001] 11500.262869216: ffffffff8220116c error_entry+0xc ([guest.kernel.kallsyms]) pushq %rdx + :17006 17006 [001] 11500.262869216: ffffffff8220116d error_entry+0xd ([guest.kernel.kallsyms]) pushq %rcx + :17006 17006 [001] 11500.262869216: ffffffff8220116e error_entry+0xe ([guest.kernel.kallsyms]) pushq %rax + SEE ALSO |