1perf-intel-pt(1) 2================ 3 4NAME 5---- 6perf-intel-pt - Support for Intel Processor Trace within perf tools 7 8SYNOPSIS 9-------- 10[verse] 11'perf record' -e intel_pt// 12 13DESCRIPTION 14----------- 15 16Intel Processor Trace (Intel PT) is an extension of Intel Architecture that 17collects information about software execution such as control flow, execution 18modes and timings and formats it into highly compressed binary packets. 19Technical details are documented in the Intel 64 and IA-32 Architectures 20Software Developer Manuals, Chapter 36 Intel Processor Trace. 21 22Intel PT is first supported in Intel Core M and 5th generation Intel Core 23processors that are based on the Intel micro-architecture code name Broadwell. 24 25Trace data is collected by 'perf record' and stored within the perf.data file. 26See below for options to 'perf record'. 27 28Trace data must be 'decoded' which involves walking the object code and matching 29the trace data packets. For example a TNT packet only tells whether a 30conditional branch was taken or not taken, so to make use of that packet the 31decoder must know precisely which instruction was being executed. 32 33Decoding is done on-the-fly. The decoder outputs samples in the same format as 34samples output by perf hardware events, for example as though the "instructions" 35or "branches" events had been recorded. Presently 3 tools support this: 36'perf script', 'perf report' and 'perf inject'. See below for more information 37on using those tools. 38 39The main distinguishing feature of Intel PT is that the decoder can determine 40the exact flow of software execution. Intel PT can be used to understand why 41and how did software get to a certain point, or behave a certain way. The 42software does not have to be recompiled, so Intel PT works with debug or release 43builds, however the executed images are needed - which makes use in JIT-compiled 44environments, or with self-modified code, a challenge. Also symbols need to be 45provided to make sense of addresses. 46 47A 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 decode, 49for example two or three orders of magnitude longer than it took to collect. 50Another limitation is the performance impact of tracing, something that will 51vary depending on the use-case and architecture. 52 53 54Quickstart 55---------- 56 57It is important to start small. That is because it is easy to capture vastly 58more data than can possibly be processed. 59 60The simplest thing to do with Intel PT is userspace profiling of small programs. 61Data is captured with 'perf record' e.g. to trace 'ls' userspace-only: 62 63 perf record -e intel_pt//u ls 64 65And profiled with 'perf report' e.g. 66 67 perf report 68 69To also trace kernel space presents a problem, namely kernel self-modifying 70code. A fairly good kernel image is available in /proc/kcore but to get an 71accurate image a copy of /proc/kcore needs to be made under the same conditions 72as the data capture. 'perf record' can make a copy of /proc/kcore if the option 73--kcore is used, but access to /proc/kcore is restricted e.g. 74 75 sudo perf record -o pt_ls --kcore -e intel_pt// -- ls 76 77which will create a directory named 'pt_ls' and put the perf.data file (named 78simply 'data') and copies of /proc/kcore, /proc/kallsyms and /proc/modules into 79it. The other tools understand the directory format, so to use 'perf report' 80becomes: 81 82 sudo perf report -i pt_ls 83 84Because samples are synthesized after-the-fact, the sampling period can be 85selected for reporting. e.g. sample every microsecond 86 87 sudo perf report pt_ls --itrace=i1usge 88 89See the sections below for more information about the --itrace option. 90 91Beware the smaller the period, the more samples that are produced, and the 92longer it takes to process them. 93 94Also note that the coarseness of Intel PT timing information will start to 95distort the statistical value of the sampling as the sampling period becomes 96smaller. 97 98To represent software control flow, "branches" samples are produced. By default 99a branch sample is synthesized for every single branch. To get an idea what 100data is available you can use the 'perf script' tool with all itrace sampling 101options, which will list all the samples. 102 103 perf record -e intel_pt//u ls 104 perf script --itrace=ibxwpe 105 106An interesting field that is not printed by default is 'flags' which can be 107displayed as follows: 108 109 perf script --itrace=ibxwpe -F+flags 110 111The flags are "bcrosyiABExgh" which stand for branch, call, return, conditional, 112system, asynchronous, interrupt, transaction abort, trace begin, trace end, 113in transaction, VM-entry, and VM-exit respectively. 114 115perf script also supports higher level ways to dump instruction traces: 116 117 perf script --insn-trace --xed 118 119Dump all instructions. This requires installing the xed tool (see XED below) 120Dumping all instructions in a long trace can be fairly slow. It is usually better 121to start with higher level decoding, like 122 123 perf script --call-trace 124 125or 126 127 perf script --call-ret-trace 128 129and then select a time range of interest. The time range can then be examined 130in detail with 131 132 perf script --time starttime,stoptime --insn-trace --xed 133 134While examining the trace it's also useful to filter on specific CPUs using 135the -C option 136 137 perf script --time starttime,stoptime --insn-trace --xed -C 1 138 139Dump all instructions in time range on CPU 1. 140 141Another interesting field that is not printed by default is 'ipc' which can be 142displayed as follows: 143 144 perf script --itrace=be -F+ipc 145 146There are two ways that instructions-per-cycle (IPC) can be calculated depending 147on the recording. 148 149If the 'cyc' config term (see config terms section below) was used, then IPC is 150calculated using the cycle count from CYC packets, otherwise MTC packets are 151used - refer to the 'mtc' config term. When MTC is used, however, the values 152are less accurate because the timing is less accurate. 153 154Because Intel PT does not update the cycle count on every branch or instruction, 155the values will often be zero. When there are values, they will be the number 156of instructions and number of cycles since the last update, and thus represent 157the average IPC since the last IPC for that event type. Note IPC for "branches" 158events is calculated separately from IPC for "instructions" events. 159 160Also note that the IPC instruction count may or may not include the current 161instruction. If the cycle count is associated with an asynchronous branch 162(e.g. page fault or interrupt), then the instruction count does not include the 163current instruction, otherwise it does. That is consistent with whether or not 164that instruction has retired when the cycle count is updated. 165 166Another note, in the case of "branches" events, non-taken branches are not 167presently sampled, so IPC values for them do not appear e.g. a CYC packet with a 168TNT packet that starts with a non-taken branch. To see every possible IPC 169value, "instructions" events can be used e.g. --itrace=i0ns 170 171While it is possible to create scripts to analyze the data, an alternative 172approach is available to export the data to a sqlite or postgresql database. 173Refer to script export-to-sqlite.py or export-to-postgresql.py for more details, 174and to script exported-sql-viewer.py for an example of using the database. 175 176There is also script intel-pt-events.py which provides an example of how to 177unpack the raw data for power events and PTWRITE. The script also displays 178branches, and supports 2 additional modes selected by option: 179 180 --insn-trace - instruction trace 181 --src-trace - source trace 182 183As mentioned above, it is easy to capture too much data. One way to limit the 184data captured is to use 'snapshot' mode which is explained further below. 185Refer to 'new snapshot option' and 'Intel PT modes of operation' further below. 186 187Another problem that will be experienced is decoder errors. They can be caused 188by inability to access the executed image, self-modified or JIT-ed code, or the 189inability to match side-band information (such as context switches and mmaps) 190which results in the decoder not knowing what code was executed. 191 192There is also the problem of perf not being able to copy the data fast enough, 193resulting in data lost because the buffer was full. See 'Buffer handling' below 194for more details. 195 196 197perf record 198----------- 199 200new event 201~~~~~~~~~ 202 203The Intel PT kernel driver creates a new PMU for Intel PT. PMU events are 204selected by providing the PMU name followed by the "config" separated by slashes. 205An enhancement has been made to allow default "config" e.g. the option 206 207 -e intel_pt// 208 209will use a default config value. Currently that is the same as 210 211 -e intel_pt/tsc,noretcomp=0/ 212 213which is the same as 214 215 -e intel_pt/tsc=1,noretcomp=0/ 216 217Note there are now new config terms - see section 'config terms' further below. 218 219The config terms are listed in /sys/devices/intel_pt/format. They are bit 220fields within the config member of the struct perf_event_attr which is 221passed to the kernel by the perf_event_open system call. They correspond to bit 222fields in the IA32_RTIT_CTL MSR. Here is a list of them and their definitions: 223 224 $ grep -H . /sys/bus/event_source/devices/intel_pt/format/* 225 /sys/bus/event_source/devices/intel_pt/format/cyc:config:1 226 /sys/bus/event_source/devices/intel_pt/format/cyc_thresh:config:19-22 227 /sys/bus/event_source/devices/intel_pt/format/mtc:config:9 228 /sys/bus/event_source/devices/intel_pt/format/mtc_period:config:14-17 229 /sys/bus/event_source/devices/intel_pt/format/noretcomp:config:11 230 /sys/bus/event_source/devices/intel_pt/format/psb_period:config:24-27 231 /sys/bus/event_source/devices/intel_pt/format/tsc:config:10 232 233Note that the default config must be overridden for each term i.e. 234 235 -e intel_pt/noretcomp=0/ 236 237is the same as: 238 239 -e intel_pt/tsc=1,noretcomp=0/ 240 241So, to disable TSC packets use: 242 243 -e intel_pt/tsc=0/ 244 245It is also possible to specify the config value explicitly: 246 247 -e intel_pt/config=0x400/ 248 249Note that, as with all events, the event is suffixed with event modifiers: 250 251 u userspace 252 k kernel 253 h hypervisor 254 G guest 255 H host 256 p precise ip 257 258'h', 'G' and 'H' are for virtualization which is not supported by Intel PT. 259'p' is also not relevant to Intel PT. So only options 'u' and 'k' are 260meaningful for Intel PT. 261 262perf_event_attr is displayed if the -vv option is used e.g. 263 264 ------------------------------------------------------------ 265 perf_event_attr: 266 type 6 267 size 112 268 config 0x400 269 { sample_period, sample_freq } 1 270 sample_type IP|TID|TIME|CPU|IDENTIFIER 271 read_format ID 272 disabled 1 273 inherit 1 274 exclude_kernel 1 275 exclude_hv 1 276 enable_on_exec 1 277 sample_id_all 1 278 ------------------------------------------------------------ 279 sys_perf_event_open: pid 31104 cpu 0 group_fd -1 flags 0x8 280 sys_perf_event_open: pid 31104 cpu 1 group_fd -1 flags 0x8 281 sys_perf_event_open: pid 31104 cpu 2 group_fd -1 flags 0x8 282 sys_perf_event_open: pid 31104 cpu 3 group_fd -1 flags 0x8 283 ------------------------------------------------------------ 284 285 286config terms 287~~~~~~~~~~~~ 288 289The June 2015 version of Intel 64 and IA-32 Architectures Software Developer 290Manuals, Chapter 36 Intel Processor Trace, defined new Intel PT features. 291Some of the features are reflect in new config terms. All the config terms are 292described below. 293 294tsc Always supported. Produces TSC timestamp packets to provide 295 timing information. In some cases it is possible to decode 296 without timing information, for example a per-thread context 297 that does not overlap executable memory maps. 298 299 The default config selects tsc (i.e. tsc=1). 300 301noretcomp Always supported. Disables "return compression" so a TIP packet 302 is produced when a function returns. Causes more packets to be 303 produced but might make decoding more reliable. 304 305 The default config does not select noretcomp (i.e. noretcomp=0). 306 307psb_period Allows the frequency of PSB packets to be specified. 308 309 The PSB packet is a synchronization packet that provides a 310 starting point for decoding or recovery from errors. 311 312 Support for psb_period is indicated by: 313 314 /sys/bus/event_source/devices/intel_pt/caps/psb_cyc 315 316 which contains "1" if the feature is supported and "0" 317 otherwise. 318 319 Valid values are given by: 320 321 /sys/bus/event_source/devices/intel_pt/caps/psb_periods 322 323 which contains a hexadecimal value, the bits of which represent 324 valid values e.g. bit 2 set means value 2 is valid. 325 326 The psb_period value is converted to the approximate number of 327 trace bytes between PSB packets as: 328 329 2 ^ (value + 11) 330 331 e.g. value 3 means 16KiB bytes between PSBs 332 333 If an invalid value is entered, the error message 334 will give a list of valid values e.g. 335 336 $ perf record -e intel_pt/psb_period=15/u uname 337 Invalid psb_period for intel_pt. Valid values are: 0-5 338 339 If MTC packets are selected, the default config selects a value 340 of 3 (i.e. psb_period=3) or the nearest lower value that is 341 supported (0 is always supported). Otherwise the default is 0. 342 343 If decoding is expected to be reliable and the buffer is large 344 then a large PSB period can be used. 345 346 Because a TSC packet is produced with PSB, the PSB period can 347 also affect the granularity to timing information in the absence 348 of MTC or CYC. 349 350mtc Produces MTC timing packets. 351 352 MTC packets provide finer grain timestamp information than TSC 353 packets. MTC packets record time using the hardware crystal 354 clock (CTC) which is related to TSC packets using a TMA packet. 355 356 Support for this feature is indicated by: 357 358 /sys/bus/event_source/devices/intel_pt/caps/mtc 359 360 which contains "1" if the feature is supported and 361 "0" otherwise. 362 363 The frequency of MTC packets can also be specified - see 364 mtc_period below. 365 366mtc_period Specifies how frequently MTC packets are produced - see mtc 367 above for how to determine if MTC packets are supported. 368 369 Valid values are given by: 370 371 /sys/bus/event_source/devices/intel_pt/caps/mtc_periods 372 373 which contains a hexadecimal value, the bits of which represent 374 valid values e.g. bit 2 set means value 2 is valid. 375 376 The mtc_period value is converted to the MTC frequency as: 377 378 CTC-frequency / (2 ^ value) 379 380 e.g. value 3 means one eighth of CTC-frequency 381 382 Where CTC is the hardware crystal clock, the frequency of which 383 can be related to TSC via values provided in cpuid leaf 0x15. 384 385 If an invalid value is entered, the error message 386 will give a list of valid values e.g. 387 388 $ perf record -e intel_pt/mtc_period=15/u uname 389 Invalid mtc_period for intel_pt. Valid values are: 0,3,6,9 390 391 The default value is 3 or the nearest lower value 392 that is supported (0 is always supported). 393 394cyc Produces CYC timing packets. 395 396 CYC packets provide even finer grain timestamp information than 397 MTC and TSC packets. A CYC packet contains the number of CPU 398 cycles since the last CYC packet. Unlike MTC and TSC packets, 399 CYC packets are only sent when another packet is also sent. 400 401 Support for this feature is indicated by: 402 403 /sys/bus/event_source/devices/intel_pt/caps/psb_cyc 404 405 which contains "1" if the feature is supported and 406 "0" otherwise. 407 408 The number of CYC packets produced can be reduced by specifying 409 a threshold - see cyc_thresh below. 410 411cyc_thresh Specifies how frequently CYC packets are produced - see cyc 412 above for how to determine if CYC packets are supported. 413 414 Valid cyc_thresh values are given by: 415 416 /sys/bus/event_source/devices/intel_pt/caps/cycle_thresholds 417 418 which contains a hexadecimal value, the bits of which represent 419 valid values e.g. bit 2 set means value 2 is valid. 420 421 The cyc_thresh value represents the minimum number of CPU cycles 422 that must have passed before a CYC packet can be sent. The 423 number of CPU cycles is: 424 425 2 ^ (value - 1) 426 427 e.g. value 4 means 8 CPU cycles must pass before a CYC packet 428 can be sent. Note a CYC packet is still only sent when another 429 packet is sent, not at, e.g. every 8 CPU cycles. 430 431 If an invalid value is entered, the error message 432 will give a list of valid values e.g. 433 434 $ perf record -e intel_pt/cyc,cyc_thresh=15/u uname 435 Invalid cyc_thresh for intel_pt. Valid values are: 0-12 436 437 CYC packets are not requested by default. 438 439pt Specifies pass-through which enables the 'branch' config term. 440 441 The default config selects 'pt' if it is available, so a user will 442 never need to specify this term. 443 444branch Enable branch tracing. Branch tracing is enabled by default so to 445 disable branch tracing use 'branch=0'. 446 447 The default config selects 'branch' if it is available. 448 449ptw Enable PTWRITE packets which are produced when a ptwrite instruction 450 is executed. 451 452 Support for this feature is indicated by: 453 454 /sys/bus/event_source/devices/intel_pt/caps/ptwrite 455 456 which contains "1" if the feature is supported and 457 "0" otherwise. 458 459fup_on_ptw Enable a FUP packet to follow the PTWRITE packet. The FUP packet 460 provides the address of the ptwrite instruction. In the absence of 461 fup_on_ptw, the decoder will use the address of the previous branch 462 if branch tracing is enabled, otherwise the address will be zero. 463 Note that fup_on_ptw will work even when branch tracing is disabled. 464 465pwr_evt Enable power events. The power events provide information about 466 changes to the CPU C-state. 467 468 Support for this feature is indicated by: 469 470 /sys/bus/event_source/devices/intel_pt/caps/power_event_trace 471 472 which contains "1" if the feature is supported and 473 "0" otherwise. 474 475 476AUX area sampling option 477~~~~~~~~~~~~~~~~~~~~~~~~ 478 479To select Intel PT "sampling" the AUX area sampling option can be used: 480 481 --aux-sample 482 483Optionally it can be followed by the sample size in bytes e.g. 484 485 --aux-sample=8192 486 487In addition, the Intel PT event to sample must be defined e.g. 488 489 -e intel_pt//u 490 491Samples on other events will be created containing Intel PT data e.g. the 492following will create Intel PT samples on the branch-misses event, note the 493events must be grouped using {}: 494 495 perf record --aux-sample -e '{intel_pt//u,branch-misses:u}' 496 497An alternative to '--aux-sample' is to add the config term 'aux-sample-size' to 498events. In this case, the grouping is implied e.g. 499 500 perf record -e intel_pt//u -e branch-misses/aux-sample-size=8192/u 501 502is the same as: 503 504 perf record -e '{intel_pt//u,branch-misses/aux-sample-size=8192/u}' 505 506but allows for also using an address filter e.g.: 507 508 perf record -e intel_pt//u --filter 'filter * @/bin/ls' -e branch-misses/aux-sample-size=8192/u -- ls 509 510It is important to select a sample size that is big enough to contain at least 511one PSB packet. If not a warning will be displayed: 512 513 Intel PT sample size (%zu) may be too small for PSB period (%zu) 514 515The calculation used for that is: if sample_size <= psb_period + 256 display the 516warning. When sampling is used, psb_period defaults to 0 (2KiB). 517 518The default sample size is 4KiB. 519 520The sample size is passed in aux_sample_size in struct perf_event_attr. The 521sample size is limited by the maximum event size which is 64KiB. It is 522difficult to know how big the event might be without the trace sample attached, 523but the tool validates that the sample size is not greater than 60KiB. 524 525 526new snapshot option 527~~~~~~~~~~~~~~~~~~~ 528 529The difference between full trace and snapshot from the kernel's perspective is 530that in full trace we don't overwrite trace data that the user hasn't collected 531yet (and indicated that by advancing aux_tail), whereas in snapshot mode we let 532the trace run and overwrite older data in the buffer so that whenever something 533interesting happens, we can stop it and grab a snapshot of what was going on 534around that interesting moment. 535 536To select snapshot mode a new option has been added: 537 538 -S 539 540Optionally it can be followed by the snapshot size e.g. 541 542 -S0x100000 543 544The default snapshot size is the auxtrace mmap size. If neither auxtrace mmap size 545nor snapshot size is specified, then the default is 4MiB for privileged users 546(or if /proc/sys/kernel/perf_event_paranoid < 0), 128KiB for unprivileged users. 547If an unprivileged user does not specify mmap pages, the mmap pages will be 548reduced as described in the 'new auxtrace mmap size option' section below. 549 550The snapshot size is displayed if the option -vv is used e.g. 551 552 Intel PT snapshot size: %zu 553 554 555new auxtrace mmap size option 556~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 557 558Intel PT buffer size is specified by an addition to the -m option e.g. 559 560 -m,16 561 562selects a buffer size of 16 pages i.e. 64KiB. 563 564Note that the existing functionality of -m is unchanged. The auxtrace mmap size 565is specified by the optional addition of a comma and the value. 566 567The default auxtrace mmap size for Intel PT is 4MiB/page_size for privileged users 568(or if /proc/sys/kernel/perf_event_paranoid < 0), 128KiB for unprivileged users. 569If an unprivileged user does not specify mmap pages, the mmap pages will be 570reduced from the default 512KiB/page_size to 256KiB/page_size, otherwise the 571user is likely to get an error as they exceed their mlock limit (Max locked 572memory as shown in /proc/self/limits). Note that perf does not count the first 573512KiB (actually /proc/sys/kernel/perf_event_mlock_kb minus 1 page) per cpu 574against the mlock limit so an unprivileged user is allowed 512KiB per cpu plus 575their mlock limit (which defaults to 64KiB but is not multiplied by the number 576of cpus). 577 578In full-trace mode, powers of two are allowed for buffer size, with a minimum 579size of 2 pages. In snapshot mode or sampling mode, it is the same but the 580minimum size is 1 page. 581 582The mmap size and auxtrace mmap size are displayed if the -vv option is used e.g. 583 584 mmap length 528384 585 auxtrace mmap length 4198400 586 587 588Intel PT modes of operation 589~~~~~~~~~~~~~~~~~~~~~~~~~~~ 590 591Intel PT can be used in 3 modes: 592 full-trace mode 593 sample mode 594 snapshot mode 595 596Full-trace mode traces continuously e.g. 597 598 perf record -e intel_pt//u uname 599 600Sample mode attaches a Intel PT sample to other events e.g. 601 602 perf record --aux-sample -e intel_pt//u -e branch-misses:u 603 604Snapshot mode captures the available data when a signal is sent or "snapshot" 605control command is issued. e.g. using a signal 606 607 perf record -v -e intel_pt//u -S ./loopy 1000000000 & 608 [1] 11435 609 kill -USR2 11435 610 Recording AUX area tracing snapshot 611 612Note that the signal sent is SIGUSR2. 613Note that "Recording AUX area tracing snapshot" is displayed because the -v 614option is used. 615 616The advantage of using "snapshot" control command is that the access is 617controlled by access to a FIFO e.g. 618 619 $ mkfifo perf.control 620 $ mkfifo perf.ack 621 $ cat perf.ack & 622 [1] 15235 623 $ sudo ~/bin/perf record --control fifo:perf.control,perf.ack -S -e intel_pt//u -- sleep 60 & 624 [2] 15243 625 $ ps -e | grep perf 626 15244 pts/1 00:00:00 perf 627 $ kill -USR2 15244 628 bash: kill: (15244) - Operation not permitted 629 $ echo snapshot > perf.control 630 ack 631 632The 3 Intel PT modes of operation cannot be used together. 633 634 635Buffer handling 636~~~~~~~~~~~~~~~ 637 638There may be buffer limitations (i.e. single ToPa entry) which means that actual 639buffer sizes are limited to powers of 2 up to 4MiB (MAX_ORDER). In order to 640provide other sizes, and in particular an arbitrarily large size, multiple 641buffers are logically concatenated. However an interrupt must be used to switch 642between buffers. That has two potential problems: 643 a) the interrupt may not be handled in time so that the current buffer 644 becomes full and some trace data is lost. 645 b) the interrupts may slow the system and affect the performance 646 results. 647 648If trace data is lost, the driver sets 'truncated' in the PERF_RECORD_AUX event 649which the tools report as an error. 650 651In full-trace mode, the driver waits for data to be copied out before allowing 652the (logical) buffer to wrap-around. If data is not copied out quickly enough, 653again 'truncated' is set in the PERF_RECORD_AUX event. If the driver has to 654wait, the intel_pt event gets disabled. Because it is difficult to know when 655that happens, perf tools always re-enable the intel_pt event after copying out 656data. 657 658 659Intel PT and build ids 660~~~~~~~~~~~~~~~~~~~~~~ 661 662By default "perf record" post-processes the event stream to find all build ids 663for executables for all addresses sampled. Deliberately, Intel PT is not 664decoded for that purpose (it would take too long). Instead the build ids for 665all executables encountered (due to mmap, comm or task events) are included 666in the perf.data file. 667 668To see buildids included in the perf.data file use the command: 669 670 perf buildid-list 671 672If the perf.data file contains Intel PT data, that is the same as: 673 674 perf buildid-list --with-hits 675 676 677Snapshot mode and event disabling 678~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 679 680In order to make a snapshot, the intel_pt event is disabled using an IOCTL, 681namely PERF_EVENT_IOC_DISABLE. However doing that can also disable the 682collection of side-band information. In order to prevent that, a dummy 683software event has been introduced that permits tracking events (like mmaps) to 684continue to be recorded while intel_pt is disabled. That is important to ensure 685there is complete side-band information to allow the decoding of subsequent 686snapshots. 687 688A test has been created for that. To find the test: 689 690 perf test list 691 ... 692 23: Test using a dummy software event to keep tracking 693 694To run the test: 695 696 perf test 23 697 23: Test using a dummy software event to keep tracking : Ok 698 699 700perf record modes (nothing new here) 701~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 702 703perf record essentially operates in one of three modes: 704 per thread 705 per cpu 706 workload only 707 708"per thread" mode is selected by -t or by --per-thread (with -p or -u or just a 709workload). 710"per cpu" is selected by -C or -a. 711"workload only" mode is selected by not using the other options but providing a 712command to run (i.e. the workload). 713 714In per-thread mode an exact list of threads is traced. There is no inheritance. 715Each thread has its own event buffer. 716 717In per-cpu mode all processes (or processes from the selected cgroup i.e. -G 718option, or processes selected with -p or -u) are traced. Each cpu has its own 719buffer. Inheritance is allowed. 720 721In workload-only mode, the workload is traced but with per-cpu buffers. 722Inheritance is allowed. Note that you can now trace a workload in per-thread 723mode by using the --per-thread option. 724 725 726Privileged vs non-privileged users 727~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 728 729Unless /proc/sys/kernel/perf_event_paranoid is set to -1, unprivileged users 730have memory limits imposed upon them. That affects what buffer sizes they can 731have as outlined above. 732 733The v4.2 kernel introduced support for a context switch metadata event, 734PERF_RECORD_SWITCH, which allows unprivileged users to see when their processes 735are scheduled out and in, just not by whom, which is left for the 736PERF_RECORD_SWITCH_CPU_WIDE, that is only accessible in system wide context, 737which in turn requires CAP_PERFMON or CAP_SYS_ADMIN. 738 739Please see the 45ac1403f564 ("perf: Add PERF_RECORD_SWITCH to indicate context 740switches") commit, that introduces these metadata events for further info. 741 742When working with kernels < v4.2, the following considerations must be taken, 743as the sched:sched_switch tracepoints will be used to receive such information: 744 745Unless /proc/sys/kernel/perf_event_paranoid is set to -1, unprivileged users are 746not permitted to use tracepoints which means there is insufficient side-band 747information to decode Intel PT in per-cpu mode, and potentially workload-only 748mode too if the workload creates new processes. 749 750Note also, that to use tracepoints, read-access to debugfs is required. So if 751debugfs is not mounted or the user does not have read-access, it will again not 752be possible to decode Intel PT in per-cpu mode. 753 754 755sched_switch tracepoint 756~~~~~~~~~~~~~~~~~~~~~~~ 757 758The sched_switch tracepoint is used to provide side-band data for Intel PT 759decoding in kernels where the PERF_RECORD_SWITCH metadata event isn't 760available. 761 762The sched_switch events are automatically added. e.g. the second event shown 763below: 764 765 $ perf record -vv -e intel_pt//u uname 766 ------------------------------------------------------------ 767 perf_event_attr: 768 type 6 769 size 112 770 config 0x400 771 { sample_period, sample_freq } 1 772 sample_type IP|TID|TIME|CPU|IDENTIFIER 773 read_format ID 774 disabled 1 775 inherit 1 776 exclude_kernel 1 777 exclude_hv 1 778 enable_on_exec 1 779 sample_id_all 1 780 ------------------------------------------------------------ 781 sys_perf_event_open: pid 31104 cpu 0 group_fd -1 flags 0x8 782 sys_perf_event_open: pid 31104 cpu 1 group_fd -1 flags 0x8 783 sys_perf_event_open: pid 31104 cpu 2 group_fd -1 flags 0x8 784 sys_perf_event_open: pid 31104 cpu 3 group_fd -1 flags 0x8 785 ------------------------------------------------------------ 786 perf_event_attr: 787 type 2 788 size 112 789 config 0x108 790 { sample_period, sample_freq } 1 791 sample_type IP|TID|TIME|CPU|PERIOD|RAW|IDENTIFIER 792 read_format ID 793 inherit 1 794 sample_id_all 1 795 exclude_guest 1 796 ------------------------------------------------------------ 797 sys_perf_event_open: pid -1 cpu 0 group_fd -1 flags 0x8 798 sys_perf_event_open: pid -1 cpu 1 group_fd -1 flags 0x8 799 sys_perf_event_open: pid -1 cpu 2 group_fd -1 flags 0x8 800 sys_perf_event_open: pid -1 cpu 3 group_fd -1 flags 0x8 801 ------------------------------------------------------------ 802 perf_event_attr: 803 type 1 804 size 112 805 config 0x9 806 { sample_period, sample_freq } 1 807 sample_type IP|TID|TIME|IDENTIFIER 808 read_format ID 809 disabled 1 810 inherit 1 811 exclude_kernel 1 812 exclude_hv 1 813 mmap 1 814 comm 1 815 enable_on_exec 1 816 task 1 817 sample_id_all 1 818 mmap2 1 819 comm_exec 1 820 ------------------------------------------------------------ 821 sys_perf_event_open: pid 31104 cpu 0 group_fd -1 flags 0x8 822 sys_perf_event_open: pid 31104 cpu 1 group_fd -1 flags 0x8 823 sys_perf_event_open: pid 31104 cpu 2 group_fd -1 flags 0x8 824 sys_perf_event_open: pid 31104 cpu 3 group_fd -1 flags 0x8 825 mmap size 528384B 826 AUX area mmap length 4194304 827 perf event ring buffer mmapped per cpu 828 Synthesizing auxtrace information 829 Linux 830 [ perf record: Woken up 1 times to write data ] 831 [ perf record: Captured and wrote 0.042 MB perf.data ] 832 833Note, the sched_switch event is only added if the user is permitted to use it 834and only in per-cpu mode. 835 836Note also, the sched_switch event is only added if TSC packets are requested. 837That is because, in the absence of timing information, the sched_switch events 838cannot be matched against the Intel PT trace. 839 840 841perf script 842----------- 843 844By default, perf script will decode trace data found in the perf.data file. 845This can be further controlled by new option --itrace. 846 847 848New --itrace option 849~~~~~~~~~~~~~~~~~~~ 850 851Having no option is the same as 852 853 --itrace 854 855which, in turn, is the same as 856 857 --itrace=cepwx 858 859The letters are: 860 861 i synthesize "instructions" events 862 b synthesize "branches" events 863 x synthesize "transactions" events 864 w synthesize "ptwrite" events 865 p synthesize "power" events (incl. PSB events) 866 c synthesize branches events (calls only) 867 r synthesize branches events (returns only) 868 e synthesize tracing error events 869 d create a debug log 870 g synthesize a call chain (use with i or x) 871 G synthesize a call chain on existing event records 872 l synthesize last branch entries (use with i or x) 873 L synthesize last branch entries on existing event records 874 s skip initial number of events 875 q quicker (less detailed) decoding 876 Z prefer to ignore timestamps (so-called "timeless" decoding) 877 878"Instructions" events look like they were recorded by "perf record -e 879instructions". 880 881"Branches" events look like they were recorded by "perf record -e branches". "c" 882and "r" can be combined to get calls and returns. 883 884"Transactions" events correspond to the start or end of transactions. The 885'flags' field can be used in perf script to determine whether the event is a 886transaction start, commit or abort. 887 888Note that "instructions", "branches" and "transactions" events depend on code 889flow packets which can be disabled by using the config term "branch=0". Refer 890to the config terms section above. 891 892"ptwrite" events record the payload of the ptwrite instruction and whether 893"fup_on_ptw" was used. "ptwrite" events depend on PTWRITE packets which are 894recorded only if the "ptw" config term was used. Refer to the config terms 895section above. perf script "synth" field displays "ptwrite" information like 896this: "ip: 0 payload: 0x123456789abcdef0" where "ip" is 1 if "fup_on_ptw" was 897used. 898 899"Power" events correspond to power event packets and CBR (core-to-bus ratio) 900packets. While CBR packets are always recorded when tracing is enabled, power 901event packets are recorded only if the "pwr_evt" config term was used. Refer to 902the config terms section above. The power events record information about 903C-state changes, whereas CBR is indicative of CPU frequency. perf script 904"event,synth" fields display information like this: 905 cbr: cbr: 22 freq: 2189 MHz (200%) 906 mwait: hints: 0x60 extensions: 0x1 907 pwre: hw: 0 cstate: 2 sub-cstate: 0 908 exstop: ip: 1 909 pwrx: deepest cstate: 2 last cstate: 2 wake reason: 0x4 910Where: 911 "cbr" includes the frequency and the percentage of maximum non-turbo 912 "mwait" shows mwait hints and extensions 913 "pwre" shows C-state transitions (to a C-state deeper than C0) and 914 whether initiated by hardware 915 "exstop" indicates execution stopped and whether the IP was recorded 916 exactly, 917 "pwrx" indicates return to C0 918For more details refer to the Intel 64 and IA-32 Architectures Software 919Developer Manuals. 920 921PSB events show when a PSB+ occurred and also the byte-offset in the trace. 922Emitting a PSB+ can cause a CPU a slight delay. When doing timing analysis 923of code with Intel PT, it is useful to know if a timing bubble was caused 924by Intel PT or not. 925 926Error events show where the decoder lost the trace. Error events 927are quite important. Users must know if what they are seeing is a complete 928picture or not. The "e" option may be followed by flags which affect what errors 929will or will not be reported. Each flag must be preceded by either '+' or '-'. 930The flags supported by Intel PT are: 931 -o Suppress overflow errors 932 -l Suppress trace data lost errors 933For example, for errors but not overflow or data lost errors: 934 935 --itrace=e-o-l 936 937The "d" option will cause the creation of a file "intel_pt.log" containing all 938decoded packets and instructions. Note that this option slows down the decoder 939and that the resulting file may be very large. The "d" option may be followed 940by flags which affect what debug messages will or will not be logged. Each flag 941must be preceded by either '+' or '-'. The flags support by Intel PT are: 942 -a Suppress logging of perf events 943 +a Log all perf events 944By default, logged perf events are filtered by any specified time ranges, but 945flag +a overrides that. 946 947In addition, the period of the "instructions" event can be specified. e.g. 948 949 --itrace=i10us 950 951sets the period to 10us i.e. one instruction sample is synthesized for each 10 952microseconds of trace. Alternatives to "us" are "ms" (milliseconds), 953"ns" (nanoseconds), "t" (TSC ticks) or "i" (instructions). 954 955"ms", "us" and "ns" are converted to TSC ticks. 956 957The timing information included with Intel PT does not give the time of every 958instruction. Consequently, for the purpose of sampling, the decoder estimates 959the time since the last timing packet based on 1 tick per instruction. The time 960on the sample is *not* adjusted and reflects the last known value of TSC. 961 962For Intel PT, the default period is 100us. 963 964Setting it to a zero period means "as often as possible". 965 966In the case of Intel PT that is the same as a period of 1 and a unit of 967'instructions' (i.e. --itrace=i1i). 968 969Also the call chain size (default 16, max. 1024) for instructions or 970transactions events can be specified. e.g. 971 972 --itrace=ig32 973 --itrace=xg32 974 975Also the number of last branch entries (default 64, max. 1024) for instructions or 976transactions events can be specified. e.g. 977 978 --itrace=il10 979 --itrace=xl10 980 981Note that last branch entries are cleared for each sample, so there is no overlap 982from one sample to the next. 983 984The G and L options are designed in particular for sample mode, and work much 985like g and l but add call chain and branch stack to the other selected events 986instead of synthesized events. For example, to record branch-misses events for 987'ls' and then add a call chain derived from the Intel PT trace: 988 989 perf record --aux-sample -e '{intel_pt//u,branch-misses:u}' -- ls 990 perf report --itrace=Ge 991 992Although in fact G is a default for perf report, so that is the same as just: 993 994 perf report 995 996One caveat with the G and L options is that they work poorly with "Large PEBS". 997Large PEBS means PEBS records will be accumulated by hardware and the written 998into the event buffer in one go. That reduces interrupts, but can give very 999late timestamps. Because the Intel PT trace is synchronized by timestamps, 1000the PEBS events do not match the trace. Currently, Large PEBS is used only in 1001certain circumstances: 1002 - hardware supports it 1003 - PEBS is used 1004 - event period is specified, instead of frequency 1005 - the sample type is limited to the following flags: 1006 PERF_SAMPLE_IP | PERF_SAMPLE_TID | PERF_SAMPLE_ADDR | 1007 PERF_SAMPLE_ID | PERF_SAMPLE_CPU | PERF_SAMPLE_STREAM_ID | 1008 PERF_SAMPLE_DATA_SRC | PERF_SAMPLE_IDENTIFIER | 1009 PERF_SAMPLE_TRANSACTION | PERF_SAMPLE_PHYS_ADDR | 1010 PERF_SAMPLE_REGS_INTR | PERF_SAMPLE_REGS_USER | 1011 PERF_SAMPLE_PERIOD (and sometimes) | PERF_SAMPLE_TIME 1012Because Intel PT sample mode uses a different sample type to the list above, 1013Large PEBS is not used with Intel PT sample mode. To avoid Large PEBS in other 1014cases, avoid specifying the event period i.e. avoid the 'perf record' -c option, 1015--count option, or 'period' config term. 1016 1017To disable trace decoding entirely, use the option --no-itrace. 1018 1019It is also possible to skip events generated (instructions, branches, transactions) 1020at the beginning. This is useful to ignore initialization code. 1021 1022 --itrace=i0nss1000000 1023 1024skips the first million instructions. 1025 1026The q option changes the way the trace is decoded. The decoding is much faster 1027but much less detailed. Specifically, with the q option, the decoder does not 1028decode TNT packets, and does not walk object code, but gets the ip from FUP and 1029TIP packets. The q option can be used with the b and i options but the period 1030is not used. The q option decodes more quickly, but is useful only if the 1031control flow of interest is represented or indicated by FUP, TIP, TIP.PGE, or 1032TIP.PGD packets (refer below). However the q option could be used to find time 1033ranges that could then be decoded fully using the --time option. 1034 1035What will *not* be decoded with the (single) q option: 1036 1037 - direct calls and jmps 1038 - conditional branches 1039 - non-branch instructions 1040 1041What *will* be decoded with the (single) q option: 1042 1043 - asynchronous branches such as interrupts 1044 - indirect branches 1045 - function return target address *if* the noretcomp config term (refer 1046 config terms section) was used 1047 - start of (control-flow) tracing 1048 - end of (control-flow) tracing, if it is not out of context 1049 - power events, ptwrite, transaction start and abort 1050 - instruction pointer associated with PSB packets 1051 1052Note the q option does not specify what events will be synthesized e.g. the p 1053option must be used also to show power events. 1054 1055Repeating the q option (double-q i.e. qq) results in even faster decoding and even 1056less detail. The decoder decodes only extended PSB (PSB+) packets, getting the 1057instruction pointer if there is a FUP packet within PSB+ (i.e. between PSB and 1058PSBEND). Note PSB packets occur regularly in the trace based on the psb_period 1059config term (refer config terms section). There will be a FUP packet if the 1060PSB+ occurs while control flow is being traced. 1061 1062What will *not* be decoded with the qq option: 1063 1064 - everything except instruction pointer associated with PSB packets 1065 1066What *will* be decoded with the qq option: 1067 1068 - instruction pointer associated with PSB packets 1069 1070The Z option is equivalent to having recorded a trace without TSC 1071(i.e. config term tsc=0). It can be useful to avoid timestamp issues when 1072decoding a trace of a virtual machine. 1073 1074 1075dump option 1076~~~~~~~~~~~ 1077 1078perf script has an option (-D) to "dump" the events i.e. display the binary 1079data. 1080 1081When -D is used, Intel PT packets are displayed. The packet decoder does not 1082pay attention to PSB packets, but just decodes the bytes - so the packets seen 1083by the actual decoder may not be identical in places where the data is corrupt. 1084One example of that would be when the buffer-switching interrupt has been too 1085slow, and the buffer has been filled completely. In that case, the last packet 1086in the buffer might be truncated and immediately followed by a PSB as the trace 1087continues in the next buffer. 1088 1089To disable the display of Intel PT packets, combine the -D option with 1090--no-itrace. 1091 1092 1093perf report 1094----------- 1095 1096By default, perf report will decode trace data found in the perf.data file. 1097This can be further controlled by new option --itrace exactly the same as 1098perf script, with the exception that the default is --itrace=igxe. 1099 1100 1101perf inject 1102----------- 1103 1104perf inject also accepts the --itrace option in which case tracing data is 1105removed and replaced with the synthesized events. e.g. 1106 1107 perf inject --itrace -i perf.data -o perf.data.new 1108 1109Below is an example of using Intel PT with autofdo. It requires autofdo 1110(https://github.com/google/autofdo) and gcc version 5. The bubble 1111sort example is from the AutoFDO tutorial (https://gcc.gnu.org/wiki/AutoFDO/Tutorial) 1112amended to take the number of elements as a parameter. 1113 1114 $ gcc-5 -O3 sort.c -o sort_optimized 1115 $ ./sort_optimized 30000 1116 Bubble sorting array of 30000 elements 1117 2254 ms 1118 1119 $ cat ~/.perfconfig 1120 [intel-pt] 1121 mispred-all = on 1122 1123 $ perf record -e intel_pt//u ./sort 3000 1124 Bubble sorting array of 3000 elements 1125 58 ms 1126 [ perf record: Woken up 2 times to write data ] 1127 [ perf record: Captured and wrote 3.939 MB perf.data ] 1128 $ perf inject -i perf.data -o inj --itrace=i100usle --strip 1129 $ ./create_gcov --binary=./sort --profile=inj --gcov=sort.gcov -gcov_version=1 1130 $ gcc-5 -O3 -fauto-profile=sort.gcov sort.c -o sort_autofdo 1131 $ ./sort_autofdo 30000 1132 Bubble sorting array of 30000 elements 1133 2155 ms 1134 1135Note there is currently no advantage to using Intel PT instead of LBR, but 1136that may change in the future if greater use is made of the data. 1137 1138 1139PEBS via Intel PT 1140----------------- 1141 1142Some hardware has the feature to redirect PEBS records to the Intel PT trace. 1143Recording is selected by using the aux-output config term e.g. 1144 1145 perf record -c 10000 -e '{intel_pt/branch=0/,cycles/aux-output/ppp}' uname 1146 1147Note that currently, software only supports redirecting at most one PEBS event. 1148 1149To display PEBS events from the Intel PT trace, use the itrace 'o' option e.g. 1150 1151 perf script --itrace=oe 1152 1153XED 1154--- 1155 1156include::build-xed.txt[] 1157 1158 1159Tracing Virtual Machines 1160------------------------ 1161 1162Currently, only kernel tracing is supported and only with either "timeless" decoding 1163(i.e. no TSC timestamps) or VM Time Correlation. VM Time Correlation is an extra step 1164using 'perf inject' and requires unchanging VMX TSC Offset and no VMX TSC Scaling. 1165 1166Other limitations and caveats 1167 1168 VMX controls may suppress packets needed for decoding resulting in decoding errors 1169 VMX controls may block the perf NMI to the host potentially resulting in lost trace data 1170 Guest kernel self-modifying code (e.g. jump labels or JIT-compiled eBPF) will result in decoding errors 1171 Guest thread information is unknown 1172 Guest VCPU is unknown but may be able to be inferred from the host thread 1173 Callchains are not supported 1174 1175Example using "timeless" decoding 1176 1177Start VM 1178 1179 $ sudo virsh start kubuntu20.04 1180 Domain kubuntu20.04 started 1181 1182Mount the guest file system. Note sshfs needs -o direct_io to enable reading of proc files. root access is needed to read /proc/kcore. 1183 1184 $ mkdir vm0 1185 $ sshfs -o direct_io root@vm0:/ vm0 1186 1187Copy the guest /proc/kallsyms, /proc/modules and /proc/kcore 1188 1189 $ perf buildid-cache -v --kcore vm0/proc/kcore 1190 kcore added to build-id cache directory /home/user/.debug/[kernel.kcore]/9600f316a53a0f54278885e8d9710538ec5f6a08/2021021807494306 1191 $ KALLSYMS=/home/user/.debug/[kernel.kcore]/9600f316a53a0f54278885e8d9710538ec5f6a08/2021021807494306/kallsyms 1192 1193Find the VM process 1194 1195 $ ps -eLl | grep 'KVM\|PID' 1196 F S UID PID PPID LWP C PRI NI ADDR SZ WCHAN TTY TIME CMD 1197 3 S 64055 1430 1 1440 1 80 0 - 1921718 - ? 00:02:47 CPU 0/KVM 1198 3 S 64055 1430 1 1441 1 80 0 - 1921718 - ? 00:02:41 CPU 1/KVM 1199 3 S 64055 1430 1 1442 1 80 0 - 1921718 - ? 00:02:38 CPU 2/KVM 1200 3 S 64055 1430 1 1443 2 80 0 - 1921718 - ? 00:03:18 CPU 3/KVM 1201 1202Start an open-ended perf record, tracing the VM process, do something on the VM, and then ctrl-C to stop. 1203TSC is not supported and tsc=0 must be specified. That means mtc is useless, so add mtc=0. 1204However, IPC can still be determined, hence cyc=1 can be added. 1205Only kernel decoding is supported, so 'k' must be specified. 1206Intel PT traces both the host and the guest so --guest and --host need to be specified. 1207Without timestamps, --per-thread must be specified to distinguish threads. 1208 1209 $ sudo perf kvm --guest --host --guestkallsyms $KALLSYMS record --kcore -e intel_pt/tsc=0,mtc=0,cyc=1/k -p 1430 --per-thread 1210 ^C 1211 [ perf record: Woken up 1 times to write data ] 1212 [ perf record: Captured and wrote 5.829 MB ] 1213 1214perf script can be used to provide an instruction trace 1215 1216 $ perf script --guestkallsyms $KALLSYMS --insn-trace --xed -F+ipc | grep -C10 vmresume | head -21 1217 CPU 0/KVM 1440 ffffffff82133cdd __vmx_vcpu_run+0x3d ([kernel.kallsyms]) movq 0x48(%rax), %r9 1218 CPU 0/KVM 1440 ffffffff82133ce1 __vmx_vcpu_run+0x41 ([kernel.kallsyms]) movq 0x50(%rax), %r10 1219 CPU 0/KVM 1440 ffffffff82133ce5 __vmx_vcpu_run+0x45 ([kernel.kallsyms]) movq 0x58(%rax), %r11 1220 CPU 0/KVM 1440 ffffffff82133ce9 __vmx_vcpu_run+0x49 ([kernel.kallsyms]) movq 0x60(%rax), %r12 1221 CPU 0/KVM 1440 ffffffff82133ced __vmx_vcpu_run+0x4d ([kernel.kallsyms]) movq 0x68(%rax), %r13 1222 CPU 0/KVM 1440 ffffffff82133cf1 __vmx_vcpu_run+0x51 ([kernel.kallsyms]) movq 0x70(%rax), %r14 1223 CPU 0/KVM 1440 ffffffff82133cf5 __vmx_vcpu_run+0x55 ([kernel.kallsyms]) movq 0x78(%rax), %r15 1224 CPU 0/KVM 1440 ffffffff82133cf9 __vmx_vcpu_run+0x59 ([kernel.kallsyms]) movq (%rax), %rax 1225 CPU 0/KVM 1440 ffffffff82133cfc __vmx_vcpu_run+0x5c ([kernel.kallsyms]) callq 0xffffffff82133c40 1226 CPU 0/KVM 1440 ffffffff82133c40 vmx_vmenter+0x0 ([kernel.kallsyms]) jz 0xffffffff82133c46 1227 CPU 0/KVM 1440 ffffffff82133c42 vmx_vmenter+0x2 ([kernel.kallsyms]) vmresume IPC: 0.11 (50/445) 1228 :1440 1440 ffffffffbb678b06 native_write_msr+0x6 ([guest.kernel.kallsyms]) nopl %eax, (%rax,%rax,1) 1229 :1440 1440 ffffffffbb678b0b native_write_msr+0xb ([guest.kernel.kallsyms]) retq IPC: 0.04 (2/41) 1230 :1440 1440 ffffffffbb666646 lapic_next_deadline+0x26 ([guest.kernel.kallsyms]) data16 nop 1231 :1440 1440 ffffffffbb666648 lapic_next_deadline+0x28 ([guest.kernel.kallsyms]) xor %eax, %eax 1232 :1440 1440 ffffffffbb66664a lapic_next_deadline+0x2a ([guest.kernel.kallsyms]) popq %rbp 1233 :1440 1440 ffffffffbb66664b lapic_next_deadline+0x2b ([guest.kernel.kallsyms]) retq IPC: 0.16 (4/25) 1234 :1440 1440 ffffffffbb74607f clockevents_program_event+0x8f ([guest.kernel.kallsyms]) test %eax, %eax 1235 :1440 1440 ffffffffbb746081 clockevents_program_event+0x91 ([guest.kernel.kallsyms]) jz 0xffffffffbb74603c IPC: 0.06 (2/30) 1236 :1440 1440 ffffffffbb74603c clockevents_program_event+0x4c ([guest.kernel.kallsyms]) popq %rbx 1237 :1440 1440 ffffffffbb74603d clockevents_program_event+0x4d ([guest.kernel.kallsyms]) popq %r12 1238 1239Example using VM Time Correlation 1240 1241Start VM 1242 1243 $ sudo virsh start kubuntu20.04 1244 Domain kubuntu20.04 started 1245 1246Mount the guest file system. Note sshfs needs -o direct_io to enable reading of proc files. root access is needed to read /proc/kcore. 1247 1248 $ mkdir -p vm0 1249 $ sshfs -o direct_io root@vm0:/ vm0 1250 1251Copy the guest /proc/kallsyms, /proc/modules and /proc/kcore 1252 1253 $ perf buildid-cache -v --kcore vm0/proc/kcore 1254 same kcore found in /home/user/.debug/[kernel.kcore]/cc9c55a98c5e4ec0aeda69302554aabed5cd6491/2021021312450777 1255 $ KALLSYMS=/home/user/.debug/\[kernel.kcore\]/cc9c55a98c5e4ec0aeda69302554aabed5cd6491/2021021312450777/kallsyms 1256 1257Find the VM process 1258 1259 $ ps -eLl | grep 'KVM\|PID' 1260 F S UID PID PPID LWP C PRI NI ADDR SZ WCHAN TTY TIME CMD 1261 3 S 64055 16998 1 17005 13 80 0 - 1818189 - ? 00:00:16 CPU 0/KVM 1262 3 S 64055 16998 1 17006 4 80 0 - 1818189 - ? 00:00:05 CPU 1/KVM 1263 3 S 64055 16998 1 17007 3 80 0 - 1818189 - ? 00:00:04 CPU 2/KVM 1264 3 S 64055 16998 1 17008 4 80 0 - 1818189 - ? 00:00:05 CPU 3/KVM 1265 1266Start an open-ended perf record, tracing the VM process, do something on the VM, and then ctrl-C to stop. 1267IPC can be determined, hence cyc=1 can be added. 1268Only kernel decoding is supported, so 'k' must be specified. 1269Intel PT traces both the host and the guest so --guest and --host need to be specified. 1270 1271 $ sudo perf kvm --guest --host --guestkallsyms $KALLSYMS record --kcore -e intel_pt/cyc=1/k -p 16998 1272 ^C[ perf record: Woken up 1 times to write data ] 1273 [ perf record: Captured and wrote 9.041 MB perf.data.kvm ] 1274 1275Now 'perf inject' can be used to determine the VMX TCS Offset. Note, Intel PT TSC packets are 1276only 7-bytes, so the TSC Offset might differ from the actual value in the 8th byte. That will 1277have no effect i.e. the resulting timestamps will be correct anyway. 1278 1279 $ perf inject -i perf.data.kvm --vm-time-correlation=dry-run 1280 ERROR: Unknown TSC Offset for VMCS 0x1bff6a 1281 VMCS: 0x1bff6a TSC Offset 0xffffe42722c64c41 1282 ERROR: Unknown TSC Offset for VMCS 0x1cbc08 1283 VMCS: 0x1cbc08 TSC Offset 0xffffe42722c64c41 1284 ERROR: Unknown TSC Offset for VMCS 0x1c3ce8 1285 VMCS: 0x1c3ce8 TSC Offset 0xffffe42722c64c41 1286 ERROR: Unknown TSC Offset for VMCS 0x1cbce9 1287 VMCS: 0x1cbce9 TSC Offset 0xffffe42722c64c41 1288 1289Each virtual CPU has a different Virtual Machine Control Structure (VMCS) 1290shown above with the calculated TSC Offset. For an unchanging TSC Offset 1291they should all be the same for the same virtual machine. 1292 1293Now that the TSC Offset is known, it can be provided to 'perf inject' 1294 1295 $ perf inject -i perf.data.kvm --vm-time-correlation="dry-run 0xffffe42722c64c41" 1296 1297Note the options for 'perf inject' --vm-time-correlation are: 1298 1299 [ dry-run ] [ <TSC Offset> [ : <VMCS> [ , <VMCS> ]... ] ]... 1300 1301So it is possible to specify different TSC Offsets for different VMCS. 1302The option "dry-run" will cause the file to be processed but without updating it. 1303Note it is also possible to get a intel_pt.log file by adding option --itrace=d 1304 1305There were no errors so, do it for real 1306 1307 $ perf inject -i perf.data.kvm --vm-time-correlation=0xffffe42722c64c41 --force 1308 1309'perf script' can be used to see if there are any decoder errors 1310 1311 $ perf script -i perf.data.kvm --guestkallsyms $KALLSYMS --itrace=e-o 1312 1313There were none. 1314 1315'perf script' can be used to provide an instruction trace showing timestamps 1316 1317 $ perf script -i perf.data.kvm --guestkallsyms $KALLSYMS --insn-trace --xed -F+ipc | grep -C10 vmresume | head -21 1318 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cdd __vmx_vcpu_run+0x3d ([kernel.kallsyms]) movq 0x48(%rax), %r9 1319 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133ce1 __vmx_vcpu_run+0x41 ([kernel.kallsyms]) movq 0x50(%rax), %r10 1320 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133ce5 __vmx_vcpu_run+0x45 ([kernel.kallsyms]) movq 0x58(%rax), %r11 1321 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133ce9 __vmx_vcpu_run+0x49 ([kernel.kallsyms]) movq 0x60(%rax), %r12 1322 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133ced __vmx_vcpu_run+0x4d ([kernel.kallsyms]) movq 0x68(%rax), %r13 1323 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cf1 __vmx_vcpu_run+0x51 ([kernel.kallsyms]) movq 0x70(%rax), %r14 1324 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cf5 __vmx_vcpu_run+0x55 ([kernel.kallsyms]) movq 0x78(%rax), %r15 1325 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cf9 __vmx_vcpu_run+0x59 ([kernel.kallsyms]) movq (%rax), %rax 1326 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133cfc __vmx_vcpu_run+0x5c ([kernel.kallsyms]) callq 0xffffffff82133c40 1327 CPU 1/KVM 17006 [001] 11500.262865593: ffffffff82133c40 vmx_vmenter+0x0 ([kernel.kallsyms]) jz 0xffffffff82133c46 1328 CPU 1/KVM 17006 [001] 11500.262866075: ffffffff82133c42 vmx_vmenter+0x2 ([kernel.kallsyms]) vmresume IPC: 0.05 (40/769) 1329 :17006 17006 [001] 11500.262869216: ffffffff82200cb0 asm_sysvec_apic_timer_interrupt+0x0 ([guest.kernel.kallsyms]) clac 1330 :17006 17006 [001] 11500.262869216: ffffffff82200cb3 asm_sysvec_apic_timer_interrupt+0x3 ([guest.kernel.kallsyms]) pushq $0xffffffffffffffff 1331 :17006 17006 [001] 11500.262869216: ffffffff82200cb5 asm_sysvec_apic_timer_interrupt+0x5 ([guest.kernel.kallsyms]) callq 0xffffffff82201160 1332 :17006 17006 [001] 11500.262869216: ffffffff82201160 error_entry+0x0 ([guest.kernel.kallsyms]) cld 1333 :17006 17006 [001] 11500.262869216: ffffffff82201161 error_entry+0x1 ([guest.kernel.kallsyms]) pushq %rsi 1334 :17006 17006 [001] 11500.262869216: ffffffff82201162 error_entry+0x2 ([guest.kernel.kallsyms]) movq 0x8(%rsp), %rsi 1335 :17006 17006 [001] 11500.262869216: ffffffff82201167 error_entry+0x7 ([guest.kernel.kallsyms]) movq %rdi, 0x8(%rsp) 1336 :17006 17006 [001] 11500.262869216: ffffffff8220116c error_entry+0xc ([guest.kernel.kallsyms]) pushq %rdx 1337 :17006 17006 [001] 11500.262869216: ffffffff8220116d error_entry+0xd ([guest.kernel.kallsyms]) pushq %rcx 1338 :17006 17006 [001] 11500.262869216: ffffffff8220116e error_entry+0xe ([guest.kernel.kallsyms]) pushq %rax 1339 1340 1341 1342SEE ALSO 1343-------- 1344 1345linkperf:perf-record[1], linkperf:perf-script[1], linkperf:perf-report[1], 1346linkperf:perf-inject[1] 1347