PERF-INTEL-PT(1) perf Manual PERF-INTEL-PT(1) (NAME) perf-intel-pt - Intel Processor Trace perf (SYNOPSIS) perf record -e intel_pt// (DESCRIPTION) Intel Processor Trace (Intel PT) . Intel 64 IA-32 Intel Processor Trace . Intel PT Intel Core M Intel Core Broadwell . perf record perf.data . perf record . (decode) . TNT . . perf "instructions" "branches" . : perf script perf report perf inject. . Intel PT . Intel PT . Intel PT - JIT . . Intel PT ( ) . . (QUICKSTART) . Intel PT . perf record ls : perf record -e intel_pt//u ls perf report : perf report . /proc/kcore /proc/kcore . --kcore perf record /proc/kcore /proc/kcore : sudo perf record -o pt_ls --kcore -e intel_pt// -- ls pt_ls perf.data ( data ) /proc/kcore /proc/kallsyms /proc/modules . perf report : sudo perf report -i pt_ls (synthesize) : sudo perf report pt_ls --itrace=i1usge --itrace . . Intel PT . "branches" . . perf script itrace : perf record -e intel_pt//u ls perf script --itrace=iybxwpe flags : perf script --itrace=iybxwpe -F+flags "bcrosyiABExghDt" branch () call () return () conditional () system () asynchronous () interrupt () transaction abort ( ) trace begin ( ) trace end ( ) in transaction ( ) VM-entry ( VM) VM-exit ( VM) interrupt disabled ( ) interrupt disable toggle ( ) . perf script : perf script --insn-trace=disasm xed xed ( XED ): perf script --insn-trace --xed . perf script --call-trace perf script --call-ret-trace . perf script --time starttime,stoptime --insn-trace=disasm -C : perf script --time starttime,stoptime --insn-trace=disasm -C 1 CPU 1. ipc : perf script --itrace=be -F+ipc (IPC) . cyc ( ) IPC CYC MTC - mtc . MTC . Intel PT . IPC IPC . IPC "branches" IPC "instructions" . cyc IPC . A itrace . . IPC IPC . . A dlfilter-show-cycles.so . IPC . ( ) . (retire) . "branches" IPC CYC TNT . IPC "instructions" --itrace=i0ns sqlite postgresql . export-to-sqlite.py export-to-postgresql.py exported-sql-viewer.py . intel-pt-events.py PTWRITE . : o --insn-trace - o --src-trace - intel-pt-events.py : o --all-switch-events - (switch) . o --interleave [] - n CPU . n . . . snapshot . new snapshot option Intel PT modes of operation . (decoder) . (executed image) JIT ( mmap) . perf . Buffer handling . PERF RECORD (new event) Intel PT PMU Intel PT . PMU PMU "config" . "config" -e intel_pt// config . -e intel_pt/tsc,noretcomp=0/ -e intel_pt/tsc=1,noretcomp=0/ . config - config . config /sys/devices/intel_pt/format . config struct perf_event_attr perf_event_open . IA32_RTIT_CTL MSR . : $ grep -H . /sys/bus/event_source/devices/intel_pt/format/* /sys/bus/event_source/devices/intel_pt/format/cyc:config:1 /sys/bus/event_source/devices/intel_pt/format/cyc_thresh:config:19-22 /sys/bus/event_source/devices/intel_pt/format/mtc:config:9 /sys/bus/event_source/devices/intel_pt/format/mtc_period:config:14-17 /sys/bus/event_source/devices/intel_pt/format/noretcomp:config:11 /sys/bus/event_source/devices/intel_pt/format/psb_period:config:24-27 /sys/bus/event_source/devices/intel_pt/format/tsc:config:10 : -e intel_pt/noretcomp=0/ : -e intel_pt/tsc=1,noretcomp=0/ TSC : -e intel_pt/tsc=0/ config : -e intel_pt/config=0x400/ : u userspace k kernel h hypervisor G guest H host p precise ip h G H Intel PT . p Intel PT . u k Intel PT . -vv perf_event_attr : ------------------------------------------------------------ perf_event_attr: type 6 size 112 config 0x400 { sample_period, sample_freq } 1 sample_type IP|TID|TIME|CPU|IDENTIFIER read_format ID disabled 1 inherit 1 exclude_kernel 1 exclude_hv 1 enable_on_exec 1 sample_id_all 1 ------------------------------------------------------------ sys_perf_event_open: pid 31104 cpu 0 group_fd -1 flags 0x8 sys_perf_event_open: pid 31104 cpu 1 group_fd -1 flags 0x8 sys_perf_event_open: pid 31104 cpu 2 group_fd -1 flags 0x8 sys_perf_event_open: pid 31104 cpu 3 group_fd -1 flags 0x8 ------------------------------------------------------------ << >> (Config terms) -e intel_pt// : -e intel_pt/cyc/ (cycle accurate) . 1 : -e intel_pt/cyc=1/ 0 . (branch tracing): -e intel_pt/branch=0/ : -e intel_pt/cyc,mtc_period=9/ perf-record(1) . Intel PT . tsc . TSC . (per-thread context) . tsc ( tsc=1). noretcomp . << >> (return compression) TIP . . noretcomp ( noretcomp=0). psb_period PSB . PSB . psb_period : /sys/bus/event_source/devices/intel_pt/caps/psb_cyc <<1>> <<0>> . : /sys/bus/event_source/devices/intel_pt/caps/psb_periods 2 2 . psb_period (trace) PSB : 2 ^ (value + 11) 3 16KiB PSB . : $ perf record -e intel_pt/psb_period=15/u uname Invalid psb_period for intel_pt. Valid values are: 0-5 MTC 3 ( psb_period=3) (0 ). 0 . PSB . TSC PSB PSB MTC CYC . mtc MTC . MTC TSC . MTC (CTC) TSC TMA . : /sys/bus/event_source/devices/intel_pt/caps/mtc <<1>> <<0>> . MTC - mtc_period . mtc_period MTC - MTC mtc . : /sys/bus/event_source/devices/intel_pt/caps/mtc_periods 2 2 . mtc_period MTC : CTC-frequency / (2 ^ value) 3 CTC-frequency . CTC cpuid leaf 0x15 TSC . : $ perf record -e intel_pt/mtc_period=15/u uname Invalid mtc_period for intel_pt. Valid values are: 0,3,6,9 3 (0 ). cyc CYC . CYC (timestamp) MTC TSC . CYC CPU CYC . MTC TSC CYC . : /sys/bus/event_source/devices/intel_pt/caps/psb_cyc <<1>> <<0>> . CYC - cyc_thresh . cyc_thresh CYC - CYC cyc . cyc_thresh : /sys/bus/event_source/devices/intel_pt/caps/cycle_thresholds . cyc_thresh CPU CYC . CPU : 2 ^ (value - 1) CYC CPU . CYC CPU. : $ perf record -e intel_pt/cyc,cyc_thresh=15/u uname Invalid cyc_thresh for intel_pt. Valid values are: 0-12 CYC . pt (pass-through) branch . pt . branch . branch=0 . branch . ptw PTWRITE ptwrite . : /sys/bus/event_source/devices/intel_pt/caps/ptwrite <<1>> <<0>> . <> . fup_on_ptw FUP PTWRITE . FUP ptwrite . fup_on_ptw . fup_on_ptw . pwr_evt (power events) . C-state . : /sys/bus/event_source/devices/intel_pt/caps/power_event_trace <<1>> <<0>> . event (Event Trace) . . : /sys/bus/event_source/devices/intel_pt/caps/event_trace <<1>> <<0>> . notnt TNT . TNT (control flow) FUP TIP TIP.PGE TIP.PGD return ( - noretcomp ) . TNT . : /sys/bus/event_source/devices/intel_pt/caps/tnt_disable <<1>> <<0>> . aux-action=start-paused (paused) Pause or Resume Tracing . Intel PT AUX PEBS-via-PT. : aux-sample-size AUX AUX area sampling option aux-output PEBS-via-PT PEBS via Intel PT aux-action Pause or Resume Tracing AUX <<>> (sampling) Intel PT AUX : --aux-sample : --aux-sample=8192 Intel PT : -e intel_pt//u Intel PT Intel PT branch-misses {} : perf record --aux-sample -e '{intel_pt//u,branch-misses:u}' --aux-sample aux-sample-size . : perf record -e intel_pt//u -e branch-misses/aux-sample-size=8192/u : perf record -e '{intel_pt//u,branch-misses/aux-sample-size=8192/u}' : perf record -e intel_pt//u --filter 'filter * @/bin/ls' -e branch-misses/aux-sample-size=8192/u -- ls PSB . : Intel PT sample size (%zu) may be too small for PSB period (%zu) : sample_size < psb_period + 256 . psb_period 0 (2KiB) . 4KiB . aux_sample_size struct perf_event_attr . 64KiB . 60KiB ..SS " snapshot" full trace snapshot (kernel) full trace ( aux_tail ) snapshot (snapshot) . snapshot : -S snapshot : -S0x100000 snapshot auxtrace mmap . auxtrace mmap snapshot ( /proc/sys/kernel/perf_event_paranoid < 0 ) 4MiB ( ) 128KiB . mmap mmap auxtrace mmap size . snapshot -vv : Intel PT snapshot size: %zu auxtrace mmap size Intel PT -m : -m,16 64KiB . -m . auxtrace mmap . auxtrace mmap Intel PT ( /proc/sys/kernel/perf_event_paranoid < 0 ) 4MiB/page_size 128KiB . mmap mmap 512KiB/page_size 256KiB/page_size mlock ( /proc/self/limits ) . perf 512KiB ( /proc/sys/kernel/perf_event_mlock_kb ) cpu mlock 512KiB cpu mlock ( 64KiB cpu ). full-trace . snapshot (sampling mode) . mmap auxtrace mmap -vv : mmap length 528384 auxtrace mmap length 4198400 Intel PT Intel PT : full-trace sample snapshot. full-trace : perf record -e intel_pt//u uname sample Intel PT : perf record --aux-sample -e intel_pt//u -e branch-misses:u snapshot "snapshot" : perf record -v -e intel_pt//u -S ./loopy 1000000000 & [1] 11435 kill -USR2 11435 Recording AUX area tracing snapshot SIGUSR2 . "Recording AUX area tracing snapshot" -v . "snapshot" FIFO : $ mkfifo perf.control $ mkfifo perf.ack $ cat perf.ack & [1] 15235 $ sudo ~/bin/perf record --control fifo:perf.control,perf.ack -S -e intel_pt//u -- sleep 60 & [2] 15243 $ ps -e | grep perf 15244 pts/1 00:00:00 perf $ kill -USR2 15244 bash: kill: (15244) - Operation not permitted $ echo snapshot > perf.control ack Intel PT ..SS " (Buffer handling)" ( ToPa ) (MAX_PAGE_ORDER) . () . (interrupt) . : ) (trace) . ) . truncated PERF_RECORD_AUX . (full-trace mode) () (wrap-around) . truncated PERF_RECORD_AUX . intel_pt . perf intel_pt . Intel PT (Intel PT and build ids) <> (build ids) . Intel PT ( ). ( mmap comm task) perf.data . perf.data : perf buildid-list perf.data Intel PT : perf buildid-list --with-hits (Snapshot mode and event disabling) (snapshot) intel_pt IOCTL PERF_EVENT_IOC_DISABLE . (side-band) . (dummy) ( mmap) intel_pt . . . : perf test list ... 23: Test using a dummy software event to keep tracking : perf test 23 23: Test using a dummy software event to keep tracking : Ok perf record ( ) perf record : (per thread) (per cpu) (workload only). << >> -t --per-thread ( -p -u ) . << >> -C -a . << >> ( ) . (per-thread) . . . (per-cpu) ( cgroup -G -p -u) . . . (workload-only) . . --per-thread . (Privileged vs non-privileged users) /proc/sys/kernel/perf_event_paranoid -1 . . v4.2 (context switch) PERF_RECORD_SWITCH PERF_RECORD_SWITCH_CPU_WIDE (system wide) CAP_PERFMON CAP_SYS_ADMIN . 45ac1403f564 ("perf: Add PERF_RECORD_SWITCH to indicate context switches") . . (kernels < v4.2) sched:sched_switch : /proc/sys/kernel/perf_event_paranoid -1 (side-band) Intel PT (per-cpu) ( ) . debugfs . debugfs Intel PT . sched_switch sched_switch Intel PT PERF_RECORD_SWITCH . sched_switch : $ perf record -vv -e intel_pt//u uname ------------------------------------------------------------ perf_event_attr: type 6 size 112 config 0x400 { sample_period, sample_freq } 1 sample_type IP|TID|TIME|CPU|IDENTIFIER read_format ID disabled 1 inherit 1 exclude_kernel 1 exclude_hv 1 enable_on_exec 1 sample_id_all 1 ------------------------------------------------------------ sys_perf_event_open: pid 31104 cpu 0 group_fd -1 flags 0x8 sys_perf_event_open: pid 31104 cpu 1 group_fd -1 flags 0x8 sys_perf_event_open: pid 31104 cpu 2 group_fd -1 flags 0x8 sys_perf_event_open: pid 31104 cpu 3 group_fd -1 flags 0x8 ------------------------------------------------------------ perf_event_attr: type 2 size 112 config 0x108 { sample_period, sample_freq } 1 sample_type IP|TID|TIME|CPU|PERIOD|RAW|IDENTIFIER read_format ID inherit 1 sample_id_all 1 exclude_guest 1 ------------------------------------------------------------ sys_perf_event_open: pid -1 cpu 0 group_fd -1 flags 0x8 sys_perf_event_open: pid -1 cpu 1 group_fd -1 flags 0x8 sys_perf_event_open: pid -1 cpu 2 group_fd -1 flags 0x8 sys_perf_event_open: pid -1 cpu 3 group_fd -1 flags 0x8 ------------------------------------------------------------ perf_event_attr: type 1 size 112 config 0x9 { sample_period, sample_freq } 1 sample_type IP|TID|TIME|IDENTIFIER read_format ID disabled 1 inherit 1 exclude_kernel 1 exclude_hv 1 mmap 1 comm 1 enable_on_exec 1 task 1 sample_id_all 1 mmap2 1 comm_exec 1 ------------------------------------------------------------ sys_perf_event_open: pid 31104 cpu 0 group_fd -1 flags 0x8 sys_perf_event_open: pid 31104 cpu 1 group_fd -1 flags 0x8 sys_perf_event_open: pid 31104 cpu 2 group_fd -1 flags 0x8 sys_perf_event_open: pid 31104 cpu 3 group_fd -1 flags 0x8 mmap size 528384B AUX area mmap length 4194304 perf event ring buffer mmapped per cpu Synthesizing auxtrace information Linux [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.042 MB perf.data ] sched_switch per-cpu . sched_switch TSC . sched_switch Intel PT ..SH "PERF SCRIPT" perf script (trace) perf.data . --itrace . --itrace (New --itrace option) : --itrace : --itrace=cepwxy : i "instructions" y "cycles" b "branches" x "transactions" w "ptwrite" p "power" ( PSB) c branches ( calls) r branches ( returns) o PEBS-via-PT I (Event Trace) e (tracing error) d (debug log) g (call chain) ( i x) G l (last branch entries) ( i x) L s q ( ) A IPC Z ( "timeless") "Instructions" "perf record -e instructions" . "Cycles" "perf record -e cycles" ( ) . CYC CYC ( TNT ) . ( ) ( noretcomp ). "Branches" "perf record -e branches" . "c" "r" . "Transactions" . flags perf script (commit) (abort) . "instructions" "cycles" "branches" "transactions" (code flow packets) "branch=0" . . "ptwrite" (payload) ptwrite "fup_on_ptw" . "ptwrite" PTWRITE "ptw" . . "synth" perf script "ptwrite" : "ip: 0 payload: 0x123456789abcdef0" "fup_on_ptw" "ip" . "Power" CBR ( core-to-bus ratio) . CBR "pwr_evt" . . C-state CBR CPU . "event,synth" perf script : cbr: cbr: 22 freq: 2189 MHz (200%) mwait: hints: 0x60 extensions: 0x1 pwre: hw: 0 cstate: 2 sub-cstate: 0 exstop: ip: 1 pwrx: deepest cstate: 2 last cstate: 2 wake reason: 0x4 : "cbr" non-turbo "mwait" (hints) mwait "pwre" C-state ( C-state C0) "exstop" IP "pwrx" C0 Intel 64 IA-32 . PSB PSB+ . PSB+ . Intel PT (timing bubble) Intel PT . . . "e" . + - . Intel PT : -o (overflow) -l (data lost) : --itrace=e-o-l "d" "intel_pt.log" . . "d" . + - . Intel PT : -a perf +a perf +e ( ) +o stdout "intel_pt.log" perf +a . +e . perf-config(1) perf config itrace.debug-log-buffer-size=30000 "instructions" . : --itrace=i10us 10us . "us" "ms" () "ns" () "t" ( TSC) "i" (). "ms" "us" "ns" TSC . Intel PT . . TSC . Intel PT 100us . << >> . Intel PT instructions ( --itrace=i1i). (call chain) ( ) instructions transactions . : --itrace=ig32 --itrace=xg32 ( ) instructions transactions . : --itrace=il10 --itrace=xl10 . G L (sample mode) g l (branch stack) . branch-misses ls Intel PT: perf record --aux-sample -e '{intel_pt//u,branch-misses:u}' -- ls perf report --itrace=Ge G perf report : perf report G L "Large PEBS" . Large PEBS PEBS . . Intel PT PEBS . Large PEBS : - - PEBS - - : PERF_SAMPLE_IP | PERF_SAMPLE_TID | PERF_SAMPLE_ADDR | PERF_SAMPLE_ID | PERF_SAMPLE_CPU | PERF_SAMPLE_STREAM_ID | PERF_SAMPLE_DATA_SRC | PERF_SAMPLE_IDENTIFIER | PERF_SAMPLE_TRANSACTION | PERF_SAMPLE_PHYS_ADDR | PERF_SAMPLE_REGS_INTR | PERF_SAMPLE_REGS_USER | PERF_SAMPLE_PERIOD ( ) | PERF_SAMPLE_TIME. Intel PT Large PEBS Intel PT . Large PEBS -c perf record --count period . --no-itrace . (instructions branches transactions) . . --itrace=i0nss1000000 . q . . q TNT (object code) ip FUP TIP . q b i . q FUP TIP TIP.PGE TIP.PGD ( ). q --time . q () : o jmp o o () q : o o o noretcomp ( ) o ( ) o ( ) o ptwrite o PSB q p . q ( q qq) . PSB (PSB+) FUP PSB+ ( PSB PSBEND) . PSB psb_period ( ) . PSB+ FUP . qq : o PSB qq : o PSB Z TSC ( tsc=0). ..SS "dlfilter-show-cycles.so" dlfilter-show-cycles.so itrace A ( ) : perf script --itrace=A --call-trace --dlfilter dlfilter-show-cycles.so dlfilter: perf script -v --list-dlfilters : perf-dlfilters(1) dump (dump option) perf script (-D) (dump) . -D Intel PT . PSB - . . (truncated) PSB . Intel PT -D --no-itrace . PERF REPORT perf report perf.data . --itrace perf script --itrace=igxe . PERF INJECT perf inject --itrace : perf inject --itrace -i perf.data -o perf.data.new Intel PT autofdo . autofdo (https://github.com/google/autofdo) gcc . AutoFDO (https://gcc.gnu.org/wiki/AutoFDO/Tutorial) . $ gcc-5 -O3 sort.c -o sort_optimized $ ./sort_optimized 30000 Bubble sorting array of 30000 elements 2254 ms $ cat ~/.perfconfig [intel-pt] mispred-all = on $ perf record -e intel_pt//u ./sort 3000 Bubble sorting array of 3000 elements 58 ms [ perf record: Woken up 2 times to write data ] [ perf record: Captured and wrote 3.939 MB perf.data ] $ perf inject -i perf.data -o inj --itrace=i100usle --strip $ ./create_gcov --binary=./sort --profile=inj --gcov=sort.gcov -gcov_version=1 $ gcc-5 -O3 -fauto-profile=sort.gcov sort.c -o sort_autofdo $ ./sort_autofdo 30000 Bubble sorting array of 30000 elements 2155 ms Intel PT LBR . PEBS INTEL PT (PEBS VIA INTEL PT) PEBS Intel PT (redirect) . aux-output : perf record -c 10000 -e '{intel_pt/branch=0/,cycles/aux-output/ppp}' uname PEBS . perf PERF_RECORD_AUX_OUTPUT_HW_ID . PEBS-via-PT: perf script -D --no-itrace | grep PERF_RECORD_AUX_OUTPUT_HW_ID PEBS Intel PT itrace o : perf script --itrace=oe --xed xed . : $ git clone https://github.com/intelxed/mbuild.git mbuild $ git clone https://github.com/intelxed/xed $ cd xed $ ./mfile.py --share $ ./mfile.py examples $ sudo ./mfile.py --prefix=/usr/local install $ sudo ldconfig $ sudo cp obj/examples/xed /usr/local/bin xed: $ xed | head -3 ERROR: required argument(s) were missing Copyright (C) 2017, Intel Corporation. All rights reserved. XED version: [v10.0-328-g7d62c8c49b7b] $ ( ) (TRACING VIRTUAL MACHINES (KERNEL ONLY)) << >> (timeless) ( TSC) << >> (VM Time Correlation) . perf inject VMX TSC Offset VMX TSC Scaling . VMX VMX perf NMI - ( jump labels eBPF JIT) VCPU (Callchains) << >> (timeless) $ sudo virsh start kubuntu20.04 Domain kubuntu20.04 started . sshfs -o direct_io proc . /proc/kcore (root) . $ mkdir vm0 $ sshfs -o direct_io root@vm0:/ vm0 /proc/kallsyms /proc/modules /proc/kcore $ perf buildid-cache -v --kcore vm0/proc/kcore kcore added to build-id cache directory /home/user/.debug/[kernel.kcore]/9600f316a53a0f54278885e8d9710538ec5f6a08/2021021807494306 $ KALLSYMS=/home/user/.debug/[kernel.kcore]/9600f316a53a0f54278885e8d9710538ec5f6a08/2021021807494306/kallsyms $ ps -eLl | grep 'KVM\|PID' F S UID PID PPID LWP C PRI NI ADDR SZ WCHAN TTY TIME CMD 3 S 64055 1430 1 1440 1 80 0 - 1921718 - ? 00:02:47 CPU 0/KVM 3 S 64055 1430 1 1441 1 80 0 - 1921718 - ? 00:02:41 CPU 1/KVM 3 S 64055 1430 1 1442 1 80 0 - 1921718 - ? 00:02:38 CPU 2/KVM 3 S 64055 1430 1 1443 2 80 0 - 1921718 - ? 00:03:18 CPU 3/KVM perf record ctrl-C . TSC tsc=0 . mtc mtc=0 . IPC cyc=1 . k . Intel PT --guest --host . --per-thread . $ sudo perf kvm --guest --host --guestkallsyms $KALLSYMS record --kcore -e intel_pt/tsc=0,mtc=0,cyc=1/k -p 1430 --per-thread ^C [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 5.829 MB ] (instruction trace) perf script $ perf script --guestkallsyms $KALLSYMS --insn-trace=disasm -F+ipc | grep -C10 vmresume | head -21 CPU 0/KVM 1440 ffffffff82133cdd __vmx_vcpu_run+0x3d ([kernel.kallsyms]) movq 0x48(%rax), %r9 CPU 0/KVM 1440 ffffffff82133ce1 __vmx_vcpu_run+0x41 ([kernel.kallsyms]) movq 0x50(%rax), %r10 CPU 0/KVM 1440 ffffffff82133ce5 __vmx_vcpu_run+0x45 ([kernel.kallsyms]) movq 0x58(%rax), %r11 CPU 0/KVM 1440 ffffffff82133ce9 __vmx_vcpu_run+0x49 ([kernel.kallsyms]) movq 0x60(%rax), %r12 CPU 0/KVM 1440 ffffffff82133ced __vmx_vcpu_run+0x4d ([kernel.kallsyms]) movq 0x68(%rax), %r13 CPU 0/KVM 1440 ffffffff82133cf1 __vmx_vcpu_run+0x51 ([kernel.kallsyms]) movq 0x70(%rax), %r14 CPU 0/KVM 1440 ffffffff82133cf5 __vmx_vcpu_run+0x55 ([kernel.kallsyms]) movq 0x78(%rax), %r15 CPU 0/KVM 1440 ffffffff82133cf9 __vmx_vcpu_run+0x59 ([kernel.kallsyms]) movq (%rax), %rax CPU 0/KVM 1440 ffffffff82133cfc __vmx_vcpu_run+0x5c ([kernel.kallsyms]) callq 0xffffffff82133c40 CPU 0/KVM 1440 ffffffff82133c40 vmx_vmenter+0x0 ([kernel.kallsyms]) jz 0xffffffff82133c46 CPU 0/KVM 1440 ffffffff82133c42 vmx_vmenter+0x2 ([kernel.kallsyms]) vmresume IPC: 0.11 (50/445) :1440 1440 ffffffffbb678b06 native_write_msr+0x6 ([guest.kernel.kallsyms]) nopl %eax, (%rax,%rax,1) :1440 1440 ffffffffbb678b0b native_write_msr+0xb ([guest.kernel.kallsyms]) retq IPC: 0.04 (2/41) :1440 1440 ffffffffbb666646 lapic_next_deadline+0x26 ([guest.kernel.kallsyms]) data16 nop :1440 1440 ffffffffbb666648 lapic_next_deadline+0x28 ([guest.kernel.kallsyms]) xor %eax, %eax :1440 1440 ffffffffbb66664a lapic_next_deadline+0x2a ([guest.kernel.kallsyms]) popq %rbp :1440 1440 ffffffffbb66664b lapic_next_deadline+0x2b ([guest.kernel.kallsyms]) retq IPC: 0.16 (4/25) :1440 1440 ffffffffbb74607f clockevents_program_event+0x8f ([guest.kernel.kallsyms]) test %eax, %eax :1440 1440 ffffffffbb746081 clockevents_program_event+0x91 ([guest.kernel.kallsyms]) jz 0xffffffffbb74603c IPC: 0.06 (2/30) :1440 1440 ffffffffbb74603c clockevents_program_event+0x4c ([guest.kernel.kallsyms]) popq %rbx :1440 1440 ffffffffbb74603d clockevents_program_event+0x4d ([guest.kernel.kallsyms]) popq %r12 (VM Time Correlation) $ sudo virsh start kubuntu20.04 Domain kubuntu20.04 started . sshfs -o direct_io proc . /proc/kcore (root) . $ mkdir -p vm0 $ sshfs -o direct_io root@vm0:/ vm0 /proc/kallsyms /proc/modules /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 $ 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 perf record ctrl-C . IPC cyc=1 . k . Intel PT --guest --host . $ 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 ] perf inject VMX TCS Offset . TSC Intel PT TSC Offset . . $ 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 (VMCS) TSC Offset . TSC Offset . TSC Offset perf inject $ perf inject -i perf.data.kvm --vm-time-correlation="dry-run 0xffffe42722c64c41" --vm-time-correlation perf inject : [ dry-run ] [ [ : [ , ]... ] ]... TSC Offset VMCS . <> . intel_pt.log --itrace=d . $ perf inject -i perf.data.kvm --vm-time-correlation=0xffffe42722c64c41 --force perf script $ perf script -i perf.data.kvm --guestkallsyms $KALLSYMS --itrace=e-o . perf script $ perf script -i perf.data.kvm --guestkallsyms $KALLSYMS --insn-trace=disasm -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 perf record (sideband events) Intel PT . perf.data perf inject perf.data . : : no-kvmclock : . $ cat /proc/cmdline BOOT_IMAGE=/boot/vmlinuz-5.10.0-16-amd64 root=UUID=cb49c910-e573-47e0-bce7-79e293df8e1d ro no-kvmclock BPF JIT : $ echo 0 | sudo tee /proc/sys/net/core/bpf_jit_enable 0 perf record : $ sudo perf record -o guest-sideband-testing-guest-perf.data --sample-identifier --buildid-all --switch-events --kcore -a -e dummy : perf record Intel PT : . $ sudo perf record -o guest-sideband-testing-host-perf.data -m,64M --kcore -a -e intel_pt/cyc/ : uname: $ uname Linux : Intel PT : ^C [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 76.122 MB guest-sideband-testing-host-perf.data ] : Intel PT : ^C [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 1.247 MB guest-sideband-testing-guest-perf.data ] guest-sideband-testing-guest-perf.data ( ). : perf.data . TSC Offset : $ perf inject -i guest-sideband-testing-host-perf.data --vm-time-correlation=dry-run VMCS: 0x103fc6 TSC Offset 0xfffffa6ae070cb20 VMCS: 0x103ff2 TSC Offset 0xfffffa6ae070cb20 VMCS: 0x10fdaa TSC Offset 0xfffffa6ae070cb20 VMCS: 0x24d57c TSC Offset 0xfffffa6ae070cb20 TSC Intel PT : $ perf inject -i guest-sideband-testing-host-perf.data --vm-time-correlation=0xfffffa6ae070cb20 --force (PID) : $ perf script -i guest-sideband-testing-host-perf.data --no-itrace --show-task-events | grep KVM CPU 0/KVM 0 [000] 0.000000: PERF_RECORD_COMM: CPU 0/KVM:13376/13381 CPU 1/KVM 0 [000] 0.000000: PERF_RECORD_COMM: CPU 1/KVM:13376/13382 CPU 2/KVM 0 [000] 0.000000: PERF_RECORD_COMM: CPU 2/KVM:13376/13383 CPU 3/KVM 0 [000] 0.000000: PERF_RECORD_COMM: CPU 3/KVM:13376/13384 QEMU -name debug-threads=on VCPU ( ) . libvirt . guestmount vm_to_test : $ mkdir -p ~/guestmount/13376 $ sshfs -o direct_io vm_to_test:/ ~/guestmount/13376 perf.data perf.data : guestmount build ID VDSO. VDSO perf-archive . $ perf inject -i guest-sideband-testing-host-perf.data -o inj --guestmount ~/guestmount --guest-data=guest-sideband-testing-guest-perf.data,13376,0xfffffa6ae070cb20 . CPU uname : : o [002] o VM:13376 VCPU:003 (PID) 13376 VCPU o --itrace=ce o / "0 [unknown] ([unknown])" $ perf script -i inj --itrace=ce -F+machine_pid,+vcpu,+addr,+pid,+tid,-period --ns --time 7919.408803365,7919.408804631 -C 2 CPU 3/KVM 13376/13384 [002] 7919.408803365: branches: ffffffffc0f8ebe0 vmx_vcpu_enter_exit+0xc0 ([kernel.kallsyms]) => ffffffffc0f8edc0 __vmx_vcpu_run+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803365: branches: ffffffffc0f8edd5 __vmx_vcpu_run+0x15 ([kernel.kallsyms]) => ffffffffc0f8eca0 vmx_update_host_rsp+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803365: branches: ffffffffc0f8ee1b __vmx_vcpu_run+0x5b ([kernel.kallsyms]) => ffffffffc0f8ed60 vmx_vmenter+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803461: branches: ffffffffc0f8ed62 vmx_vmenter+0x2 ([kernel.kallsyms]) => 0 [unknown] ([unknown]) VM:13376 VCPU:003 uname 3404/3404 [002] 7919.408803461: branches: 0 [unknown] ([unknown]) => 7f851c9b5a5c init_cacheinfo+0x3ac (/usr/lib/x86_64-linux-gnu/libc-2.31.so) VM:13376 VCPU:003 uname 3404/3404 [002] 7919.408803567: branches: 7f851c9b5a5a init_cacheinfo+0x3aa (/usr/lib/x86_64-linux-gnu/libc-2.31.so) => 0 [unknown] ([unknown]) CPU 3/KVM 13376/13384 [002] 7919.408803567: branches: 0 [unknown] ([unknown]) => ffffffffc0f8ed80 vmx_vmexit+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803596: branches: ffffffffc0f6619a vmx_vcpu_run+0x26a ([kernel.kallsyms]) => ffffffffb2255c60 x86_virt_spec_ctrl+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803801: branches: ffffffffc0f66445 vmx_vcpu_run+0x515 ([kernel.kallsyms]) => ffffffffb2290b30 native_write_msr+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803850: branches: ffffffffc0f661f8 vmx_vcpu_run+0x2c8 ([kernel.kallsyms]) => ffffffffc1092300 kvm_load_host_xsave_state+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803850: branches: ffffffffc1092327 kvm_load_host_xsave_state+0x27 ([kernel.kallsyms]) => ffffffffc1092220 kvm_load_host_xsave_state.part.0+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803862: branches: ffffffffc0f662cf vmx_vcpu_run+0x39f ([kernel.kallsyms]) => ffffffffc0f63f90 vmx_recover_nmi_blocking+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803862: branches: ffffffffc0f662e9 vmx_vcpu_run+0x3b9 ([kernel.kallsyms]) => ffffffffc0f619a0 __vmx_complete_interrupts+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803872: branches: ffffffffc109cfb2 vcpu_enter_guest+0x752 ([kernel.kallsyms]) => ffffffffc0f5f570 vmx_handle_exit_irqoff+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803881: branches: ffffffffc109d028 vcpu_enter_guest+0x7c8 ([kernel.kallsyms]) => ffffffffb234f900 __srcu_read_lock+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803897: branches: ffffffffc109d06f vcpu_enter_guest+0x80f ([kernel.kallsyms]) => ffffffffc0f72e30 vmx_handle_exit+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803897: branches: ffffffffc0f72e3d vmx_handle_exit+0xd ([kernel.kallsyms]) => ffffffffc0f727c0 __vmx_handle_exit+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803897: branches: ffffffffc0f72b15 __vmx_handle_exit+0x355 ([kernel.kallsyms]) => ffffffffc0f60ae0 vmx_flush_pml_buffer+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803903: branches: ffffffffc0f72994 __vmx_handle_exit+0x1d4 ([kernel.kallsyms]) => ffffffffc10b7090 kvm_emulate_cpuid+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803903: branches: ffffffffc10b70f1 kvm_emulate_cpuid+0x61 ([kernel.kallsyms]) => ffffffffc10b6e10 kvm_cpuid+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803941: branches: ffffffffc10b7125 kvm_emulate_cpuid+0x95 ([kernel.kallsyms]) => ffffffffc1093110 kvm_skip_emulated_instruction+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803941: branches: ffffffffc109311f kvm_skip_emulated_instruction+0xf ([kernel.kallsyms]) => ffffffffc0f5e180 vmx_get_rflags+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803951: branches: ffffffffc109312a kvm_skip_emulated_instruction+0x1a ([kernel.kallsyms]) => ffffffffc0f5fd30 vmx_skip_emulated_instruction+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803951: branches: ffffffffc0f5fd79 vmx_skip_emulated_instruction+0x49 ([kernel.kallsyms]) => ffffffffc0f5fb50 skip_emulated_instruction+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803956: branches: ffffffffc0f5fc68 skip_emulated_instruction+0x118 ([kernel.kallsyms]) => ffffffffc0f6a940 vmx_cache_reg+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803964: branches: ffffffffc0f5fc11 skip_emulated_instruction+0xc1 ([kernel.kallsyms]) => ffffffffc0f5f9e0 vmx_set_interrupt_shadow+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803980: branches: ffffffffc109f8b1 vcpu_run+0x71 ([kernel.kallsyms]) => ffffffffc10ad2f0 kvm_cpu_has_pending_timer+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803980: branches: ffffffffc10ad2fb kvm_cpu_has_pending_timer+0xb ([kernel.kallsyms]) => ffffffffc10b0490 apic_has_pending_timer+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803991: branches: ffffffffc109f899 vcpu_run+0x59 ([kernel.kallsyms]) => ffffffffc109c860 vcpu_enter_guest+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803993: branches: ffffffffc109cd4c vcpu_enter_guest+0x4ec ([kernel.kallsyms]) => ffffffffc0f69140 vmx_prepare_switch_to_guest+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803996: branches: ffffffffc109cd7d vcpu_enter_guest+0x51d ([kernel.kallsyms]) => ffffffffb234f930 __srcu_read_unlock+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803996: branches: ffffffffc109cd9c vcpu_enter_guest+0x53c ([kernel.kallsyms]) => ffffffffc0f609b0 vmx_sync_pir_to_irr+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408803996: branches: ffffffffc0f60a6d vmx_sync_pir_to_irr+0xbd ([kernel.kallsyms]) => ffffffffc10adc20 kvm_lapic_find_highest_irr+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804010: branches: ffffffffc0f60abd vmx_sync_pir_to_irr+0x10d ([kernel.kallsyms]) => ffffffffc0f60820 vmx_set_rvi+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804019: branches: ffffffffc109ceca vcpu_enter_guest+0x66a ([kernel.kallsyms]) => ffffffffb2249840 fpregs_assert_state_consistent+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804021: branches: ffffffffc109cf10 vcpu_enter_guest+0x6b0 ([kernel.kallsyms]) => ffffffffc0f65f30 vmx_vcpu_run+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804024: branches: ffffffffc0f6603b vmx_vcpu_run+0x10b ([kernel.kallsyms]) => ffffffffb229bed0 __get_current_cr3_fast+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804024: branches: ffffffffc0f66055 vmx_vcpu_run+0x125 ([kernel.kallsyms]) => ffffffffb2253050 cr4_read_shadow+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804030: branches: ffffffffc0f6608d vmx_vcpu_run+0x15d ([kernel.kallsyms]) => ffffffffc10921e0 kvm_load_guest_xsave_state+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804030: branches: ffffffffc1092207 kvm_load_guest_xsave_state+0x27 ([kernel.kallsyms]) => ffffffffc1092110 kvm_load_guest_xsave_state.part.0+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804032: branches: ffffffffc0f660c6 vmx_vcpu_run+0x196 ([kernel.kallsyms]) => ffffffffb22061a0 perf_guest_get_msrs+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804032: branches: ffffffffb22061a9 perf_guest_get_msrs+0x9 ([kernel.kallsyms]) => ffffffffb220cda0 intel_guest_get_msrs+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804039: branches: ffffffffc0f66109 vmx_vcpu_run+0x1d9 ([kernel.kallsyms]) => ffffffffc0f652c0 clear_atomic_switch_msr+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804040: branches: ffffffffc0f66119 vmx_vcpu_run+0x1e9 ([kernel.kallsyms]) => ffffffffc0f73f60 intel_pmu_lbr_is_enabled+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804042: branches: ffffffffc0f73f81 intel_pmu_lbr_is_enabled+0x21 ([kernel.kallsyms]) => ffffffffc10b68e0 kvm_find_cpuid_entry+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804045: branches: ffffffffc0f66454 vmx_vcpu_run+0x524 ([kernel.kallsyms]) => ffffffffc0f61ff0 vmx_update_hv_timer+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804057: branches: ffffffffc0f66142 vmx_vcpu_run+0x212 ([kernel.kallsyms]) => ffffffffc10af100 kvm_wait_lapic_expire+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804057: branches: ffffffffc0f66156 vmx_vcpu_run+0x226 ([kernel.kallsyms]) => ffffffffb2255c60 x86_virt_spec_ctrl+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804057: branches: ffffffffc0f66161 vmx_vcpu_run+0x231 ([kernel.kallsyms]) => ffffffffc0f8eb20 vmx_vcpu_enter_exit+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804057: branches: ffffffffc0f8eb44 vmx_vcpu_enter_exit+0x24 ([kernel.kallsyms]) => ffffffffb2353e10 rcu_note_context_switch+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804057: branches: ffffffffb2353e1c rcu_note_context_switch+0xc ([kernel.kallsyms]) => ffffffffb2353db0 rcu_qs+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804066: branches: ffffffffc0f8ebe0 vmx_vcpu_enter_exit+0xc0 ([kernel.kallsyms]) => ffffffffc0f8edc0 __vmx_vcpu_run+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804066: branches: ffffffffc0f8edd5 __vmx_vcpu_run+0x15 ([kernel.kallsyms]) => ffffffffc0f8eca0 vmx_update_host_rsp+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804066: branches: ffffffffc0f8ee1b __vmx_vcpu_run+0x5b ([kernel.kallsyms]) => ffffffffc0f8ed60 vmx_vmenter+0x0 ([kernel.kallsyms]) CPU 3/KVM 13376/13384 [002] 7919.408804162: branches: ffffffffc0f8ed62 vmx_vmenter+0x2 ([kernel.kallsyms]) => 0 [unknown] ([unknown]) VM:13376 VCPU:003 uname 3404/3404 [002] 7919.408804162: branches: 0 [unknown] ([unknown]) => 7f851c9b5a5c init_cacheinfo+0x3ac (/usr/lib/x86_64-linux-gnu/libc-2.31.so) VM:13376 VCPU:003 uname 3404/3404 [002] 7919.408804273: branches: 7f851cb7c0e4 _dl_init+0x74 (/usr/lib/x86_64-linux-gnu/ld-2.31.so) => 7f851cb7bf50 call_init.part.0+0x0 (/usr/lib/x86_64-linux-gnu/ld-2.31.so) VM:13376 VCPU:003 uname 3404/3404 [002] 7919.408804526: branches: 55e0c00136f0 _start+0x0 (/usr/bin/uname) => ffffffff83200ac0 asm_exc_page_fault+0x0 ([kernel.kallsyms]) VM:13376 VCPU:003 uname 3404/3404 [002] 7919.408804526: branches: ffffffff83200ac3 asm_exc_page_fault+0x3 ([kernel.kallsyms]) => ffffffff83201290 error_entry+0x0 ([kernel.kallsyms]) VM:13376 VCPU:003 uname 3404/3404 [002] 7919.408804534: branches: ffffffff832012fa error_entry+0x6a ([kernel.kallsyms]) => ffffffff830b59a0 sync_regs+0x0 ([kernel.kallsyms]) VM:13376 VCPU:003 uname 3404/3404 [002] 7919.408804631: branches: ffffffff83200ad9 asm_exc_page_fault+0x19 ([kernel.kallsyms]) => ffffffff830b8210 exc_page_fault+0x0 ([kernel.kallsyms]) VM:13376 VCPU:003 uname 3404/3404 [002] 7919.408804631: branches: ffffffff830b82a4 exc_page_fault+0x94 ([kernel.kallsyms]) => ffffffff830b80e0 __kvm_handle_async_pf+0x0 ([kernel.kallsyms]) VM:13376 VCPU:003 uname 3404/3404 [002] 7919.408804631: branches: ffffffff830b80ed __kvm_handle_async_pf+0xd ([kernel.kallsyms]) => ffffffff830b80c0 kvm_read_and_reset_apf_flags+0x0 ([kernel.kallsyms]) - (TRACING VIRTUAL MACHINES - GUEST CODE) KVM (hypervisor) (object code) . . "--guest-code" perf script perf kvm report . KVM selftests : # perf record --kcore -e intel_pt/cyc/ -- tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.280 MB perf.data ] # perf script --guest-code --itrace=bep --ns -F-period,+addr,+flags [SNIP] tsc_msrs_test 18436 [007] 10897.962087733: branches: call ffffffffc13b2ff5 __vmx_vcpu_run+0x15 (vmlinux) => ffffffffc13b2f50 vmx_update_host_rsp+0x0 (vmlinux) tsc_msrs_test 18436 [007] 10897.962087733: branches: return ffffffffc13b2f5d vmx_update_host_rsp+0xd (vmlinux) => ffffffffc13b2ffa __vmx_vcpu_run+0x1a (vmlinux) tsc_msrs_test 18436 [007] 10897.962087733: branches: call ffffffffc13b303b __vmx_vcpu_run+0x5b (vmlinux) => ffffffffc13b2f80 vmx_vmenter+0x0 (vmlinux) tsc_msrs_test 18436 [007] 10897.962087836: branches: vmentry ffffffffc13b2f82 vmx_vmenter+0x2 (vmlinux) => 0 [unknown] ([unknown]) [guest/18436] 18436 [007] 10897.962087836: branches: vmentry 0 [unknown] ([unknown]) => 402c81 guest_code+0x131 (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) [guest/18436] 18436 [007] 10897.962087836: branches: call 402c81 guest_code+0x131 (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) => 40dba0 ucall+0x0 (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) [guest/18436] 18436 [007] 10897.962088248: branches: vmexit 40dba0 ucall+0x0 (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) => 0 [unknown] ([unknown]) tsc_msrs_test 18436 [007] 10897.962088248: branches: vmexit 0 [unknown] ([unknown]) => ffffffffc13b2fa0 vmx_vmexit+0x0 (vmlinux) tsc_msrs_test 18436 [007] 10897.962088248: branches: jmp ffffffffc13b2fa0 vmx_vmexit+0x0 (vmlinux) => ffffffffc13b2fd2 vmx_vmexit+0x32 (vmlinux) tsc_msrs_test 18436 [007] 10897.962088256: branches: return ffffffffc13b2fd2 vmx_vmexit+0x32 (vmlinux) => ffffffffc13b3040 __vmx_vcpu_run+0x60 (vmlinux) tsc_msrs_test 18436 [007] 10897.962088270: branches: return ffffffffc13b30b6 __vmx_vcpu_run+0xd6 (vmlinux) => ffffffffc13b2f2e vmx_vcpu_enter_exit+0x4e (vmlinux) [SNIP] tsc_msrs_test 18436 [007] 10897.962089321: branches: call ffffffffc13b2ff5 __vmx_vcpu_run+0x15 (vmlinux) => ffffffffc13b2f50 vmx_update_host_rsp+0x0 (vmlinux) tsc_msrs_test 18436 [007] 10897.962089321: branches: return ffffffffc13b2f5d vmx_update_host_rsp+0xd (vmlinux) => ffffffffc13b2ffa __vmx_vcpu_run+0x1a (vmlinux) tsc_msrs_test 18436 [007] 10897.962089321: branches: call ffffffffc13b303b __vmx_vcpu_run+0x5b (vmlinux) => ffffffffc13b2f80 vmx_vmenter+0x0 (vmlinux) tsc_msrs_test 18436 [007] 10897.962089424: branches: vmentry ffffffffc13b2f82 vmx_vmenter+0x2 (vmlinux) => 0 [unknown] ([unknown]) [guest/18436] 18436 [007] 10897.962089424: branches: vmentry 0 [unknown] ([unknown]) => 40dba0 ucall+0x0 (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) [guest/18436] 18436 [007] 10897.962089701: branches: jmp 40dc1b ucall+0x7b (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) => 40dc39 ucall+0x99 (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) [guest/18436] 18436 [007] 10897.962089701: branches: jcc 40dc3c ucall+0x9c (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) => 40dc20 ucall+0x80 (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) [guest/18436] 18436 [007] 10897.962089701: branches: jcc 40dc3c ucall+0x9c (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) => 40dc20 ucall+0x80 (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) [guest/18436] 18436 [007] 10897.962089701: branches: jcc 40dc37 ucall+0x97 (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) => 40dc50 ucall+0xb0 (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) [guest/18436] 18436 [007] 10897.962089878: branches: vmexit 40dc55 ucall+0xb5 (/home/user/git/work/tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test) => 0 [unknown] ([unknown]) tsc_msrs_test 18436 [007] 10897.962089878: branches: vmexit 0 [unknown] ([unknown]) => ffffffffc13b2fa0 vmx_vmexit+0x0 (vmlinux) tsc_msrs_test 18436 [007] 10897.962089878: branches: jmp ffffffffc13b2fa0 vmx_vmexit+0x0 (vmlinux) => ffffffffc13b2fd2 vmx_vmexit+0x32 (vmlinux) tsc_msrs_test 18436 [007] 10897.962089887: branches: return ffffffffc13b2fd2 vmx_vmexit+0x32 (vmlinux) => ffffffffc13b3040 __vmx_vcpu_run+0x60 (vmlinux) tsc_msrs_test 18436 [007] 10897.962089901: branches: return ffffffffc13b30b6 __vmx_vcpu_run+0xd6 (vmlinux) => ffffffffc13b2f2e vmx_vcpu_enter_exit+0x4e (vmlinux) [SNIP] # perf kvm --guest-code --guest --host report -i perf.data --stdio | head -20 # To display the perf.data header info, please use --header/--header-only options. # # # Total Lost Samples: 0 # # Samples: 12 of event 'instructions' # Event count (approx.): 2274583 # # Children Self Command Shared Object Symbol # ........ ........ ............. .................... ........................................... # 54.70% 0.00% tsc_msrs_test [kernel.vmlinux] [k] entry_SYSCALL_64_after_hwframe | ---entry_SYSCALL_64_after_hwframe do_syscall_64 | |--29.44%--syscall_exit_to_user_mode | exit_to_user_mode_prepare | task_work_run | __fput (Event Trace) (faults) (VM exits and entries). CFE EVD (Interrupt Flag) MODE.Exec . CFE (type) : 1 INTR interrupt, fault, exception, NMI 2 IRET interrupt return 3 SMI system management interrupt 4 RSM resume from system management mode 5 SIPI startup interprocessor interrupt 6 INIT INIT signal 7 VMENTRY VM-Entry 8 VMEXIT VM-Entry 9 VMEXIT_INTR VM-Exit due to interrupt 10 SHUTDOWN Shutdown Intel 64 IA-32 ( 076 ) . Event Trace /sys/bus/event_source/devices/intel_pt/caps/event_trace . "event" : perf record -e intel_pt/event/u uname Event trace --itrace I : perf script --itrace=Ie perf script CFE (vector) : evt: hw int (t) cfe: INTR IP: 1 vector: 3 PFA: 0x8877665544332211 IP IP IP CFE . perf script Interrupt Flag : iflag: t IFLAG: 1->0 via branch "via branch" ( ) "non branch" CFI STI POPF ). "D" ( ) perf script . "t" : no flag, interrupts enabled IF=1 t interrupts become disabled IF=1 -> IF=0 D interrupts are disabled IF=0 Dt interrupts become enabled IF=0 -> IF=1 intel-pt-events.py Event Trace Python . TNT (TNT DISABLE) TNT "notnt" : perf record -e intel_pt/notnt/u uname --itrace q (control flow) . PTWRITE (EMULATED PTWRITE) perf ptwrite . ptwrite (trace) (payload) TNT . : #include void perf_emulate_ptwrite(uint64_t x) __attribute__((externally_visible, noipa, no_instrument_function, naked)); #define PERF_EMULATE_PTWRITE_8_BITS \ "1: shl %rax\n" \ " jc 1f\n" \ "1: shl %rax\n" \ " jc 1f\n" \ "1: shl %rax\n" \ " jc 1f\n" \ "1: shl %rax\n" \ " jc 1f\n" \ "1: shl %rax\n" \ " jc 1f\n" \ "1: shl %rax\n" \ " jc 1f\n" \ "1: shl %rax\n" \ " jc 1f\n" \ "1: shl %rax\n" \ " jc 1f\n" /* Undefined instruction */ #define PERF_EMULATE_PTWRITE_UD2 ".byte 0x0f, 0x0b\n" #define PERF_EMULATE_PTWRITE_MAGIC PERF_EMULATE_PTWRITE_UD2 ".ascii \"perf,ptwrite \"\n" void perf_emulate_ptwrite(uint64_t x __attribute__ ((__unused__))) { /* Assumes SysV ABI : x passed in rdi */ __asm__ volatile ( "jmp 1f\n" PERF_EMULATE_PTWRITE_MAGIC "1: mov %rdi, %rax\n" PERF_EMULATE_PTWRITE_8_BITS PERF_EMULATE_PTWRITE_8_BITS PERF_EMULATE_PTWRITE_8_BITS PERF_EMULATE_PTWRITE_8_BITS PERF_EMULATE_PTWRITE_8_BITS PERF_EMULATE_PTWRITE_8_BITS PERF_EMULATE_PTWRITE_8_BITS PERF_EMULATE_PTWRITE_8_BITS "1: ret\n" ); } : #include #include #include #include "perf_emulate_ptwrite.h" int main(int argc, char *argv[]) { uint64_t x = 0; if (argc > 1) x = strtoull(argv[1], NULL, 0); perf_emulate_ptwrite(x); return 0; } : $ gcc -Wall -Wextra -O3 -g -o eg_ptw eg_ptw.c $ perf record -e intel_pt//u ./eg_ptw 0x1234567890abcdef [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.017 MB perf.data ] $ perf script --itrace=ew eg_ptw 19875 [007] 8061.235912: ptwrite: IP: 0 payload: 0x1234567890abcdef 55701249a196 perf_emulate_ptwrite+0x16 (/home/user/eg_ptw) $ (Pipe mode) Intel PT auxtrace . Intel PT . auxtrace perf . head tail auxtrace . head tail . Intel PT head tail : - (full-trace, system wide): watermark - (full-trace, not system-wide): watermark (context switch) - (snapshot mode): snapshot - (sample mode): (sample) (finished-round ordering) . auxtrace . perf.data auxtrace . (timestamps) . (PAUSE OR RESUME TRACING) Intel PT . "aux-action" : "aux-action=pause" Intel PT () . "aux-action=resume" Intel PT . "aux-action=start-paused" Intel PT . uname (sys_newuname) uname: $ perf record --kcore -e intel_pt/aux-action=start-paused/k,syscalls:sys_enter_newuname/aux-action=resume/,syscalls:sys_exit_newuname/aux-action=pause/ uname Linux [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.043 MB perf.data ] $ perf script --call-trace uname 30805 [000] 24001.058782799: name: 0x7ffc9c1865b0 uname 30805 [000] 24001.058784424: psb offs: 0 uname 30805 [000] 24001.058784424: cbr: 39 freq: 3904 MHz (139%) uname 30805 [000] 24001.058784629: ([kernel.kallsyms]) debug_smp_processor_id uname 30805 [000] 24001.058784629: ([kernel.kallsyms]) __x64_sys_newuname uname 30805 [000] 24001.058784629: ([kernel.kallsyms]) down_read uname 30805 [000] 24001.058784629: ([kernel.kallsyms]) __cond_resched uname 30805 [000] 24001.058784629: ([kernel.kallsyms]) preempt_count_add uname 30805 [000] 24001.058784629: ([kernel.kallsyms]) in_lock_functions uname 30805 [000] 24001.058784629: ([kernel.kallsyms]) preempt_count_sub uname 30805 [000] 24001.058784629: ([kernel.kallsyms]) up_read uname 30805 [000] 24001.058784629: ([kernel.kallsyms]) preempt_count_add uname 30805 [000] 24001.058784838: ([kernel.kallsyms]) in_lock_functions uname 30805 [000] 24001.058784838: ([kernel.kallsyms]) preempt_count_sub uname 30805 [000] 24001.058784838: ([kernel.kallsyms]) _copy_to_user uname 30805 [000] 24001.058784838: ([kernel.kallsyms]) syscall_exit_to_user_mode uname 30805 [000] 24001.058784838: ([kernel.kallsyms]) syscall_exit_work uname 30805 [000] 24001.058784838: ([kernel.kallsyms]) perf_syscall_exit uname 30805 [000] 24001.058784838: ([kernel.kallsyms]) debug_smp_processor_id uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) perf_trace_buf_alloc uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) perf_swevent_get_recursion_context uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) debug_smp_processor_id uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) debug_smp_processor_id uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) perf_tp_event uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) perf_trace_buf_update uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) tracing_gen_ctx_irq_test uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) perf_swevent_event uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) __perf_event_account_interrupt uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) __this_cpu_preempt_check uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) perf_event_output_forward uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) perf_event_aux_pause uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) ring_buffer_get uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) __rcu_read_lock uname 30805 [000] 24001.058785046: ([kernel.kallsyms]) __rcu_read_unlock uname 30805 [000] 24001.058785254: ([kernel.kallsyms]) pt_event_stop uname 30805 [000] 24001.058785254: ([kernel.kallsyms]) debug_smp_processor_id uname 30805 [000] 24001.058785254: ([kernel.kallsyms]) debug_smp_processor_id uname 30805 [000] 24001.058785254: ([kernel.kallsyms]) native_write_msr uname 30805 [000] 24001.058785463: ([kernel.kallsyms]) native_write_msr uname 30805 [000] 24001.058785639: 0x0 tracepoint (sampled event) . : arch_cpu_idle_enter() arch_cpu_idle_exit() breakpoint: $ sudo cat /proc/kallsyms | sort | grep ' arch_cpu_idle_enter\| arch_cpu_idle_exit' ffffffffb605bf60 T arch_cpu_idle_enter ffffffffb614d8a0 W arch_cpu_idle_exit $ sudo perf record --kcore -a -e intel_pt/aux-action=start-paused/k -e mem:0xffffffffb605bf60:x/aux-action=resume/ -e mem:0xffffffffb614d8a0:x/aux-action=pause/ -- sleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 1.387 MB perf.data ] __alloc_pages() kprobe: $ sudo perf probe --add '__alloc_pages order' Added new event: probe:__alloc_pages (on __alloc_pages with order) $ sudo perf probe --add __alloc_pages%return Added new event: probe:__alloc_pages__return (on __alloc_pages%return) $ sudo perf record --kcore -aR -e intel_pt/aux-action=start-paused/k -e probe:__alloc_pages/aux-action=resume/ -e probe:__alloc_pages__return/aux-action=pause/ -- sleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 1.490 MB perf.data ] main() uprobe: $ sudo perf probe -x /usr/bin/uname main Added new event: probe_uname:main (on main in /usr/bin/uname) $ sudo perf record -e intel_pt/-aux-action=start-paused/u -e probe_uname:main/aux-action=resume/ -- uname Linux [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.031 MB perf.data ] cycles : $ perf record --kcore -a -m,64M -e intel_pt/aux-action=start-paused/k -e cycles/aux-action=pause,period=1000000/Pk -e cycles/aux-action=resume,period=10500000/Pk -- firefox [ perf record: Woken up 19 times to write data ] [ perf record: Captured and wrote 16.561 MB perf.data ] perf "Perf tools support for Intel(R) Processor Trace" : https://perf.wiki.kernel.org/index.php/Perf_tools_support_for_Intel%C2%AE_Processor_Trace (SEE ALSO) perf-record(1), perf-script(1), perf-report(1), perf-inject(1) perf 09/04/2026 PERF-INTEL-PT(1)