1PERF-INTEL-PT(1) perf Manual PERF-INTEL-PT(1)
2
6 perf-intel-pt - Support for Intel Processor Trace within perf tools
7
9 perf record -e intel_pt//
10
12 Intel Processor Trace (Intel PT) is an extension of Intel Architecture
13 that collects information about software execution such as control
14 flow, execution modes and timings and formats it into highly compressed
15 binary packets. Technical details are documented in the Intel 64 and
16 IA-32 Architectures Software Developer Manuals, Chapter 36 Intel
17 Processor Trace.
18 Intel PT is first supported in Intel Core M and 5th generation Intel
20 Core processors that are based on the Intel micro-architecture code
21 name Broadwell.
22 Trace data is collected by perf record and stored within the perf.data
24 file. See below for options to perf record.
25 Trace data must be decoded which involves walking the object code and
27 matching the trace data packets. For example a TNT packet only tells
28 whether a conditional branch was taken or not taken, so to make use of
29 that packet the decoder must know precisely which instruction was being
30 executed.
31 Decoding is done on-the-fly. The decoder outputs samples in the same
33 format as samples output by perf hardware events, for example as though
34 the "instructions" or "branches" events had been recorded. Presently 3
35 tools support this: perf script, perf report and perf inject. See below
36 for more information on using those tools.
37 The main distinguishing feature of Intel PT is that the decoder can
39 determine the exact flow of software execution. Intel PT can be used to
40 understand why and how did software get to a certain point, or behave a
41 certain way. The software does not have to be recompiled, so Intel PT
42 works with debug or release builds, however the executed images are
43 needed - which makes use in JIT-compiled environments, or with
44 self-modified code, a challenge. Also symbols need to be provided to
45 make sense of addresses.
46 A limitation of Intel PT is that it produces huge amounts of trace data
48 (hundreds of megabytes per second per core) which takes a long time to
49 decode, for example two or three orders of magnitude longer than it
50 took to collect. Another limitation is the performance impact of
51 tracing, something that will vary depending on the use-case and
52 architecture.
53
55 It is important to start small. That is because it is easy to capture
56 vastly more data than can possibly be processed.
57 The simplest thing to do with Intel PT is userspace profiling of small
59 programs. Data is captured with perf record e.g. to trace ls
60 userspace-only:
61 perf record -e intel_pt//u ls
63 And profiled with perf report e.g.
65 perf report
67 To also trace kernel space presents a problem, namely kernel
69 self-modifying code. A fairly good kernel image is available in
70 /proc/kcore but to get an accurate image a copy of /proc/kcore needs to
71 be made under the same conditions as the data capture. perf record can
72 make a copy of /proc/kcore if the option --kcore is used, but access to
73 /proc/kcore is restricted e.g.
74 sudo perf record -o pt_ls --kcore -e intel_pt// -- ls
76 which will create a directory named pt_ls and put the perf.data file
78 (named simply data) and copies of /proc/kcore, /proc/kallsyms and
79 /proc/modules into it. The other tools understand the directory format,
80 so to use perf report becomes:
81 sudo perf report -i pt_ls
83 Because samples are synthesized after-the-fact, the sampling period can
85 be selected for reporting. e.g. sample every microsecond
86 sudo perf report pt_ls --itrace=i1usge
88 See the sections below for more information about the --itrace option.
90 Beware the smaller the period, the more samples that are produced, and
92 the longer it takes to process them.
93 Also note that the coarseness of Intel PT timing information will start
95 to distort the statistical value of the sampling as the sampling period
96 becomes smaller.
97 To represent software control flow, "branches" samples are produced. By
99 default a branch sample is synthesized for every single branch. To get
100 an idea what data is available you can use the perf script tool with
101 all itrace sampling options, which will list all the samples.
102 perf record -e intel_pt//u ls
104 perf script --itrace=iybxwpe
105 An interesting field that is not printed by default is flags which can
107 be displayed as follows:
108 perf script --itrace=iybxwpe -F+flags
110 The flags are "bcrosyiABExghDt" which stand for branch, call, return,
112 conditional, system, asynchronous, interrupt, transaction abort, trace
113 begin, trace end, in transaction, VM-entry, VM-exit, interrupt
114 disabled, and interrupt disable toggle respectively.
115 perf script also supports higher level ways to dump instruction traces:
117 perf script --insn-trace --xed
119 Dump all instructions. This requires installing the xed tool (see XED
121 below) Dumping all instructions in a long trace can be fairly slow. It
122 is usually better to start with higher level decoding, like
123 perf script --call-trace
125 or
127 perf script --call-ret-trace
129 and then select a time range of interest. The time range can then be
131 examined in detail with
132 perf script --time starttime,stoptime --insn-trace --xed
134 While examining the trace it’s also useful to filter on specific CPUs
136 using the -C option
137 perf script --time starttime,stoptime --insn-trace --xed -C 1
139 Dump all instructions in time range on CPU 1.
141 Another interesting field that is not printed by default is ipc which
143 can be displayed as follows:
144 perf script --itrace=be -F+ipc
146 There are two ways that instructions-per-cycle (IPC) can be calculated
148 depending on the recording.
149 If the cyc config term (see config terms section below) was used, then
151 IPC and cycle events are calculated using the cycle count from CYC
152 packets, otherwise MTC packets are used - refer to the mtc config term.
153 When MTC is used, however, the values are less accurate because the
154 timing is less accurate.
155 Because Intel PT does not update the cycle count on every branch or
157 instruction, the values will often be zero. When there are values, they
158 will be the number of instructions and number of cycles since the last
159 update, and thus represent the average IPC cycle count since the last
160 IPC for that event type. Note IPC for "branches" events is calculated
161 separately from IPC for "instructions" events.
162 Even with the cyc config term, it is possible to produce IPC
164 information for every change of timestamp, but at the expense of
165 accuracy. That is selected by specifying the itrace A option. Due to
166 the granularity of timestamps, the actual number of cycles increases
167 even though the cycles reported does not. The number of instructions is
168 known, but if IPC is reported, cycles can be too low and so IPC is too
169 high. Note that inaccuracy decreases as the period of sampling
170 increases i.e. if the number of cycles is too low by a small amount,
171 that becomes less significant if the number of cycles is large. It may
172 also be useful to use the A option in conjunction with
173 dlfilter-show-cycles.so to provide higher granularity cycle
174 information.
175 Also note that the IPC instruction count may or may not include the
177 current instruction. If the cycle count is associated with an
178 asynchronous branch (e.g. page fault or interrupt), then the
179 instruction count does not include the current instruction, otherwise
180 it does. That is consistent with whether or not that instruction has
181 retired when the cycle count is updated.
182 Another note, in the case of "branches" events, non-taken branches are
184 not presently sampled, so IPC values for them do not appear e.g. a CYC
185 packet with a TNT packet that starts with a non-taken branch. To see
186 every possible IPC value, "instructions" events can be used e.g.
187 --itrace=i0ns
188 While it is possible to create scripts to analyze the data, an
190 alternative approach is available to export the data to a sqlite or
191 postgresql database. Refer to script export-to-sqlite.py or
192 export-to-postgresql.py for more details, and to script
193 exported-sql-viewer.py for an example of using the database.
194 There is also script intel-pt-events.py which provides an example of
196 how to unpack the raw data for power events and PTWRITE. The script
197 also displays branches, and supports 2 additional modes selected by
198 option:
199 • --insn-trace - instruction trace
201 • --src-trace - source trace
203 The intel-pt-events.py script also has options:
205 • --all-switch-events - display all switch events, not only the last
207 consecutive.
208 • --interleave [<n>] - interleave sample output for the same
210 timestamp so that no more than n samples for a CPU are displayed in
211 a row. n defaults to 4. Note this only affects the order of
212 output, and only when the timestamp is the same.
213 As mentioned above, it is easy to capture too much data. One way to
215 limit the data captured is to use snapshot mode which is explained
216 further below. Refer to new snapshot option and Intel PT modes of
217 operation further below.
218 Another problem that will be experienced is decoder errors. They can be
220 caused by inability to access the executed image, self-modified or
221 JIT-ed code, or the inability to match side-band information (such as
222 context switches and mmaps) which results in the decoder not knowing
223 what code was executed.
224 There is also the problem of perf not being able to copy the data fast
226 enough, resulting in data lost because the buffer was full. See Buffer
227 handling below for more details.
228
230 new event
231 The Intel PT kernel driver creates a new PMU for Intel PT. PMU events
232 are selected by providing the PMU name followed by the "config"
233 separated by slashes. An enhancement has been made to allow default
234 "config" e.g. the option
235 -e intel_pt//
237 will use a default config value. Currently that is the same as
239 -e intel_pt/tsc,noretcomp=0/
241 which is the same as
243 -e intel_pt/tsc=1,noretcomp=0/
245 Note there are now new config terms - see section config terms further
247 below.
248 The config terms are listed in /sys/devices/intel_pt/format. They are
250 bit fields within the config member of the struct perf_event_attr which
251 is passed to the kernel by the perf_event_open system call. They
252 correspond to bit fields in the IA32_RTIT_CTL MSR. Here is a list of
253 them and their definitions:
254 $ grep -H . /sys/bus/event_source/devices/intel_pt/format/*
256 /sys/bus/event_source/devices/intel_pt/format/cyc:config:1
257 /sys/bus/event_source/devices/intel_pt/format/cyc_thresh:config:19-22
258 /sys/bus/event_source/devices/intel_pt/format/mtc:config:9
259 /sys/bus/event_source/devices/intel_pt/format/mtc_period:config:14-17
260 /sys/bus/event_source/devices/intel_pt/format/noretcomp:config:11
261 /sys/bus/event_source/devices/intel_pt/format/psb_period:config:24-27
262 /sys/bus/event_source/devices/intel_pt/format/tsc:config:10
263 Note that the default config must be overridden for each term i.e.
265 -e intel_pt/noretcomp=0/
267 is the same as:
269 -e intel_pt/tsc=1,noretcomp=0/
271 So, to disable TSC packets use:
273 -e intel_pt/tsc=0/
275 It is also possible to specify the config value explicitly:
277 -e intel_pt/config=0x400/
279 Note that, as with all events, the event is suffixed with event
281 modifiers:
282 u userspace
284 k kernel
285 h hypervisor
286 G guest
287 H host
288 p precise ip
289 h, G and H are for virtualization which are not used by Intel PT. p is
291 also not relevant to Intel PT. So only options u and k are meaningful
292 for Intel PT.
293 perf_event_attr is displayed if the -vv option is used e.g.
295 ------------------------------------------------------------
297 perf_event_attr:
298 type 6
299 size 112
300 config 0x400
301 { sample_period, sample_freq } 1
302 sample_type IP|TID|TIME|CPU|IDENTIFIER
303 read_format ID
304 disabled 1
305 inherit 1
306 exclude_kernel 1
307 exclude_hv 1
308 enable_on_exec 1
309 sample_id_all 1
310 ------------------------------------------------------------
311 sys_perf_event_open: pid 31104 cpu 0 group_fd -1 flags 0x8
312 sys_perf_event_open: pid 31104 cpu 1 group_fd -1 flags 0x8
313 sys_perf_event_open: pid 31104 cpu 2 group_fd -1 flags 0x8
314 sys_perf_event_open: pid 31104 cpu 3 group_fd -1 flags 0x8
315 ------------------------------------------------------------
316 config terms
318 The June 2015 version of Intel 64 and IA-32 Architectures Software
319 Developer Manuals, Chapter 36 Intel Processor Trace, defined new Intel
320 PT features. Some of the features are reflect in new config terms. All
321 the config terms are described below.
322 tsc Always supported. Produces TSC timestamp packets to provide timing
324 information. In some cases it is possible to decode without timing
325 information, for example a per-thread context that does not overlap
326 executable memory maps.
327 The default config selects tsc (i.e. tsc=1).
329 noretcomp Always supported. Disables "return compression" so a TIP
331 packet is produced when a function returns. Causes more packets to be
332 produced but might make decoding more reliable.
333 The default config does not select noretcomp (i.e. noretcomp=0).
335 psb_period Allows the frequency of PSB packets to be specified.
337 The PSB packet is a synchronization packet that provides a
339 starting point for decoding or recovery from errors.
340 Support for psb_period is indicated by:
342 /sys/bus/event_source/devices/intel_pt/caps/psb_cyc
344 which contains "1" if the feature is supported and "0"
346 otherwise.
347 Valid values are given by:
349 /sys/bus/event_source/devices/intel_pt/caps/psb_periods
351 which contains a hexadecimal value, the bits of which represent
353 valid values e.g. bit 2 set means value 2 is valid.
354 The psb_period value is converted to the approximate number of
356 trace bytes between PSB packets as:
357 2 ^ (value + 11)
359 e.g. value 3 means 16KiB bytes between PSBs
361 If an invalid value is entered, the error message
363 will give a list of valid values e.g.
364 $ perf record -e intel_pt/psb_period=15/u uname
366 Invalid psb_period for intel_pt. Valid values are: 0-5
367 If MTC packets are selected, the default config selects a value
369 of 3 (i.e. psb_period=3) or the nearest lower value that is
370 supported (0 is always supported). Otherwise the default is 0.
371 If decoding is expected to be reliable and the buffer is large
373 then a large PSB period can be used.
374 Because a TSC packet is produced with PSB, the PSB period can
376 also affect the granularity to timing information in the absence
377 of MTC or CYC.
378 mtc Produces MTC timing packets.
380 MTC packets provide finer grain timestamp information than TSC
382 packets. MTC packets record time using the hardware crystal
383 clock (CTC) which is related to TSC packets using a TMA packet.
384 Support for this feature is indicated by:
386 /sys/bus/event_source/devices/intel_pt/caps/mtc
388 which contains "1" if the feature is supported and
390 "0" otherwise.
391 The frequency of MTC packets can also be specified - see
393 mtc_period below.
394 mtc_period Specifies how frequently MTC packets are produced - see mtc
396 above for how to determine if MTC packets are supported.
397 Valid values are given by:
399 /sys/bus/event_source/devices/intel_pt/caps/mtc_periods
401 which contains a hexadecimal value, the bits of which represent
403 valid values e.g. bit 2 set means value 2 is valid.
404 The mtc_period value is converted to the MTC frequency as:
406 CTC-frequency / (2 ^ value)
408 e.g. value 3 means one eighth of CTC-frequency
410 Where CTC is the hardware crystal clock, the frequency of which
412 can be related to TSC via values provided in cpuid leaf 0x15.
413 If an invalid value is entered, the error message
415 will give a list of valid values e.g.
416 $ perf record -e intel_pt/mtc_period=15/u uname
418 Invalid mtc_period for intel_pt. Valid values are: 0,3,6,9
419 The default value is 3 or the nearest lower value
421 that is supported (0 is always supported).
422 cyc Produces CYC timing packets.
424 CYC packets provide even finer grain timestamp information than
426 MTC and TSC packets. A CYC packet contains the number of CPU
427 cycles since the last CYC packet. Unlike MTC and TSC packets,
428 CYC packets are only sent when another packet is also sent.
429 Support for this feature is indicated by:
431 /sys/bus/event_source/devices/intel_pt/caps/psb_cyc
433 which contains "1" if the feature is supported and
435 "0" otherwise.
436 The number of CYC packets produced can be reduced by specifying
438 a threshold - see cyc_thresh below.
439 cyc_thresh Specifies how frequently CYC packets are produced - see cyc
441 above for how to determine if CYC packets are supported.
442 Valid cyc_thresh values are given by:
444 /sys/bus/event_source/devices/intel_pt/caps/cycle_thresholds
446 which contains a hexadecimal value, the bits of which represent
448 valid values e.g. bit 2 set means value 2 is valid.
449 The cyc_thresh value represents the minimum number of CPU cycles
451 that must have passed before a CYC packet can be sent. The
452 number of CPU cycles is:
453 2 ^ (value - 1)
455 e.g. value 4 means 8 CPU cycles must pass before a CYC packet
457 can be sent. Note a CYC packet is still only sent when another
458 packet is sent, not at, e.g. every 8 CPU cycles.
459 If an invalid value is entered, the error message
461 will give a list of valid values e.g.
462 $ perf record -e intel_pt/cyc,cyc_thresh=15/u uname
464 Invalid cyc_thresh for intel_pt. Valid values are: 0-12
465 CYC packets are not requested by default.
467 pt Specifies pass-through which enables the branch config term.
469 The default config selects 'pt' if it is available, so a user will
471 never need to specify this term.
472 branch Enable branch tracing. Branch tracing is enabled by default so
474 to disable branch tracing use branch=0.
475 The default config selects 'branch' if it is available.
477 ptw Enable PTWRITE packets which are produced when a ptwrite
479 instruction is executed.
480 Support for this feature is indicated by:
482 /sys/bus/event_source/devices/intel_pt/caps/ptwrite
484 which contains "1" if the feature is supported and
486 "0" otherwise.
487 As an alternative, refer to "Emulated PTWRITE" further below.
489 fup_on_ptw Enable a FUP packet to follow the PTWRITE packet. The FUP
491 packet provides the address of the ptwrite instruction. In the absence
492 of fup_on_ptw, the decoder will use the address of the previous branch
493 if branch tracing is enabled, otherwise the address will be zero. Note
494 that fup_on_ptw will work even when branch tracing is disabled.
495 pwr_evt Enable power events. The power events provide information about
497 changes to the CPU C-state.
498 Support for this feature is indicated by:
500 /sys/bus/event_source/devices/intel_pt/caps/power_event_trace
502 which contains "1" if the feature is supported and
504 "0" otherwise.
505 event Enable Event Trace. The events provide information about
507 asynchronous events.
508 Support for this feature is indicated by:
510 /sys/bus/event_source/devices/intel_pt/caps/event_trace
512 which contains "1" if the feature is supported and
514 "0" otherwise.
515 notnt Disable TNT packets. Without TNT packets, it is not possible to
517 walk executable code to reconstruct control flow, however FUP, TIP,
518 TIP.PGE and TIP.PGD packets still indicate asynchronous control flow,
519 and (if return compression is disabled - see noretcomp) return
520 statements. The advantage of eliminating TNT packets is reducing the
521 size of the trace and corresponding tracing overhead.
522 Support for this feature is indicated by:
524 /sys/bus/event_source/devices/intel_pt/caps/tnt_disable
526 which contains "1" if the feature is supported and
528 "0" otherwise.
529 AUX area sampling option
531 To select Intel PT "sampling" the AUX area sampling option can be used:
532 --aux-sample
534 Optionally it can be followed by the sample size in bytes e.g.
536 --aux-sample=8192
538 In addition, the Intel PT event to sample must be defined e.g.
540 -e intel_pt//u
542 Samples on other events will be created containing Intel PT data e.g.
544 the following will create Intel PT samples on the branch-misses event,
545 note the events must be grouped using {}:
546 perf record --aux-sample -e '{intel_pt//u,branch-misses:u}'
548 An alternative to --aux-sample is to add the config term
550 aux-sample-size to events. In this case, the grouping is implied e.g.
551 perf record -e intel_pt//u -e branch-misses/aux-sample-size=8192/u
553 is the same as:
555 perf record -e '{intel_pt//u,branch-misses/aux-sample-size=8192/u}'
557 but allows for also using an address filter e.g.:
559 perf record -e intel_pt//u --filter 'filter * @/bin/ls' -e branch-misses/aux-sample-size=8192/u -- ls
561 It is important to select a sample size that is big enough to contain
563 at least one PSB packet. If not a warning will be displayed:
564 Intel PT sample size (%zu) may be too small for PSB period (%zu)
566 The calculation used for that is: if sample_size ⟨ psb_period + 256
568 display the warning. When sampling is used, psb_period defaults to 0
569 (2KiB).
570 The default sample size is 4KiB.
572 The sample size is passed in aux_sample_size in struct perf_event_attr.
574 The sample size is limited by the maximum event size which is 64KiB. It
575 is difficult to know how big the event might be without the trace
576 sample attached, but the tool validates that the sample size is not
577 greater than 60KiB.
578 new snapshot option
580 The difference between full trace and snapshot from the kernel’s
581 perspective is that in full trace we don’t overwrite trace data that
582 the user hasn’t collected yet (and indicated that by advancing
583 aux_tail), whereas in snapshot mode we let the trace run and overwrite
584 older data in the buffer so that whenever something interesting
585 happens, we can stop it and grab a snapshot of what was going on around
586 that interesting moment.
587 To select snapshot mode a new option has been added:
589 -S
591 Optionally it can be followed by the snapshot size e.g.
593 -S0x100000
595 The default snapshot size is the auxtrace mmap size. If neither
597 auxtrace mmap size nor snapshot size is specified, then the default is
598 4MiB for privileged users (or if /proc/sys/kernel/perf_event_paranoid <
599 0), 128KiB for unprivileged users. If an unprivileged user does not
600 specify mmap pages, the mmap pages will be reduced as described in the
601 new auxtrace mmap size option section below.
602 The snapshot size is displayed if the option -vv is used e.g.
604 Intel PT snapshot size: %zu
606 new auxtrace mmap size option
608 Intel PT buffer size is specified by an addition to the -m option e.g.
609 -m,16
611 selects a buffer size of 16 pages i.e. 64KiB.
613 Note that the existing functionality of -m is unchanged. The auxtrace
615 mmap size is specified by the optional addition of a comma and the
616 value.
617 The default auxtrace mmap size for Intel PT is 4MiB/page_size for
619 privileged users (or if /proc/sys/kernel/perf_event_paranoid < 0),
620 128KiB for unprivileged users. If an unprivileged user does not specify
621 mmap pages, the mmap pages will be reduced from the default
622 512KiB/page_size to 256KiB/page_size, otherwise the user is likely to
623 get an error as they exceed their mlock limit (Max locked memory as
624 shown in /proc/self/limits). Note that perf does not count the first
625 512KiB (actually /proc/sys/kernel/perf_event_mlock_kb minus 1 page) per
626 cpu against the mlock limit so an unprivileged user is allowed 512KiB
627 per cpu plus their mlock limit (which defaults to 64KiB but is not
628 multiplied by the number of cpus).
629 In full-trace mode, powers of two are allowed for buffer size, with a
631 minimum size of 2 pages. In snapshot mode or sampling mode, it is the
632 same but the minimum size is 1 page.
633 The mmap size and auxtrace mmap size are displayed if the -vv option is
635 used e.g.
636 mmap length 528384
638 auxtrace mmap length 4198400
639 Intel PT modes of operation
641 Intel PT can be used in 3 modes: full-trace mode sample mode snapshot
642 mode
643 Full-trace mode traces continuously e.g.
645 perf record -e intel_pt//u uname
647 Sample mode attaches a Intel PT sample to other events e.g.
649 perf record --aux-sample -e intel_pt//u -e branch-misses:u
651 Snapshot mode captures the available data when a signal is sent or
653 "snapshot" control command is issued. e.g. using a signal
654 perf record -v -e intel_pt//u -S ./loopy 1000000000 &
656 [1] 11435
657 kill -USR2 11435
658 Recording AUX area tracing snapshot
659 Note that the signal sent is SIGUSR2. Note that "Recording AUX area
661 tracing snapshot" is displayed because the -v option is used.
662 The advantage of using "snapshot" control command is that the access is
664 controlled by access to a FIFO e.g.
665 $ mkfifo perf.control
667 $ mkfifo perf.ack
668 $ cat perf.ack &
669 [1] 15235
670 $ sudo ~/bin/perf record --control fifo:perf.control,perf.ack -S -e intel_pt//u -- sleep 60 &
671 [2] 15243
672 $ ps -e | grep perf
673 15244 pts/1 00:00:00 perf
674 $ kill -USR2 15244
675 bash: kill: (15244) - Operation not permitted
676 $ echo snapshot > perf.control
677 ack
678 The 3 Intel PT modes of operation cannot be used together.
680 Buffer handling
682 There may be buffer limitations (i.e. single ToPa entry) which means
683 that actual buffer sizes are limited to powers of 2 up to 4MiB
684 (MAX_ORDER). In order to provide other sizes, and in particular an
685 arbitrarily large size, multiple buffers are logically concatenated.
686 However an interrupt must be used to switch between buffers. That has
687 two potential problems: a) the interrupt may not be handled in time so
688 that the current buffer becomes full and some trace data is lost. b)
689 the interrupts may slow the system and affect the performance results.
690 If trace data is lost, the driver sets truncated in the PERF_RECORD_AUX
692 event which the tools report as an error.
693 In full-trace mode, the driver waits for data to be copied out before
695 allowing the (logical) buffer to wrap-around. If data is not copied out
696 quickly enough, again truncated is set in the PERF_RECORD_AUX event. If
697 the driver has to wait, the intel_pt event gets disabled. Because it is
698 difficult to know when that happens, perf tools always re-enable the
699 intel_pt event after copying out data.
700 Intel PT and build ids
702 By default "perf record" post-processes the event stream to find all
703 build ids for executables for all addresses sampled. Deliberately,
704 Intel PT is not decoded for that purpose (it would take too long).
705 Instead the build ids for all executables encountered (due to mmap,
706 comm or task events) are included in the perf.data file.
707 To see buildids included in the perf.data file use the command:
709 perf buildid-list
711 If the perf.data file contains Intel PT data, that is the same as:
713 perf buildid-list --with-hits
715 Snapshot mode and event disabling
717 In order to make a snapshot, the intel_pt event is disabled using an
718 IOCTL, namely PERF_EVENT_IOC_DISABLE. However doing that can also
719 disable the collection of side-band information. In order to prevent
720 that, a dummy software event has been introduced that permits tracking
721 events (like mmaps) to continue to be recorded while intel_pt is
722 disabled. That is important to ensure there is complete side-band
723 information to allow the decoding of subsequent snapshots.
724 A test has been created for that. To find the test:
726 perf test list
728 ...
729 23: Test using a dummy software event to keep tracking
730 To run the test:
732 perf test 23
734 23: Test using a dummy software event to keep tracking : Ok
735 perf record modes (nothing new here)
737 perf record essentially operates in one of three modes: per thread per
738 cpu workload only
739 "per thread" mode is selected by -t or by --per-thread (with -p or -u
741 or just a workload). "per cpu" is selected by -C or -a. "workload only"
742 mode is selected by not using the other options but providing a command
743 to run (i.e. the workload).
744 In per-thread mode an exact list of threads is traced. There is no
746 inheritance. Each thread has its own event buffer.
747 In per-cpu mode all processes (or processes from the selected cgroup
749 i.e. -G option, or processes selected with -p or -u) are traced. Each
750 cpu has its own buffer. Inheritance is allowed.
751 In workload-only mode, the workload is traced but with per-cpu buffers.
753 Inheritance is allowed. Note that you can now trace a workload in
754 per-thread mode by using the --per-thread option.
755 Privileged vs non-privileged users
757 Unless /proc/sys/kernel/perf_event_paranoid is set to -1, unprivileged
758 users have memory limits imposed upon them. That affects what buffer
759 sizes they can have as outlined above.
760 The v4.2 kernel introduced support for a context switch metadata event,
762 PERF_RECORD_SWITCH, which allows unprivileged users to see when their
763 processes are scheduled out and in, just not by whom, which is left for
764 the PERF_RECORD_SWITCH_CPU_WIDE, that is only accessible in system wide
765 context, which in turn requires CAP_PERFMON or CAP_SYS_ADMIN.
766 Please see the 45ac1403f564 ("perf: Add PERF_RECORD_SWITCH to indicate
768 context switches") commit, that introduces these metadata events for
769 further info.
770 When working with kernels < v4.2, the following considerations must be
772 taken, as the sched:sched_switch tracepoints will be used to receive
773 such information:
774 Unless /proc/sys/kernel/perf_event_paranoid is set to -1, unprivileged
776 users are not permitted to use tracepoints which means there is
777 insufficient side-band information to decode Intel PT in per-cpu mode,
778 and potentially workload-only mode too if the workload creates new
779 processes.
780 Note also, that to use tracepoints, read-access to debugfs is required.
782 So if debugfs is not mounted or the user does not have read-access, it
783 will again not be possible to decode Intel PT in per-cpu mode.
784 sched_switch tracepoint
786 The sched_switch tracepoint is used to provide side-band data for Intel
787 PT decoding in kernels where the PERF_RECORD_SWITCH metadata event
788 isn’t available.
789 The sched_switch events are automatically added. e.g. the second event
791 shown below:
792 $ perf record -vv -e intel_pt//u uname
794 ------------------------------------------------------------
795 perf_event_attr:
796 type 6
797 size 112
798 config 0x400
799 { sample_period, sample_freq } 1
800 sample_type IP|TID|TIME|CPU|IDENTIFIER
801 read_format ID
802 disabled 1
803 inherit 1
804 exclude_kernel 1
805 exclude_hv 1
806 enable_on_exec 1
807 sample_id_all 1
808 ------------------------------------------------------------
809 sys_perf_event_open: pid 31104 cpu 0 group_fd -1 flags 0x8
810 sys_perf_event_open: pid 31104 cpu 1 group_fd -1 flags 0x8
811 sys_perf_event_open: pid 31104 cpu 2 group_fd -1 flags 0x8
812 sys_perf_event_open: pid 31104 cpu 3 group_fd -1 flags 0x8
813 ------------------------------------------------------------
814 perf_event_attr:
815 type 2
816 size 112
817 config 0x108
818 { sample_period, sample_freq } 1
819 sample_type IP|TID|TIME|CPU|PERIOD|RAW|IDENTIFIER
820 read_format ID
821 inherit 1
822 sample_id_all 1
823 exclude_guest 1
824 ------------------------------------------------------------
825 sys_perf_event_open: pid -1 cpu 0 group_fd -1 flags 0x8
826 sys_perf_event_open: pid -1 cpu 1 group_fd -1 flags 0x8
827 sys_perf_event_open: pid -1 cpu 2 group_fd -1 flags 0x8
828 sys_perf_event_open: pid -1 cpu 3 group_fd -1 flags 0x8
829 ------------------------------------------------------------
830 perf_event_attr:
831 type 1
832 size 112
833 config 0x9
834 { sample_period, sample_freq } 1
835 sample_type IP|TID|TIME|IDENTIFIER
836 read_format ID
837 disabled 1
838 inherit 1
839 exclude_kernel 1
840 exclude_hv 1
841 mmap 1
842 comm 1
843 enable_on_exec 1
844 task 1
845 sample_id_all 1
846 mmap2 1
847 comm_exec 1
848 ------------------------------------------------------------
849 sys_perf_event_open: pid 31104 cpu 0 group_fd -1 flags 0x8
850 sys_perf_event_open: pid 31104 cpu 1 group_fd -1 flags 0x8
851 sys_perf_event_open: pid 31104 cpu 2 group_fd -1 flags 0x8
852 sys_perf_event_open: pid 31104 cpu 3 group_fd -1 flags 0x8
853 mmap size 528384B
854 AUX area mmap length 4194304
855 perf event ring buffer mmapped per cpu
856 Synthesizing auxtrace information
857 Linux
858 [ perf record: Woken up 1 times to write data ]
859 [ perf record: Captured and wrote 0.042 MB perf.data ]
860 Note, the sched_switch event is only added if the user is permitted to
862 use it and only in per-cpu mode.
863 Note also, the sched_switch event is only added if TSC packets are
865 requested. That is because, in the absence of timing information, the
866 sched_switch events cannot be matched against the Intel PT trace.
867
869 By default, perf script will decode trace data found in the perf.data
870 file. This can be further controlled by new option --itrace.
871 New --itrace option
873 Having no option is the same as
874 --itrace
876 which, in turn, is the same as
878 --itrace=cepwxy
880 The letters are:
882 i synthesize "instructions" events
884 y synthesize "cycles" events
885 b synthesize "branches" events
886 x synthesize "transactions" events
887 w synthesize "ptwrite" events
888 p synthesize "power" events (incl. PSB events)
889 c synthesize branches events (calls only)
890 r synthesize branches events (returns only)
891 o synthesize PEBS-via-PT events
892 I synthesize Event Trace events
893 e synthesize tracing error events
894 d create a debug log
895 g synthesize a call chain (use with i or x)
896 G synthesize a call chain on existing event records
897 l synthesize last branch entries (use with i or x)
898 L synthesize last branch entries on existing event records
899 s skip initial number of events
900 q quicker (less detailed) decoding
901 A approximate IPC
902 Z prefer to ignore timestamps (so-called "timeless" decoding)
903 "Instructions" events look like they were recorded by "perf record -e
905 instructions".
906 "Cycles" events look like they were recorded by "perf record -e cycles"
908 (ie., the default). Note that even with CYC packets enabled and no
909 sampling, these are not fully accurate, since CYC packets are not
910 emitted for each instruction, only when some other event (like an
911 indirect branch, or a TNT packet representing multiple branches)
912 happens causes a packet to be emitted. Thus, it is more effective for
913 attributing cycles to functions (and possibly basic blocks) than to
914 individual instructions, although it is not even perfect for functions
915 (although it becomes better if the noretcomp option is active).
916 "Branches" events look like they were recorded by "perf record -e
918 branches". "c" and "r" can be combined to get calls and returns.
919 "Transactions" events correspond to the start or end of transactions.
921 The flags field can be used in perf script to determine whether the
922 event is a transaction start, commit or abort.
923 Note that "instructions", "cycles", "branches" and "transactions"
925 events depend on code flow packets which can be disabled by using the
926 config term "branch=0". Refer to the config terms section above.
927 "ptwrite" events record the payload of the ptwrite instruction and
929 whether "fup_on_ptw" was used. "ptwrite" events depend on PTWRITE
930 packets which are recorded only if the "ptw" config term was used.
931 Refer to the config terms section above. perf script "synth" field
932 displays "ptwrite" information like this: "ip: 0 payload:
933 0x123456789abcdef0" where "ip" is 1 if "fup_on_ptw" was used.
934 "Power" events correspond to power event packets and CBR (core-to-bus
936 ratio) packets. While CBR packets are always recorded when tracing is
937 enabled, power event packets are recorded only if the "pwr_evt" config
938 term was used. Refer to the config terms section above. The power
939 events record information about C-state changes, whereas CBR is
940 indicative of CPU frequency. perf script "event,synth" fields display
941 information like this:
942 cbr: cbr: 22 freq: 2189 MHz (200%)
944 mwait: hints: 0x60 extensions: 0x1
945 pwre: hw: 0 cstate: 2 sub-cstate: 0
946 exstop: ip: 1
947 pwrx: deepest cstate: 2 last cstate: 2 wake reason: 0x4
948 Where:
950 "cbr" includes the frequency and the percentage of maximum non-turbo
952 "mwait" shows mwait hints and extensions
953 "pwre" shows C-state transitions (to a C-state deeper than C0) and
954 whether initiated by hardware
955 "exstop" indicates execution stopped and whether the IP was recorded
956 exactly,
957 "pwrx" indicates return to C0
958 For more details refer to the Intel 64 and IA-32 Architectures Software
960 Developer Manuals.
961 PSB events show when a PSB+ occurred and also the byte-offset in the
963 trace. Emitting a PSB+ can cause a CPU a slight delay. When doing
964 timing analysis of code with Intel PT, it is useful to know if a timing
965 bubble was caused by Intel PT or not.
966 Error events show where the decoder lost the trace. Error events are
968 quite important. Users must know if what they are seeing is a complete
969 picture or not. The "e" option may be followed by flags which affect
970 what errors will or will not be reported. Each flag must be preceded by
971 either + or -. The flags supported by Intel PT are:
972 -o Suppress overflow errors
974 -l Suppress trace data lost errors
975 For example, for errors but not overflow or data lost errors:
977 --itrace=e-o-l
979 The "d" option will cause the creation of a file "intel_pt.log"
981 containing all decoded packets and instructions. Note that this option
982 slows down the decoder and that the resulting file may be very large.
983 The "d" option may be followed by flags which affect what debug
984 messages will or will not be logged. Each flag must be preceded by
985 either + or -. The flags support by Intel PT are:
986 -a Suppress logging of perf events
988 +a Log all perf events
989 +e Output only on decoding errors (size configurable)
990 +o Output to stdout instead of "intel_pt.log"
991 By default, logged perf events are filtered by any specified time
993 ranges, but flag +a overrides that. The +e flag can be useful for
994 analyzing errors. By default, the log size in that case is 16384 bytes,
995 but can be altered by perf-config(1) e.g. perf config
996 itrace.debug-log-buffer-size=30000
997 In addition, the period of the "instructions" event can be specified.
999 e.g.
1000 --itrace=i10us
1002 sets the period to 10us i.e. one instruction sample is synthesized for
1004 each 10 microseconds of trace. Alternatives to "us" are "ms"
1005 (milliseconds), "ns" (nanoseconds), "t" (TSC ticks) or "i"
1006 (instructions).
1007 "ms", "us" and "ns" are converted to TSC ticks.
1009 The timing information included with Intel PT does not give the time of
1011 every instruction. Consequently, for the purpose of sampling, the
1012 decoder estimates the time since the last timing packet based on 1 tick
1013 per instruction. The time on the sample is not adjusted and reflects
1014 the last known value of TSC.
1015 For Intel PT, the default period is 100us.
1017 Setting it to a zero period means "as often as possible".
1019 In the case of Intel PT that is the same as a period of 1 and a unit of
1021 instructions (i.e. --itrace=i1i).
1022 Also the call chain size (default 16, max. 1024) for instructions or
1024 transactions events can be specified. e.g.
1025 --itrace=ig32
1027 --itrace=xg32
1028 Also the number of last branch entries (default 64, max. 1024) for
1030 instructions or transactions events can be specified. e.g.
1031 --itrace=il10
1033 --itrace=xl10
1034 Note that last branch entries are cleared for each sample, so there is
1036 no overlap from one sample to the next.
1037 The G and L options are designed in particular for sample mode, and
1039 work much like g and l but add call chain and branch stack to the other
1040 selected events instead of synthesized events. For example, to record
1041 branch-misses events for ls and then add a call chain derived from the
1042 Intel PT trace:
1043 perf record --aux-sample -e '{intel_pt//u,branch-misses:u}' -- ls
1045 perf report --itrace=Ge
1046 Although in fact G is a default for perf report, so that is the same as
1048 just:
1049 perf report
1051 One caveat with the G and L options is that they work poorly with
1053 "Large PEBS". Large PEBS means PEBS records will be accumulated by
1054 hardware and the written into the event buffer in one go. That reduces
1055 interrupts, but can give very late timestamps. Because the Intel PT
1056 trace is synchronized by timestamps, the PEBS events do not match the
1057 trace. Currently, Large PEBS is used only in certain circumstances: -
1058 hardware supports it - PEBS is used - event period is specified,
1059 instead of frequency - the sample type is limited to the following
1060 flags: PERF_SAMPLE_IP | PERF_SAMPLE_TID | PERF_SAMPLE_ADDR |
1061 PERF_SAMPLE_ID | PERF_SAMPLE_CPU | PERF_SAMPLE_STREAM_ID |
1062 PERF_SAMPLE_DATA_SRC | PERF_SAMPLE_IDENTIFIER | PERF_SAMPLE_TRANSACTION
1063 | PERF_SAMPLE_PHYS_ADDR | PERF_SAMPLE_REGS_INTR | PERF_SAMPLE_REGS_USER
1064 | PERF_SAMPLE_PERIOD (and sometimes) | PERF_SAMPLE_TIME Because Intel
1065 PT sample mode uses a different sample type to the list above, Large
1066 PEBS is not used with Intel PT sample mode. To avoid Large PEBS in
1067 other cases, avoid specifying the event period i.e. avoid the perf
1068 record -c option, --count option, or period config term.
1069 To disable trace decoding entirely, use the option --no-itrace.
1071 It is also possible to skip events generated (instructions, branches,
1073 transactions) at the beginning. This is useful to ignore initialization
1074 code.
1075 --itrace=i0nss1000000
1077 skips the first million instructions.
1079 The q option changes the way the trace is decoded. The decoding is much
1081 faster but much less detailed. Specifically, with the q option, the
1082 decoder does not decode TNT packets, and does not walk object code, but
1083 gets the ip from FUP and TIP packets. The q option can be used with the
1084 b and i options but the period is not used. The q option decodes more
1085 quickly, but is useful only if the control flow of interest is
1086 represented or indicated by FUP, TIP, TIP.PGE, or TIP.PGD packets
1087 (refer below). However the q option could be used to find time ranges
1088 that could then be decoded fully using the --time option.
1089 What will not be decoded with the (single) q option:
1091 • direct calls and jmps
1093 • conditional branches
1095 • non-branch instructions
1097 What will be decoded with the (single) q option:
1099 • asynchronous branches such as interrupts
1101 • indirect branches
1103 • function return target address if the noretcomp config term (refer
1105 config terms section) was used
1106 • start of (control-flow) tracing
1108 • end of (control-flow) tracing, if it is not out of context
1110 • power events, ptwrite, transaction start and abort
1112 • instruction pointer associated with PSB packets
1114 Note the q option does not specify what events will be synthesized e.g.
1116 the p option must be used also to show power events.
1117 Repeating the q option (double-q i.e. qq) results in even faster
1119 decoding and even less detail. The decoder decodes only extended PSB
1120 (PSB+) packets, getting the instruction pointer if there is a FUP
1121 packet within PSB+ (i.e. between PSB and PSBEND). Note PSB packets
1122 occur regularly in the trace based on the psb_period config term (refer
1123 config terms section). There will be a FUP packet if the PSB+ occurs
1124 while control flow is being traced.
1125 What will not be decoded with the qq option:
1127 • everything except instruction pointer associated with PSB packets
1129 What will be decoded with the qq option:
1131 • instruction pointer associated with PSB packets
1133 The Z option is equivalent to having recorded a trace without TSC (i.e.
1135 config term tsc=0). It can be useful to avoid timestamp issues when
1136 decoding a trace of a virtual machine.
1137 dlfilter-show-cycles.so
1139 Cycles can be displayed using dlfilter-show-cycles.so in which case the
1140 itrace A option can be useful to provide higher granularity cycle
1141 information:
1142 perf script --itrace=A --call-trace --dlfilter dlfilter-show-cycles.so
1144 To see a list of dlfilters:
1146 perf script -v --list-dlfilters
1148 See also perf-dlfilters(1)
1150 dump option
1152 perf script has an option (-D) to "dump" the events i.e. display the
1153 binary data.
1154 When -D is used, Intel PT packets are displayed. The packet decoder
1156 does not pay attention to PSB packets, but just decodes the bytes - so
1157 the packets seen by the actual decoder may not be identical in places
1158 where the data is corrupt. One example of that would be when the
1159 buffer-switching interrupt has been too slow, and the buffer has been
1160 filled completely. In that case, the last packet in the buffer might be
1161 truncated and immediately followed by a PSB as the trace continues in
1162 the next buffer.
1163 To disable the display of Intel PT packets, combine the -D option with
1165 --no-itrace.
1166
1168 By default, perf report will decode trace data found in the perf.data
1169 file. This can be further controlled by new option --itrace exactly the
1170 same as perf script, with the exception that the default is
1171 --itrace=igxe.
1172
1174 perf inject also accepts the --itrace option in which case tracing data
1175 is removed and replaced with the synthesized events. e.g.
1176 perf inject --itrace -i perf.data -o perf.data.new
1178 Below is an example of using Intel PT with autofdo. It requires autofdo
1180 (https://github.com/google/autofdo) and gcc version 5. The bubble sort
1181 example is from the AutoFDO tutorial
1182 (https://gcc.gnu.org/wiki/AutoFDO/Tutorial) amended to take the number
1183 of elements as a parameter.
1184 $ gcc-5 -O3 sort.c -o sort_optimized
1186 $ ./sort_optimized 30000
1187 Bubble sorting array of 30000 elements
1188 2254 ms
1189 $ cat ~/.perfconfig
1191 [intel-pt]
1192 mispred-all = on
1193 $ perf record -e intel_pt//u ./sort 3000
1195 Bubble sorting array of 3000 elements
1196 58 ms
1197 [ perf record: Woken up 2 times to write data ]
1198 [ perf record: Captured and wrote 3.939 MB perf.data ]
1199 $ perf inject -i perf.data -o inj --itrace=i100usle --strip
1200 $ ./create_gcov --binary=./sort --profile=inj --gcov=sort.gcov -gcov_version=1
1201 $ gcc-5 -O3 -fauto-profile=sort.gcov sort.c -o sort_autofdo
1202 $ ./sort_autofdo 30000
1203 Bubble sorting array of 30000 elements
1204 2155 ms
1205 Note there is currently no advantage to using Intel PT instead of LBR,
1207 but that may change in the future if greater use is made of the data.
1208
1210 Some hardware has the feature to redirect PEBS records to the Intel PT
1211 trace. Recording is selected by using the aux-output config term e.g.
1212 perf record -c 10000 -e '{intel_pt/branch=0/,cycles/aux-output/ppp}' uname
1214 Originally, software only supported redirecting at most one PEBS event
1216 because it was not able to differentiate one event from another. To
1217 overcome that, more recent kernels and perf tools add support for the
1218 PERF_RECORD_AUX_OUTPUT_HW_ID side-band event. To check for the presence
1219 of that event in a PEBS-via-PT trace:
1220 perf script -D --no-itrace | grep PERF_RECORD_AUX_OUTPUT_HW_ID
1222 To display PEBS events from the Intel PT trace, use the itrace o option
1224 e.g.
1225 perf script --itrace=oe
1227
1229 For --xed the xed tool is needed. Here is how to install it:
1230 $ git clone https://github.com/intelxed/mbuild.git mbuild
1232 $ git clone https://github.com/intelxed/xed
1233 $ cd xed
1234 $ ./mfile.py --share
1235 $ ./mfile.py examples
1236 $ sudo ./mfile.py --prefix=/usr/local install
1237 $ sudo ldconfig
1238 $ sudo cp obj/examples/xed /usr/local/bin
1239 Basic xed testing:
1241 $ xed | head -3
1243 ERROR: required argument(s) were missing
1244 Copyright (C) 2017, Intel Corporation. All rights reserved.
1245 XED version: [v10.0-328-g7d62c8c49b7b]
1246 $
1247
1249 Currently, kernel tracing is supported with either "timeless" decoding
1250 (i.e. no TSC timestamps) or VM Time Correlation. VM Time Correlation is
1251 an extra step using perf inject and requires unchanging VMX TSC Offset
1252 and no VMX TSC Scaling.
1253 Other limitations and caveats
1255 VMX controls may suppress packets needed for decoding resulting in decoding errors
1257 VMX controls may block the perf NMI to the host potentially resulting in lost trace data
1258 Guest kernel self-modifying code (e.g. jump labels or JIT-compiled eBPF) will result in decoding errors
1259 Guest thread information is unknown
1260 Guest VCPU is unknown but may be able to be inferred from the host thread
1261 Callchains are not supported
1262 Example using "timeless" decoding
1264 Start VM
1266 $ sudo virsh start kubuntu20.04
1268 Domain kubuntu20.04 started
1269 Mount the guest file system. Note sshfs needs -o direct_io to enable
1271 reading of proc files. root access is needed to read /proc/kcore.
1272 $ mkdir vm0
1274 $ sshfs -o direct_io root@vm0:/ vm0
1275 Copy the guest /proc/kallsyms, /proc/modules and /proc/kcore
1277 $ perf buildid-cache -v --kcore vm0/proc/kcore
1279 kcore added to build-id cache directory /home/user/.debug/[kernel.kcore]/9600f316a53a0f54278885e8d9710538ec5f6a08/2021021807494306
1280 $ KALLSYMS=/home/user/.debug/[kernel.kcore]/9600f316a53a0f54278885e8d9710538ec5f6a08/2021021807494306/kallsyms
1281 Find the VM process
1283 $ ps -eLl | grep 'KVM\|PID'
1285 F S UID PID PPID LWP C PRI NI ADDR SZ WCHAN TTY TIME CMD
1286 3 S 64055 1430 1 1440 1 80 0 - 1921718 - ? 00:02:47 CPU 0/KVM
1287 3 S 64055 1430 1 1441 1 80 0 - 1921718 - ? 00:02:41 CPU 1/KVM
1288 3 S 64055 1430 1 1442 1 80 0 - 1921718 - ? 00:02:38 CPU 2/KVM
1289 3 S 64055 1430 1 1443 2 80 0 - 1921718 - ? 00:03:18 CPU 3/KVM
1290 Start an open-ended perf record, tracing the VM process, do something
1292 on the VM, and then ctrl-C to stop. TSC is not supported and tsc=0 must
1293 be specified. That means mtc is useless, so add mtc=0. However, IPC can
1294 still be determined, hence cyc=1 can be added. Only kernel decoding is
1295 supported, so k must be specified. Intel PT traces both the host and
1296 the guest so --guest and --host need to be specified. Without
1297 timestamps, --per-thread must be specified to distinguish threads.
1298 $ sudo perf kvm --guest --host --guestkallsyms $KALLSYMS record --kcore -e intel_pt/tsc=0,mtc=0,cyc=1/k -p 1430 --per-thread
1300 ^C
1301 [ perf record: Woken up 1 times to write data ]
1302 [ perf record: Captured and wrote 5.829 MB ]
1303 perf script can be used to provide an instruction trace
1305 $ perf script --guestkallsyms $KALLSYMS --insn-trace --xed -F+ipc | grep -C10 vmresume | head -21
1307 CPU 0/KVM 1440 ffffffff82133cdd __vmx_vcpu_run+0x3d ([kernel.kallsyms]) movq 0x48(%rax), %r9
1308 CPU 0/KVM 1440 ffffffff82133ce1 __vmx_vcpu_run+0x41 ([kernel.kallsyms]) movq 0x50(%rax), %r10
1309 CPU 0/KVM 1440 ffffffff82133ce5 __vmx_vcpu_run+0x45 ([kernel.kallsyms]) movq 0x58(%rax), %r11
1310 CPU 0/KVM 1440 ffffffff82133ce9 __vmx_vcpu_run+0x49 ([kernel.kallsyms]) movq 0x60(%rax), %r12
1311 CPU 0/KVM 1440 ffffffff82133ced __vmx_vcpu_run+0x4d ([kernel.kallsyms]) movq 0x68(%rax), %r13
1312 CPU 0/KVM 1440 ffffffff82133cf1 __vmx_vcpu_run+0x51 ([kernel.kallsyms]) movq 0x70(%rax), %r14
1313 CPU 0/KVM 1440 ffffffff82133cf5 __vmx_vcpu_run+0x55 ([kernel.kallsyms]) movq 0x78(%rax), %r15
1314 CPU 0/KVM 1440 ffffffff82133cf9 __vmx_vcpu_run+0x59 ([kernel.kallsyms]) movq (%rax), %rax
1315 CPU 0/KVM 1440 ffffffff82133cfc __vmx_vcpu_run+0x5c ([kernel.kallsyms]) callq 0xffffffff82133c40
1316 CPU 0/KVM 1440 ffffffff82133c40 vmx_vmenter+0x0 ([kernel.kallsyms]) jz 0xffffffff82133c46
1317 CPU 0/KVM 1440 ffffffff82133c42 vmx_vmenter+0x2 ([kernel.kallsyms]) vmresume IPC: 0.11 (50/445)
1318 :1440 1440 ffffffffbb678b06 native_write_msr+0x6 ([guest.kernel.kallsyms]) nopl %eax, (%rax,%rax,1)
1319 :1440 1440 ffffffffbb678b0b native_write_msr+0xb ([guest.kernel.kallsyms]) retq IPC: 0.04 (2/41)
1320 :1440 1440 ffffffffbb666646 lapic_next_deadline+0x26 ([guest.kernel.kallsyms]) data16 nop
1321 :1440 1440 ffffffffbb666648 lapic_next_deadline+0x28 ([guest.kernel.kallsyms]) xor %eax, %eax
1322 :1440 1440 ffffffffbb66664a lapic_next_deadline+0x2a ([guest.kernel.kallsyms]) popq %rbp
1323 :1440 1440 ffffffffbb66664b lapic_next_deadline+0x2b ([guest.kernel.kallsyms]) retq IPC: 0.16 (4/25)
1324 :1440 1440 ffffffffbb74607f clockevents_program_event+0x8f ([guest.kernel.kallsyms]) test %eax, %eax
1325 :1440 1440 ffffffffbb746081 clockevents_program_event+0x91 ([guest.kernel.kallsyms]) jz 0xffffffffbb74603c IPC: 0.06 (2/30)
1326 :1440 1440 ffffffffbb74603c clockevents_program_event+0x4c ([guest.kernel.kallsyms]) popq %rbx
1327 :1440 1440 ffffffffbb74603d clockevents_program_event+0x4d ([guest.kernel.kallsyms]) popq %r12
1328 Example using VM Time Correlation
1330 Start VM
1332 $ sudo virsh start kubuntu20.04
1334 Domain kubuntu20.04 started
1335 Mount the guest file system. Note sshfs needs -o direct_io to enable
1337 reading of proc files. root access is needed to read /proc/kcore.
1338 $ mkdir -p vm0
1340 $ sshfs -o direct_io root@vm0:/ vm0
1341 Copy the guest /proc/kallsyms, /proc/modules and /proc/kcore
1343 $ perf buildid-cache -v --kcore vm0/proc/kcore
1345 same kcore found in /home/user/.debug/[kernel.kcore]/cc9c55a98c5e4ec0aeda69302554aabed5cd6491/2021021312450777
1346 $ KALLSYMS=/home/user/.debug/\[kernel.kcore\]/cc9c55a98c5e4ec0aeda69302554aabed5cd6491/2021021312450777/kallsyms
1347 Find the VM process
1349 $ ps -eLl | grep 'KVM\|PID'
1351 F S UID PID PPID LWP C PRI NI ADDR SZ WCHAN TTY TIME CMD
1352 3 S 64055 16998 1 17005 13 80 0 - 1818189 - ? 00:00:16 CPU 0/KVM
1353 3 S 64055 16998 1 17006 4 80 0 - 1818189 - ? 00:00:05 CPU 1/KVM
1354 3 S 64055 16998 1 17007 3 80 0 - 1818189 - ? 00:00:04 CPU 2/KVM
1355 3 S 64055 16998 1 17008 4 80 0 - 1818189 - ? 00:00:05 CPU 3/KVM
1356 Start an open-ended perf record, tracing the VM process, do something
1358 on the VM, and then ctrl-C to stop. IPC can be determined, hence cyc=1
1359 can be added. Only kernel decoding is supported, so k must be
1360 specified. Intel PT traces both the host and the guest so --guest and
1361 --host need to be specified.
1362 $ sudo perf kvm --guest --host --guestkallsyms $KALLSYMS record --kcore -e intel_pt/cyc=1/k -p 16998
1364 ^C[ perf record: Woken up 1 times to write data ]
1365 [ perf record: Captured and wrote 9.041 MB perf.data.kvm ]
1366 Now perf inject can be used to determine the VMX TCS Offset. Note,
1368 Intel PT TSC packets are only 7-bytes, so the TSC Offset might differ
1369 from the actual value in the 8th byte. That will have no effect i.e.
1370 the resulting timestamps will be correct anyway.
1371 $ perf inject -i perf.data.kvm --vm-time-correlation=dry-run
1373 ERROR: Unknown TSC Offset for VMCS 0x1bff6a
1374 VMCS: 0x1bff6a TSC Offset 0xffffe42722c64c41
1375 ERROR: Unknown TSC Offset for VMCS 0x1cbc08
1376 VMCS: 0x1cbc08 TSC Offset 0xffffe42722c64c41
1377 ERROR: Unknown TSC Offset for VMCS 0x1c3ce8
1378 VMCS: 0x1c3ce8 TSC Offset 0xffffe42722c64c41
1379 ERROR: Unknown TSC Offset for VMCS 0x1cbce9
1380 VMCS: 0x1cbce9 TSC Offset 0xffffe42722c64c41
1381 Each virtual CPU has a different Virtual Machine Control Structure
1383 (VMCS) shown above with the calculated TSC Offset. For an unchanging
1384 TSC Offset they should all be the same for the same virtual machine.
1385 Now that the TSC Offset is known, it can be provided to perf inject
1387 $ perf inject -i perf.data.kvm --vm-time-correlation="dry-run 0xffffe42722c64c41"
1389 Note the options for perf inject --vm-time-correlation are:
1391 [ dry-run ] [ <TSC Offset> [ : <VMCS> [ , <VMCS> ]... ] ]...
1393 So it is possible to specify different TSC Offsets for different VMCS.
1395 The option "dry-run" will cause the file to be processed but without
1396 updating it. Note it is also possible to get a intel_pt.log file by
1397 adding option --itrace=d
1398 There were no errors so, do it for real
1400 $ perf inject -i perf.data.kvm --vm-time-correlation=0xffffe42722c64c41 --force
1402 perf script can be used to see if there are any decoder errors
1404 $ perf script -i perf.data.kvm --guestkallsyms $KALLSYMS --itrace=e-o
1406 There were none.
1408 perf script can be used to provide an instruction trace showing
1410 timestamps
1411 $ perf script -i perf.data.kvm --guestkallsyms $KALLSYMS --insn-trace --xed -F+ipc | grep -C10 vmresume | head -21
1413 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cdd __vmx_vcpu_run+0x3d ([kernel.kallsyms]) movq 0x48(%rax), %r9
1414 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133ce1 __vmx_vcpu_run+0x41 ([kernel.kallsyms]) movq 0x50(%rax), %r10
1415 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133ce5 __vmx_vcpu_run+0x45 ([kernel.kallsyms]) movq 0x58(%rax), %r11
1416 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133ce9 __vmx_vcpu_run+0x49 ([kernel.kallsyms]) movq 0x60(%rax), %r12
1417 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133ced __vmx_vcpu_run+0x4d ([kernel.kallsyms]) movq 0x68(%rax), %r13
1418 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cf1 __vmx_vcpu_run+0x51 ([kernel.kallsyms]) movq 0x70(%rax), %r14
1419 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cf5 __vmx_vcpu_run+0x55 ([kernel.kallsyms]) movq 0x78(%rax), %r15
1420 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cf9 __vmx_vcpu_run+0x59 ([kernel.kallsyms]) movq (%rax), %rax
1421 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cfc __vmx_vcpu_run+0x5c ([kernel.kallsyms]) callq 0xffffffff82133c40
1422 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133c40 vmx_vmenter+0x0 ([kernel.kallsyms]) jz 0xffffffff82133c46
1423 CPU 1/KVM 17006 [001] 11500.262866075: ffffffff82133c42 vmx_vmenter+0x2 ([kernel.kallsyms]) vmresume IPC: 0.05 (40/769)
1424 :17006 17006 [001] 11500.262869216: ffffffff82200cb0 asm_sysvec_apic_timer_interrupt+0x0 ([guest.kernel.kallsyms]) clac
1425 :17006 17006 [001] 11500.262869216: ffffffff82200cb3 asm_sysvec_apic_timer_interrupt+0x3 ([guest.kernel.kallsyms]) pushq $0xffffffffffffffff
1426 :17006 17006 [001] 11500.262869216: ffffffff82200cb5 asm_sysvec_apic_timer_interrupt+0x5 ([guest.kernel.kallsyms]) callq 0xffffffff82201160
1427 :17006 17006 [001] 11500.262869216: ffffffff82201160 error_entry+0x0 ([guest.kernel.kallsyms]) cld
1428 :17006 17006 [001] 11500.262869216: ffffffff82201161 error_entry+0x1 ([guest.kernel.kallsyms]) pushq %rsi
1429 :17006 17006 [001] 11500.262869216: ffffffff82201162 error_entry+0x2 ([guest.kernel.kallsyms]) movq 0x8(%rsp), %rsi
1430 :17006 17006 [001] 11500.262869216: ffffffff82201167 error_entry+0x7 ([guest.kernel.kallsyms]) movq %rdi, 0x8(%rsp)
1431 :17006 17006 [001] 11500.262869216: ffffffff8220116c error_entry+0xc ([guest.kernel.kallsyms]) pushq %rdx
1432 :17006 17006 [001] 11500.262869216: ffffffff8220116d error_entry+0xd ([guest.kernel.kallsyms]) pushq %rcx
1433 :17006 17006 [001] 11500.262869216: ffffffff8220116e error_entry+0xe ([guest.kernel.kallsyms]) pushq %rax
1434
1436 It is possible to use perf record to record sideband events within a
1437 virtual machine, so that an Intel PT trace on the host can be decoded.
1438 Sideband events from the guest perf.data file can be injected into the
1439 host perf.data file using perf inject.
1440 Here is an example of the steps needed:
1442 On the guest machine:
1444 Check that no-kvmclock kernel command line option was used to boot:
1446 Note, this is essential to enable time correlation between host and
1448 guest machines.
1449 $ cat /proc/cmdline
1451 BOOT_IMAGE=/boot/vmlinuz-5.10.0-16-amd64 root=UUID=cb49c910-e573-47e0-bce7-79e293df8e1d ro no-kvmclock
1452 There is no BPF support at present so, if possible, disable JIT
1454 compiling:
1455 $ echo 0 | sudo tee /proc/sys/net/core/bpf_jit_enable
1457 0
1458 Start perf record to collect sideband events:
1460 $ sudo perf record -o guest-sideband-testing-guest-perf.data --sample-identifier --buildid-all --switch-events --kcore -a -e dummy
1462 On the host machine:
1464 Start perf record to collect Intel PT trace:
1466 Note, the host trace will get very big, very fast, so the steps from
1468 starting to stopping the host trace really need to be done so that they
1469 happen in the shortest time possible.
1470 $ sudo perf record -o guest-sideband-testing-host-perf.data -m,64M --kcore -a -e intel_pt/cyc/
1472 On the guest machine:
1474 Run a small test case, just uname in this example:
1476 $ uname
1478 Linux
1479 On the host machine:
1481 Stop the Intel PT trace:
1483 ^C
1485 [ perf record: Woken up 1 times to write data ]
1486 [ perf record: Captured and wrote 76.122 MB guest-sideband-testing-host-perf.data ]
1487 On the guest machine:
1489 Stop the Intel PT trace:
1491 ^C
1493 [ perf record: Woken up 1 times to write data ]
1494 [ perf record: Captured and wrote 1.247 MB guest-sideband-testing-guest-perf.data ]
1495 And then copy guest-sideband-testing-guest-perf.data to the host (not
1497 shown here).
1498 On the host machine:
1500 With the 2 perf.data recordings, and with their ownership changed to
1502 the user.
1503 Identify the TSC Offset:
1505 $ perf inject -i guest-sideband-testing-host-perf.data --vm-time-correlation=dry-run
1507 VMCS: 0x103fc6 TSC Offset 0xfffffa6ae070cb20
1508 VMCS: 0x103ff2 TSC Offset 0xfffffa6ae070cb20
1509 VMCS: 0x10fdaa TSC Offset 0xfffffa6ae070cb20
1510 VMCS: 0x24d57c TSC Offset 0xfffffa6ae070cb20
1511 Correct Intel PT TSC timestamps for the guest machine:
1513 $ perf inject -i guest-sideband-testing-host-perf.data --vm-time-correlation=0xfffffa6ae070cb20 --force
1515 Identify the guest machine PID:
1517 $ perf script -i guest-sideband-testing-host-perf.data --no-itrace --show-task-events | grep KVM
1519 CPU 0/KVM 0 [000] 0.000000: PERF_RECORD_COMM: CPU 0/KVM:13376/13381
1520 CPU 1/KVM 0 [000] 0.000000: PERF_RECORD_COMM: CPU 1/KVM:13376/13382
1521 CPU 2/KVM 0 [000] 0.000000: PERF_RECORD_COMM: CPU 2/KVM:13376/13383
1522 CPU 3/KVM 0 [000] 0.000000: PERF_RECORD_COMM: CPU 3/KVM:13376/13384
1523 Note, the QEMU option -name debug-threads=on is needed so that thread
1525 names can be used to determine which thread is running which VCPU as
1526 above. libvirt seems to use this by default.
1527 Create a guestmount, assuming the guest machine is vm_to_test:
1529 $ mkdir -p ~/guestmount/13376
1531 $ sshfs -o direct_io vm_to_test:/ ~/guestmount/13376
1532 Inject the guest perf.data file into the host perf.data file:
1534 Note, due to the guestmount option, guest object files and debug files
1536 will be copied into the build ID cache from the guest machine, with the
1537 notable exception of VDSO. If needed, VDSO can be copied manually in a
1538 fashion similar to that used by the perf-archive script.
1539 $ perf inject -i guest-sideband-testing-host-perf.data -o inj --guestmount ~/guestmount --guest-data=guest-sideband-testing-guest-perf.data,13376,0xfffffa6ae070cb20
1541 Show an excerpt from the result. In this case the CPU and time range
1543 have been to chosen to show interaction between guest and host when
1544 uname is starting to run on the guest machine:
1545 Notes:
1547 • the CPU displayed, [002] in this case, is always the host CPU
1549 • events happening in the virtual machine start with VM:13376
1551 VCPU:003, which shows the hypervisor PID 13376 and the VCPU number
1552 • only calls and errors are displayed i.e. --itrace=ce
1554 • branches entering and exiting the virtual machine are split, and
1556 show as 2 branches to/from "0 [unknown] ([unknown])"
1557 $ perf script -i inj --itrace=ce -F+machine_pid,+vcpu,+addr,+pid,+tid,-period --ns --time 7919.408803365,7919.408804631 -C 2
1559 CPU 3/KVM 13376/13384 [002] 7919.408803365: branches: ffffffffc0f8ebe0 vmx_vcpu_enter_exit+0xc0 ([kernel.kallsyms]) => ffffffffc0f8edc0 __vmx_vcpu_run+0x0 ([kernel.kallsyms])
1560 CPU 3/KVM 13376/13384 [002] 7919.408803365: branches: ffffffffc0f8edd5 __vmx_vcpu_run+0x15 ([kernel.kallsyms]) => ffffffffc0f8eca0 vmx_update_host_rsp+0x0 ([kernel.kallsyms])
1561 CPU 3/KVM 13376/13384 [002] 7919.408803365: branches: ffffffffc0f8ee1b __vmx_vcpu_run+0x5b ([kernel.kallsyms]) => ffffffffc0f8ed60 vmx_vmenter+0x0 ([kernel.kallsyms])
1562 CPU 3/KVM 13376/13384 [002] 7919.408803461: branches: ffffffffc0f8ed62 vmx_vmenter+0x2 ([kernel.kallsyms]) => 0 [unknown] ([unknown])
1563 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)
1564 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])
1565 CPU 3/KVM 13376/13384 [002] 7919.408803567: branches: 0 [unknown] ([unknown]) => ffffffffc0f8ed80 vmx_vmexit+0x0 ([kernel.kallsyms])
1566 CPU 3/KVM 13376/13384 [002] 7919.408803596: branches: ffffffffc0f6619a vmx_vcpu_run+0x26a ([kernel.kallsyms]) => ffffffffb2255c60 x86_virt_spec_ctrl+0x0 ([kernel.kallsyms])
1567 CPU 3/KVM 13376/13384 [002] 7919.408803801: branches: ffffffffc0f66445 vmx_vcpu_run+0x515 ([kernel.kallsyms]) => ffffffffb2290b30 native_write_msr+0x0 ([kernel.kallsyms])
1568 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])
1569 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])
1570 CPU 3/KVM 13376/13384 [002] 7919.408803862: branches: ffffffffc0f662cf vmx_vcpu_run+0x39f ([kernel.kallsyms]) => ffffffffc0f63f90 vmx_recover_nmi_blocking+0x0 ([kernel.kallsyms])
1571 CPU 3/KVM 13376/13384 [002] 7919.408803862: branches: ffffffffc0f662e9 vmx_vcpu_run+0x3b9 ([kernel.kallsyms]) => ffffffffc0f619a0 __vmx_complete_interrupts+0x0 ([kernel.kallsyms])
1572 CPU 3/KVM 13376/13384 [002] 7919.408803872: branches: ffffffffc109cfb2 vcpu_enter_guest+0x752 ([kernel.kallsyms]) => ffffffffc0f5f570 vmx_handle_exit_irqoff+0x0 ([kernel.kallsyms])
1573 CPU 3/KVM 13376/13384 [002] 7919.408803881: branches: ffffffffc109d028 vcpu_enter_guest+0x7c8 ([kernel.kallsyms]) => ffffffffb234f900 __srcu_read_lock+0x0 ([kernel.kallsyms])
1574 CPU 3/KVM 13376/13384 [002] 7919.408803897: branches: ffffffffc109d06f vcpu_enter_guest+0x80f ([kernel.kallsyms]) => ffffffffc0f72e30 vmx_handle_exit+0x0 ([kernel.kallsyms])
1575 CPU 3/KVM 13376/13384 [002] 7919.408803897: branches: ffffffffc0f72e3d vmx_handle_exit+0xd ([kernel.kallsyms]) => ffffffffc0f727c0 __vmx_handle_exit+0x0 ([kernel.kallsyms])
1576 CPU 3/KVM 13376/13384 [002] 7919.408803897: branches: ffffffffc0f72b15 __vmx_handle_exit+0x355 ([kernel.kallsyms]) => ffffffffc0f60ae0 vmx_flush_pml_buffer+0x0 ([kernel.kallsyms])
1577 CPU 3/KVM 13376/13384 [002] 7919.408803903: branches: ffffffffc0f72994 __vmx_handle_exit+0x1d4 ([kernel.kallsyms]) => ffffffffc10b7090 kvm_emulate_cpuid+0x0 ([kernel.kallsyms])
1578 CPU 3/KVM 13376/13384 [002] 7919.408803903: branches: ffffffffc10b70f1 kvm_emulate_cpuid+0x61 ([kernel.kallsyms]) => ffffffffc10b6e10 kvm_cpuid+0x0 ([kernel.kallsyms])
1579 CPU 3/KVM 13376/13384 [002] 7919.408803941: branches: ffffffffc10b7125 kvm_emulate_cpuid+0x95 ([kernel.kallsyms]) => ffffffffc1093110 kvm_skip_emulated_instruction+0x0 ([kernel.kallsyms])
1580 CPU 3/KVM 13376/13384 [002] 7919.408803941: branches: ffffffffc109311f kvm_skip_emulated_instruction+0xf ([kernel.kallsyms]) => ffffffffc0f5e180 vmx_get_rflags+0x0 ([kernel.kallsyms])
1581 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])
1582 CPU 3/KVM 13376/13384 [002] 7919.408803951: branches: ffffffffc0f5fd79 vmx_skip_emulated_instruction+0x49 ([kernel.kallsyms]) => ffffffffc0f5fb50 skip_emulated_instruction+0x0 ([kernel.kallsyms])
1583 CPU 3/KVM 13376/13384 [002] 7919.408803956: branches: ffffffffc0f5fc68 skip_emulated_instruction+0x118 ([kernel.kallsyms]) => ffffffffc0f6a940 vmx_cache_reg+0x0 ([kernel.kallsyms])
1584 CPU 3/KVM 13376/13384 [002] 7919.408803964: branches: ffffffffc0f5fc11 skip_emulated_instruction+0xc1 ([kernel.kallsyms]) => ffffffffc0f5f9e0 vmx_set_interrupt_shadow+0x0 ([kernel.kallsyms])
1585 CPU 3/KVM 13376/13384 [002] 7919.408803980: branches: ffffffffc109f8b1 vcpu_run+0x71 ([kernel.kallsyms]) => ffffffffc10ad2f0 kvm_cpu_has_pending_timer+0x0 ([kernel.kallsyms])
1586 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])
1587 CPU 3/KVM 13376/13384 [002] 7919.408803991: branches: ffffffffc109f899 vcpu_run+0x59 ([kernel.kallsyms]) => ffffffffc109c860 vcpu_enter_guest+0x0 ([kernel.kallsyms])
1588 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])
1589 CPU 3/KVM 13376/13384 [002] 7919.408803996: branches: ffffffffc109cd7d vcpu_enter_guest+0x51d ([kernel.kallsyms]) => ffffffffb234f930 __srcu_read_unlock+0x0 ([kernel.kallsyms])
1590 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])
1591 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])
1592 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])
1593 CPU 3/KVM 13376/13384 [002] 7919.408804019: branches: ffffffffc109ceca vcpu_enter_guest+0x66a ([kernel.kallsyms]) => ffffffffb2249840 fpregs_assert_state_consistent+0x0 ([kernel.kallsyms])
1594 CPU 3/KVM 13376/13384 [002] 7919.408804021: branches: ffffffffc109cf10 vcpu_enter_guest+0x6b0 ([kernel.kallsyms]) => ffffffffc0f65f30 vmx_vcpu_run+0x0 ([kernel.kallsyms])
1595 CPU 3/KVM 13376/13384 [002] 7919.408804024: branches: ffffffffc0f6603b vmx_vcpu_run+0x10b ([kernel.kallsyms]) => ffffffffb229bed0 __get_current_cr3_fast+0x0 ([kernel.kallsyms])
1596 CPU 3/KVM 13376/13384 [002] 7919.408804024: branches: ffffffffc0f66055 vmx_vcpu_run+0x125 ([kernel.kallsyms]) => ffffffffb2253050 cr4_read_shadow+0x0 ([kernel.kallsyms])
1597 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])
1598 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])
1599 CPU 3/KVM 13376/13384 [002] 7919.408804032: branches: ffffffffc0f660c6 vmx_vcpu_run+0x196 ([kernel.kallsyms]) => ffffffffb22061a0 perf_guest_get_msrs+0x0 ([kernel.kallsyms])
1600 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])
1601 CPU 3/KVM 13376/13384 [002] 7919.408804039: branches: ffffffffc0f66109 vmx_vcpu_run+0x1d9 ([kernel.kallsyms]) => ffffffffc0f652c0 clear_atomic_switch_msr+0x0 ([kernel.kallsyms])
1602 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])
1603 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])
1604 CPU 3/KVM 13376/13384 [002] 7919.408804045: branches: ffffffffc0f66454 vmx_vcpu_run+0x524 ([kernel.kallsyms]) => ffffffffc0f61ff0 vmx_update_hv_timer+0x0 ([kernel.kallsyms])
1605 CPU 3/KVM 13376/13384 [002] 7919.408804057: branches: ffffffffc0f66142 vmx_vcpu_run+0x212 ([kernel.kallsyms]) => ffffffffc10af100 kvm_wait_lapic_expire+0x0 ([kernel.kallsyms])
1606 CPU 3/KVM 13376/13384 [002] 7919.408804057: branches: ffffffffc0f66156 vmx_vcpu_run+0x226 ([kernel.kallsyms]) => ffffffffb2255c60 x86_virt_spec_ctrl+0x0 ([kernel.kallsyms])
1607 CPU 3/KVM 13376/13384 [002] 7919.408804057: branches: ffffffffc0f66161 vmx_vcpu_run+0x231 ([kernel.kallsyms]) => ffffffffc0f8eb20 vmx_vcpu_enter_exit+0x0 ([kernel.kallsyms])
1608 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])
1609 CPU 3/KVM 13376/13384 [002] 7919.408804057: branches: ffffffffb2353e1c rcu_note_context_switch+0xc ([kernel.kallsyms]) => ffffffffb2353db0 rcu_qs+0x0 ([kernel.kallsyms])
1610 CPU 3/KVM 13376/13384 [002] 7919.408804066: branches: ffffffffc0f8ebe0 vmx_vcpu_enter_exit+0xc0 ([kernel.kallsyms]) => ffffffffc0f8edc0 __vmx_vcpu_run+0x0 ([kernel.kallsyms])
1611 CPU 3/KVM 13376/13384 [002] 7919.408804066: branches: ffffffffc0f8edd5 __vmx_vcpu_run+0x15 ([kernel.kallsyms]) => ffffffffc0f8eca0 vmx_update_host_rsp+0x0 ([kernel.kallsyms])
1612 CPU 3/KVM 13376/13384 [002] 7919.408804066: branches: ffffffffc0f8ee1b __vmx_vcpu_run+0x5b ([kernel.kallsyms]) => ffffffffc0f8ed60 vmx_vmenter+0x0 ([kernel.kallsyms])
1613 CPU 3/KVM 13376/13384 [002] 7919.408804162: branches: ffffffffc0f8ed62 vmx_vmenter+0x2 ([kernel.kallsyms]) => 0 [unknown] ([unknown])
1614 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)
1615 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)
1616 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])
1617 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])
1618 VM:13376 VCPU:003 uname 3404/3404 [002] 7919.408804534: branches: ffffffff832012fa error_entry+0x6a ([kernel.kallsyms]) => ffffffff830b59a0 sync_regs+0x0 ([kernel.kallsyms])
1619 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])
1620 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])
1621 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])
1622
1624 A common case for KVM test programs is that the test program acts as
1625 the hypervisor, creating, running and destroying the virtual machine,
1626 and providing the guest object code from its own object code. In this
1627 case, the VM is not running an OS, but only the functions loaded into
1628 it by the hypervisor test program, and conveniently, loaded at the same
1629 virtual addresses. To support that, option "--guest-code" has been
1630 added to perf script and perf kvm report.
1631 Here is an example tracing a test program from the kernel’s KVM
1633 selftests:
1634 # perf record --kcore -e intel_pt/cyc/ -- tools/testing/selftests/kselftest_install/kvm/tsc_msrs_test
1636 [ perf record: Woken up 1 times to write data ]
1637 [ perf record: Captured and wrote 0.280 MB perf.data ]
1638 # perf script --guest-code --itrace=bep --ns -F-period,+addr,+flags
1639 [SNIP]
1640 tsc_msrs_test 18436 [007] 10897.962087733: branches: call ffffffffc13b2ff5 __vmx_vcpu_run+0x15 (vmlinux) => ffffffffc13b2f50 vmx_update_host_rsp+0x0 (vmlinux)
1641 tsc_msrs_test 18436 [007] 10897.962087733: branches: return ffffffffc13b2f5d vmx_update_host_rsp+0xd (vmlinux) => ffffffffc13b2ffa __vmx_vcpu_run+0x1a (vmlinux)
1642 tsc_msrs_test 18436 [007] 10897.962087733: branches: call ffffffffc13b303b __vmx_vcpu_run+0x5b (vmlinux) => ffffffffc13b2f80 vmx_vmenter+0x0 (vmlinux)
1643 tsc_msrs_test 18436 [007] 10897.962087836: branches: vmentry ffffffffc13b2f82 vmx_vmenter+0x2 (vmlinux) => 0 [unknown] ([unknown])
1644 [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)
1645 [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)
1646 [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])
1647 tsc_msrs_test 18436 [007] 10897.962088248: branches: vmexit 0 [unknown] ([unknown]) => ffffffffc13b2fa0 vmx_vmexit+0x0 (vmlinux)
1648 tsc_msrs_test 18436 [007] 10897.962088248: branches: jmp ffffffffc13b2fa0 vmx_vmexit+0x0 (vmlinux) => ffffffffc13b2fd2 vmx_vmexit+0x32 (vmlinux)
1649 tsc_msrs_test 18436 [007] 10897.962088256: branches: return ffffffffc13b2fd2 vmx_vmexit+0x32 (vmlinux) => ffffffffc13b3040 __vmx_vcpu_run+0x60 (vmlinux)
1650 tsc_msrs_test 18436 [007] 10897.962088270: branches: return ffffffffc13b30b6 __vmx_vcpu_run+0xd6 (vmlinux) => ffffffffc13b2f2e vmx_vcpu_enter_exit+0x4e (vmlinux)
1651 [SNIP]
1652 tsc_msrs_test 18436 [007] 10897.962089321: branches: call ffffffffc13b2ff5 __vmx_vcpu_run+0x15 (vmlinux) => ffffffffc13b2f50 vmx_update_host_rsp+0x0 (vmlinux)
1653 tsc_msrs_test 18436 [007] 10897.962089321: branches: return ffffffffc13b2f5d vmx_update_host_rsp+0xd (vmlinux) => ffffffffc13b2ffa __vmx_vcpu_run+0x1a (vmlinux)
1654 tsc_msrs_test 18436 [007] 10897.962089321: branches: call ffffffffc13b303b __vmx_vcpu_run+0x5b (vmlinux) => ffffffffc13b2f80 vmx_vmenter+0x0 (vmlinux)
1655 tsc_msrs_test 18436 [007] 10897.962089424: branches: vmentry ffffffffc13b2f82 vmx_vmenter+0x2 (vmlinux) => 0 [unknown] ([unknown])
1656 [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)
1657 [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)
1658 [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)
1659 [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)
1660 [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)
1661 [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])
1662 tsc_msrs_test 18436 [007] 10897.962089878: branches: vmexit 0 [unknown] ([unknown]) => ffffffffc13b2fa0 vmx_vmexit+0x0 (vmlinux)
1663 tsc_msrs_test 18436 [007] 10897.962089878: branches: jmp ffffffffc13b2fa0 vmx_vmexit+0x0 (vmlinux) => ffffffffc13b2fd2 vmx_vmexit+0x32 (vmlinux)
1664 tsc_msrs_test 18436 [007] 10897.962089887: branches: return ffffffffc13b2fd2 vmx_vmexit+0x32 (vmlinux) => ffffffffc13b3040 __vmx_vcpu_run+0x60 (vmlinux)
1665 tsc_msrs_test 18436 [007] 10897.962089901: branches: return ffffffffc13b30b6 __vmx_vcpu_run+0xd6 (vmlinux) => ffffffffc13b2f2e vmx_vcpu_enter_exit+0x4e (vmlinux)
1666 [SNIP]
1667 # perf kvm --guest-code --guest --host report -i perf.data --stdio | head -20
1669 # To display the perf.data header info, please use --header/--header-only options.
1671 #
1672 #
1673 # Total Lost Samples: 0
1674 #
1675 # Samples: 12 of event 'instructions'
1676 # Event count (approx.): 2274583
1677 #
1678 # Children Self Command Shared Object Symbol
1679 # ........ ........ ............. .................... ...........................................
1680 #
1681 54.70% 0.00% tsc_msrs_test [kernel.vmlinux] [k] entry_SYSCALL_64_after_hwframe
1682 |
1683 ---entry_SYSCALL_64_after_hwframe
1684 do_syscall_64
1685 |
1686 |--29.44%--syscall_exit_to_user_mode
1687 | exit_to_user_mode_prepare
1688 | task_work_run
1689 | __fput
1690
1692 Event Trace records information about asynchronous events, for example
1693 interrupts, faults, VM exits and entries. The information is recorded
1694 in CFE and EVD packets, and also the Interrupt Flag is recorded on the
1695 MODE.Exec packet. The CFE packet contains a type field to identify one
1696 of the following:
1697 1 INTR interrupt, fault, exception, NMI
1699 2 IRET interrupt return
1700 3 SMI system management interrupt
1701 4 RSM resume from system management mode
1702 5 SIPI startup interprocessor interrupt
1703 6 INIT INIT signal
1704 7 VMENTRY VM-Entry
1705 8 VMEXIT VM-Entry
1706 9 VMEXIT_INTR VM-Exit due to interrupt
1707 10 SHUTDOWN Shutdown
1708 For more details, refer to the Intel 64 and IA-32 Architectures
1710 Software Developer Manuals (version 076 or later).
1711 The capability to do Event Trace is indicated by the
1713 /sys/bus/event_source/devices/intel_pt/caps/event_trace file.
1714 Event trace is selected for recording using the "event" config term.
1716 e.g.
1717 perf record -e intel_pt/event/u uname
1719 Event trace events are output using the --itrace I option. e.g.
1721 perf script --itrace=Ie
1723 perf script displays events containing CFE type, vector and event data,
1725 in the form:
1726 evt: hw int (t) cfe: INTR IP: 1 vector: 3 PFA: 0x8877665544332211
1728 The IP flag indicates if the event binds to an IP, which includes any
1730 case where flow control packet generation is enabled, as well as when
1731 CFE packet IP bit is set.
1732 perf script displays events containing changes to the Interrupt Flag in
1734 the form:
1735 iflag: t IFLAG: 1->0 via branch
1737 where "via branch" indicates a branch (interrupt or return from
1739 interrupt) and "non branch" indicates an instruction such as CFI, STI
1740 or POPF).
1741 In addition, the current state of the interrupt flag is indicated by
1743 the presence or absence of the "D" (interrupt disabled) perf script
1744 flag. If the interrupt flag is changed, then the "t" flag is also
1745 included i.e.
1746 no flag, interrupts enabled IF=1
1748 t interrupts become disabled IF=1 -> IF=0
1749 D interrupts are disabled IF=0
1750 Dt interrupts become enabled IF=0 -> IF=1
1751 The intel-pt-events.py script illustrates how to access Event Trace
1753 information using a Python script.
1754
1756 TNT packets are disabled using the "notnt" config term. e.g.
1757 perf record -e intel_pt/notnt/u uname
1759 In that case the --itrace q option is forced because walking executable
1761 code to reconstruct the control flow is not possible.
1762
1764 Later perf tools support a method to emulate the ptwrite instruction,
1765 which can be useful if hardware does not support the ptwrite
1766 instruction.
1767 Instead of using the ptwrite instruction, a function is used which
1769 produces a trace that encodes the payload data into TNT packets. Here
1770 is an example of the function:
1771 #include <stdint.h>
1773 void perf_emulate_ptwrite(uint64_t x)
1775 __attribute__((externally_visible, noipa, no_instrument_function, naked));
1776 #define PERF_EMULATE_PTWRITE_8_BITS \
1778 "1: shl %rax\n" \
1779 " jc 1f\n" \
1780 "1: shl %rax\n" \
1781 " jc 1f\n" \
1782 "1: shl %rax\n" \
1783 " jc 1f\n" \
1784 "1: shl %rax\n" \
1785 " jc 1f\n" \
1786 "1: shl %rax\n" \
1787 " jc 1f\n" \
1788 "1: shl %rax\n" \
1789 " jc 1f\n" \
1790 "1: shl %rax\n" \
1791 " jc 1f\n" \
1792 "1: shl %rax\n" \
1793 " jc 1f\n"
1794 /* Undefined instruction */
1796 #define PERF_EMULATE_PTWRITE_UD2 ".byte 0x0f, 0x0b\n"
1797 #define PERF_EMULATE_PTWRITE_MAGIC PERF_EMULATE_PTWRITE_UD2 ".ascii \"perf,ptwrite \"\n"
1799 void perf_emulate_ptwrite(uint64_t x __attribute__ ((__unused__)))
1801 {
1802 /* Assumes SysV ABI : x passed in rdi */
1803 __asm__ volatile (
1804 "jmp 1f\n"
1805 PERF_EMULATE_PTWRITE_MAGIC
1806 "1: mov %rdi, %rax\n"
1807 PERF_EMULATE_PTWRITE_8_BITS
1808 PERF_EMULATE_PTWRITE_8_BITS
1809 PERF_EMULATE_PTWRITE_8_BITS
1810 PERF_EMULATE_PTWRITE_8_BITS
1811 PERF_EMULATE_PTWRITE_8_BITS
1812 PERF_EMULATE_PTWRITE_8_BITS
1813 PERF_EMULATE_PTWRITE_8_BITS
1814 PERF_EMULATE_PTWRITE_8_BITS
1815 "1: ret\n"
1816 );
1817 }
1818 For example, a test program with the function above:
1820 #include <stdio.h>
1822 #include <stdint.h>
1823 #include <stdlib.h>
1824 #include "perf_emulate_ptwrite.h"
1826 int main(int argc, char *argv[])
1828 {
1829 uint64_t x = 0;
1830 if (argc > 1)
1832 x = strtoull(argv[1], NULL, 0);
1833 perf_emulate_ptwrite(x);
1834 return 0;
1835 }
1836 Can be compiled and traced:
1838 $ gcc -Wall -Wextra -O3 -g -o eg_ptw eg_ptw.c
1840 $ perf record -e intel_pt//u ./eg_ptw 0x1234567890abcdef
1841 [ perf record: Woken up 1 times to write data ]
1842 [ perf record: Captured and wrote 0.017 MB perf.data ]
1843 $ perf script --itrace=ew
1844 eg_ptw 19875 [007] 8061.235912: ptwrite: IP: 0 payload: 0x1234567890abcdef 55701249a196 perf_emulate_ptwrite+0x16 (/home/user/eg_ptw)
1845 $
1846
1848 Pipe mode is a problem for Intel PT and possibly other auxtrace users.
1849 It’s not recommended to use a pipe as data output with Intel PT because
1850 of the following reason.
1851 Essentially the auxtrace buffers do not behave like the regular perf
1853 event buffers. That is because the head and tail are updated by
1854 software, but in the auxtrace case the data is written by hardware. So
1855 the head and tail do not get updated as data is written.
1856 In the Intel PT case, the head and tail are updated only when the trace
1858 is disabled by software, for example: - full-trace, system wide : when
1859 buffer passes watermark - full-trace, not system-wide : when buffer
1860 passes watermark or context switches - snapshot mode : as above but
1861 also when a snapshot is made - sample mode : as above but also when a
1862 sample is made
1863 That means finished-round ordering doesn’t work. An auxtrace buffer can
1865 turn up that has data that extends back in time, possibly to the very
1866 beginning of tracing.
1867 For a perf.data file, that problem is solved by going through the trace
1869 and queuing up the auxtrace buffers in advance.
1870 For pipe mode, the order of events and timestamps can presumably be
1872 messed up.
1873
1875 Examples can be found on perf wiki page "Perf tools support for Intel®
1876 Processor Trace":
1877 https://perf.wiki.kernel.org/index.php/Perf_tools_support_for_Intel%C2%AE_Processor_Trace
1879
1881 perf-record(1), perf-script(1), perf-report(1), perf-inject(1)
1882perf 11/28/2023 PERF-INTEL-PT(1)