680 lines · plain
1perf-script-python(1)2====================3 4NAME5----6perf-script-python - Process trace data with a Python script7 8SYNOPSIS9--------10[verse]11'perf script' [-s [Python]:script[.py] ]12 13DESCRIPTION14-----------15 16This perf script option is used to process perf script data using perf's17built-in Python interpreter. It reads and processes the input file and18displays the results of the trace analysis implemented in the given19Python script, if any.20 21A QUICK EXAMPLE22---------------23 24This section shows the process, start to finish, of creating a working25Python script that aggregates and extracts useful information from a26raw perf script stream. You can avoid reading the rest of this27document if an example is enough for you; the rest of the document28provides more details on each step and lists the library functions29available to script writers.30 31This example actually details the steps that were used to create the32'syscall-counts' script you see when you list the available perf script33scripts via 'perf script -l'. As such, this script also shows how to34integrate your script into the list of general-purpose 'perf script'35scripts listed by that command.36 37The syscall-counts script is a simple script, but demonstrates all the38basic ideas necessary to create a useful script. Here's an example39of its output (syscall names are not yet supported, they will appear40as numbers):41 42----43syscall events:44 45event count46---------------------------------------- -----------47sys_write 45506748sys_getdents 407249sys_close 303750sys_swapoff 176951sys_read 92352sys_sched_setparam 82653sys_open 33154sys_newfstat 32655sys_mmap 21756sys_munmap 21657sys_futex 14158sys_select 10259sys_poll 8460sys_setitimer 1261sys_writev 86215 863sys_lseek 764sys_rt_sigprocmask 665sys_wait4 366sys_ioctl 367sys_set_robust_list 168sys_exit 16956 170sys_access 171----72 73Basically our task is to keep a per-syscall tally that gets updated74every time a system call occurs in the system. Our script will do75that, but first we need to record the data that will be processed by76that script. Theoretically, there are a couple of ways we could do77that:78 79- we could enable every event under the tracing/events/syscalls80 directory, but this is over 600 syscalls, well beyond the number81 allowable by perf. These individual syscall events will however be82 useful if we want to later use the guidance we get from the83 general-purpose scripts to drill down and get more detail about84 individual syscalls of interest.85 86- we can enable the sys_enter and/or sys_exit syscalls found under87 tracing/events/raw_syscalls. These are called for all syscalls; the88 'id' field can be used to distinguish between individual syscall89 numbers.90 91For this script, we only need to know that a syscall was entered; we92don't care how it exited, so we'll use 'perf record' to record only93the sys_enter events:94 95----96# perf record -a -e raw_syscalls:sys_enter97 98^C[ perf record: Woken up 1 times to write data ]99[ perf record: Captured and wrote 56.545 MB perf.data (~2470503 samples) ]100----101 102The options basically say to collect data for every syscall event103system-wide and multiplex the per-cpu output into a single stream.104That single stream will be recorded in a file in the current directory105called perf.data.106 107Once we have a perf.data file containing our data, we can use the -g108'perf script' option to generate a Python script that will contain a109callback handler for each event type found in the perf.data trace110stream (for more details, see the STARTER SCRIPTS section).111 112----113# perf script -g python114generated Python script: perf-script.py115 116The output file created also in the current directory is named117perf-script.py. Here's the file in its entirety:118 119# perf script event handlers, generated by perf script -g python120# Licensed under the terms of the GNU GPL License version 2121 122# The common_* event handler fields are the most useful fields common to123# all events. They don't necessarily correspond to the 'common_*' fields124# in the format files. Those fields not available as handler params can125# be retrieved using Python functions of the form common_*(context).126# See the perf-script-python Documentation for the list of available functions.127 128import os129import sys130 131sys.path.append(os.environ['PERF_EXEC_PATH'] + \132 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')133 134from perf_trace_context import *135from Core import *136 137def trace_begin():138 print "in trace_begin"139 140def trace_end():141 print "in trace_end"142 143def raw_syscalls__sys_enter(event_name, context, common_cpu,144 common_secs, common_nsecs, common_pid, common_comm,145 id, args):146 print_header(event_name, common_cpu, common_secs, common_nsecs,147 common_pid, common_comm)148 149 print "id=%d, args=%s\n" % \150 (id, args),151 152def trace_unhandled(event_name, context, event_fields_dict):153 print ' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())])154 155def print_header(event_name, cpu, secs, nsecs, pid, comm):156 print "%-20s %5u %05u.%09u %8u %-20s " % \157 (event_name, cpu, secs, nsecs, pid, comm),158----159 160At the top is a comment block followed by some import statements and a161path append which every perf script script should include.162 163Following that are a couple generated functions, trace_begin() and164trace_end(), which are called at the beginning and the end of the165script respectively (for more details, see the SCRIPT_LAYOUT section166below).167 168Following those are the 'event handler' functions generated one for169every event in the 'perf record' output. The handler functions take170the form subsystem\__event_name, and contain named parameters, one for171each field in the event; in this case, there's only one event,172raw_syscalls__sys_enter(). (see the EVENT HANDLERS section below for173more info on event handlers).174 175The final couple of functions are, like the begin and end functions,176generated for every script. The first, trace_unhandled(), is called177every time the script finds an event in the perf.data file that178doesn't correspond to any event handler in the script. This could179mean either that the record step recorded event types that it wasn't180really interested in, or the script was run against a trace file that181doesn't correspond to the script.182 183The script generated by -g option simply prints a line for each184event found in the trace stream i.e. it basically just dumps the event185and its parameter values to stdout. The print_header() function is186simply a utility function used for that purpose. Let's rename the187script and run it to see the default output:188 189----190# mv perf-script.py syscall-counts.py191# perf script -s syscall-counts.py192 193raw_syscalls__sys_enter 1 00840.847582083 7506 perf id=1, args=194raw_syscalls__sys_enter 1 00840.847595764 7506 perf id=1, args=195raw_syscalls__sys_enter 1 00840.847620860 7506 perf id=1, args=196raw_syscalls__sys_enter 1 00840.847710478 6533 npviewer.bin id=78, args=197raw_syscalls__sys_enter 1 00840.847719204 6533 npviewer.bin id=142, args=198raw_syscalls__sys_enter 1 00840.847755445 6533 npviewer.bin id=3, args=199raw_syscalls__sys_enter 1 00840.847775601 6533 npviewer.bin id=3, args=200raw_syscalls__sys_enter 1 00840.847781820 6533 npviewer.bin id=3, args=201.202.203.204----205 206Of course, for this script, we're not interested in printing every207trace event, but rather aggregating it in a useful way. So we'll get208rid of everything to do with printing as well as the trace_begin() and209trace_unhandled() functions, which we won't be using. That leaves us210with this minimalistic skeleton:211 212----213import os214import sys215 216sys.path.append(os.environ['PERF_EXEC_PATH'] + \217 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')218 219from perf_trace_context import *220from Core import *221 222def trace_end():223 print "in trace_end"224 225def raw_syscalls__sys_enter(event_name, context, common_cpu,226 common_secs, common_nsecs, common_pid, common_comm,227 id, args):228----229 230In trace_end(), we'll simply print the results, but first we need to231generate some results to print. To do that we need to have our232sys_enter() handler do the necessary tallying until all events have233been counted. A hash table indexed by syscall id is a good way to234store that information; every time the sys_enter() handler is called,235we simply increment a count associated with that hash entry indexed by236that syscall id:237 238----239 syscalls = autodict()240 241 try:242 syscalls[id] += 1243 except TypeError:244 syscalls[id] = 1245----246 247The syscalls 'autodict' object is a special kind of Python dictionary248(implemented in Core.py) that implements Perl's 'autovivifying' hashes249in Python i.e. with autovivifying hashes, you can assign nested hash250values without having to go to the trouble of creating intermediate251levels if they don't exist e.g syscalls[comm][pid][id] = 1 will create252the intermediate hash levels and finally assign the value 1 to the253hash entry for 'id' (because the value being assigned isn't a hash254object itself, the initial value is assigned in the TypeError255exception. Well, there may be a better way to do this in Python but256that's what works for now).257 258Putting that code into the raw_syscalls__sys_enter() handler, we259effectively end up with a single-level dictionary keyed on syscall id260and having the counts we've tallied as values.261 262The print_syscall_totals() function iterates over the entries in the263dictionary and displays a line for each entry containing the syscall264name (the dictionary keys contain the syscall ids, which are passed to265the Util function syscall_name(), which translates the raw syscall266numbers to the corresponding syscall name strings). The output is267displayed after all the events in the trace have been processed, by268calling the print_syscall_totals() function from the trace_end()269handler called at the end of script processing.270 271The final script producing the output shown above is shown in its272entirety below (syscall_name() helper is not yet available, you can273only deal with id's for now):274 275----276import os277import sys278 279sys.path.append(os.environ['PERF_EXEC_PATH'] + \280 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')281 282from perf_trace_context import *283from Core import *284from Util import *285 286syscalls = autodict()287 288def trace_end():289 print_syscall_totals()290 291def raw_syscalls__sys_enter(event_name, context, common_cpu,292 common_secs, common_nsecs, common_pid, common_comm,293 id, args):294 try:295 syscalls[id] += 1296 except TypeError:297 syscalls[id] = 1298 299def print_syscall_totals():300 if for_comm is not None:301 print "\nsyscall events for %s:\n\n" % (for_comm),302 else:303 print "\nsyscall events:\n\n",304 305 print "%-40s %10s\n" % ("event", "count"),306 print "%-40s %10s\n" % ("----------------------------------------", \307 "-----------"),308 309 for id, val in sorted(syscalls.iteritems(), key = lambda(k, v): (v, k), \310 reverse = True):311 print "%-40s %10d\n" % (syscall_name(id), val),312----313 314The script can be run just as before:315 316 # perf script -s syscall-counts.py317 318So those are the essential steps in writing and running a script. The319process can be generalized to any tracepoint or set of tracepoints320you're interested in - basically find the tracepoint(s) you're321interested in by looking at the list of available events shown by322'perf list' and/or look in /sys/kernel/tracing/events/ for323detailed event and field info, record the corresponding trace data324using 'perf record', passing it the list of interesting events,325generate a skeleton script using 'perf script -g python' and modify the326code to aggregate and display it for your particular needs.327 328After you've done that you may end up with a general-purpose script329that you want to keep around and have available for future use. By330writing a couple of very simple shell scripts and putting them in the331right place, you can have your script listed alongside the other332scripts listed by the 'perf script -l' command e.g.:333 334----335# perf script -l336List of available trace scripts:337 wakeup-latency system-wide min/max/avg wakeup latency338 rw-by-file <comm> r/w activity for a program, by file339 rw-by-pid system-wide r/w activity340----341 342A nice side effect of doing this is that you also then capture the343probably lengthy 'perf record' command needed to record the events for344the script.345 346To have the script appear as a 'built-in' script, you write two simple347scripts, one for recording and one for 'reporting'.348 349The 'record' script is a shell script with the same base name as your350script, but with -record appended. The shell script should be put351into the perf/scripts/python/bin directory in the kernel source tree.352In that script, you write the 'perf record' command-line needed for353your script:354 355----356# cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-record357 358#!/bin/bash359perf record -a -e raw_syscalls:sys_enter360----361 362The 'report' script is also a shell script with the same base name as363your script, but with -report appended. It should also be located in364the perf/scripts/python/bin directory. In that script, you write the365'perf script -s' command-line needed for running your script:366 367----368# cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-report369 370#!/bin/bash371# description: system-wide syscall counts372perf script -s ~/libexec/perf-core/scripts/python/syscall-counts.py373----374 375Note that the location of the Python script given in the shell script376is in the libexec/perf-core/scripts/python directory - this is where377the script will be copied by 'make install' when you install perf.378For the installation to install your script there, your script needs379to be located in the perf/scripts/python directory in the kernel380source tree:381 382----383# ls -al kernel-source/tools/perf/scripts/python384total 32385drwxr-xr-x 4 trz trz 4096 2010-01-26 22:30 .386drwxr-xr-x 4 trz trz 4096 2010-01-26 22:29 ..387drwxr-xr-x 2 trz trz 4096 2010-01-26 22:29 bin388-rw-r--r-- 1 trz trz 2548 2010-01-26 22:29 check-perf-script.py389drwxr-xr-x 3 trz trz 4096 2010-01-26 22:49 Perf-Trace-Util390-rw-r--r-- 1 trz trz 1462 2010-01-26 22:30 syscall-counts.py391----392 393Once you've done that (don't forget to do a new 'make install',394otherwise your script won't show up at run-time), 'perf script -l'395should show a new entry for your script:396 397----398# perf script -l399List of available trace scripts:400 wakeup-latency system-wide min/max/avg wakeup latency401 rw-by-file <comm> r/w activity for a program, by file402 rw-by-pid system-wide r/w activity403 syscall-counts system-wide syscall counts404----405 406You can now perform the record step via 'perf script record':407 408 # perf script record syscall-counts409 410and display the output using 'perf script report':411 412 # perf script report syscall-counts413 414STARTER SCRIPTS415---------------416 417You can quickly get started writing a script for a particular set of418trace data by generating a skeleton script using 'perf script -g419python' in the same directory as an existing perf.data trace file.420That will generate a starter script containing a handler for each of421the event types in the trace file; it simply prints every available422field for each event in the trace file.423 424You can also look at the existing scripts in425~/libexec/perf-core/scripts/python for typical examples showing how to426do basic things like aggregate event data, print results, etc. Also,427the check-perf-script.py script, while not interesting for its results,428attempts to exercise all of the main scripting features.429 430EVENT HANDLERS431--------------432 433When perf script is invoked using a trace script, a user-defined434'handler function' is called for each event in the trace. If there's435no handler function defined for a given event type, the event is436ignored (or passed to a 'trace_unhandled' function, see below) and the437next event is processed.438 439Most of the event's field values are passed as arguments to the440handler function; some of the less common ones aren't - those are441available as calls back into the perf executable (see below).442 443As an example, the following perf record command can be used to record444all sched_wakeup events in the system:445 446 # perf record -a -e sched:sched_wakeup447 448Traces meant to be processed using a script should be recorded with449the above option: -a to enable system-wide collection.450 451The format file for the sched_wakeup event defines the following fields452(see /sys/kernel/tracing/events/sched/sched_wakeup/format):453 454----455 format:456 field:unsigned short common_type;457 field:unsigned char common_flags;458 field:unsigned char common_preempt_count;459 field:int common_pid;460 461 field:char comm[TASK_COMM_LEN];462 field:pid_t pid;463 field:int prio;464 field:int success;465 field:int target_cpu;466----467 468The handler function for this event would be defined as:469 470----471def sched__sched_wakeup(event_name, context, common_cpu, common_secs,472 common_nsecs, common_pid, common_comm,473 comm, pid, prio, success, target_cpu):474 pass475----476 477The handler function takes the form subsystem__event_name.478 479The common_* arguments in the handler's argument list are the set of480arguments passed to all event handlers; some of the fields correspond481to the common_* fields in the format file, but some are synthesized,482and some of the common_* fields aren't common enough to to be passed483to every event as arguments but are available as library functions.484 485Here's a brief description of each of the invariant event args:486 487 event_name the name of the event as text488 context an opaque 'cookie' used in calls back into perf489 common_cpu the cpu the event occurred on490 common_secs the secs portion of the event timestamp491 common_nsecs the nsecs portion of the event timestamp492 common_pid the pid of the current task493 common_comm the name of the current process494 495All of the remaining fields in the event's format file have496counterparts as handler function arguments of the same name, as can be497seen in the example above.498 499The above provides the basics needed to directly access every field of500every event in a trace, which covers 90% of what you need to know to501write a useful trace script. The sections below cover the rest.502 503SCRIPT LAYOUT504-------------505 506Every perf script Python script should start by setting up a Python507module search path and 'import'ing a few support modules (see module508descriptions below):509 510----511 import os512 import sys513 514 sys.path.append(os.environ['PERF_EXEC_PATH'] + \515 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')516 517 from perf_trace_context import *518 from Core import *519----520 521The rest of the script can contain handler functions and support522functions in any order.523 524Aside from the event handler functions discussed above, every script525can implement a set of optional functions:526 527*trace_begin*, if defined, is called before any event is processed and528gives scripts a chance to do setup tasks:529 530----531def trace_begin():532 pass533----534 535*trace_end*, if defined, is called after all events have been536 processed and gives scripts a chance to do end-of-script tasks, such537 as display results:538 539----540def trace_end():541 pass542----543 544*trace_unhandled*, if defined, is called after for any event that545 doesn't have a handler explicitly defined for it. The standard set546 of common arguments are passed into it:547 548----549def trace_unhandled(event_name, context, event_fields_dict):550 pass551----552 553*process_event*, if defined, is called for any non-tracepoint event554 555----556def process_event(param_dict):557 pass558----559 560*context_switch*, if defined, is called for any context switch561 562----563def context_switch(ts, cpu, pid, tid, np_pid, np_tid, machine_pid, out, out_preempt, *x):564 pass565----566 567*auxtrace_error*, if defined, is called for any AUX area tracing error568 569----570def auxtrace_error(typ, code, cpu, pid, tid, ip, ts, msg, cpumode, *x):571 pass572----573 574The remaining sections provide descriptions of each of the available575built-in perf script Python modules and their associated functions.576 577AVAILABLE MODULES AND FUNCTIONS578-------------------------------579 580The following sections describe the functions and variables available581via the various perf script Python modules. To use the functions and582variables from the given module, add the corresponding 'from XXXX583import' line to your perf script script.584 585Core.py Module586~~~~~~~~~~~~~~587 588These functions provide some essential functions to user scripts.589 590The *flag_str* and *symbol_str* functions provide human-readable591strings for flag and symbolic fields. These correspond to the strings592and values parsed from the 'print fmt' fields of the event format593files:594 595 flag_str(event_name, field_name, field_value) - returns the string representation corresponding to field_value for the flag field field_name of event event_name596 symbol_str(event_name, field_name, field_value) - returns the string representation corresponding to field_value for the symbolic field field_name of event event_name597 598The *autodict* function returns a special kind of Python599dictionary that implements Perl's 'autovivifying' hashes in Python600i.e. with autovivifying hashes, you can assign nested hash values601without having to go to the trouble of creating intermediate levels if602they don't exist.603 604 autodict() - returns an autovivifying dictionary instance605 606 607perf_trace_context Module608~~~~~~~~~~~~~~~~~~~~~~~~~609 610Some of the 'common' fields in the event format file aren't all that611common, but need to be made accessible to user scripts nonetheless.612 613perf_trace_context defines a set of functions that can be used to614access this data in the context of the current event. Each of these615functions expects a context variable, which is the same as the616context variable passed into every tracepoint event handler as the second617argument. For non-tracepoint events, the context variable is also present618as perf_trace_context.perf_script_context .619 620 common_pc(context) - returns common_preempt count for the current event621 common_flags(context) - returns common_flags for the current event622 common_lock_depth(context) - returns common_lock_depth for the current event623 perf_sample_insn(context) - returns the machine code instruction624 perf_set_itrace_options(context, itrace_options) - set --itrace options if they have not been set already625 perf_sample_srcline(context) - returns source_file_name, line_number626 perf_sample_srccode(context) - returns source_file_name, line_number, source_line627 628 629Util.py Module630~~~~~~~~~~~~~~631 632Various utility functions for use with perf script:633 634 nsecs(secs, nsecs) - returns total nsecs given secs/nsecs pair635 nsecs_secs(nsecs) - returns whole secs portion given nsecs636 nsecs_nsecs(nsecs) - returns nsecs remainder given nsecs637 nsecs_str(nsecs) - returns printable string in the form secs.nsecs638 avg(total, n) - returns average given a sum and a total number of values639 640SUPPORTED FIELDS641----------------642 643Currently supported fields:644 645ev_name, comm, id, stream_id, pid, tid, cpu, ip, time, period, phys_addr,646addr, symbol, symoff, dso, time_enabled, time_running, values, callchain,647brstack, brstacksym, datasrc, datasrc_decode, iregs, uregs,648weight, transaction, raw_buf, attr, cpumode.649 650Fields that may also be present:651 652 flags - sample flags653 flags_disp - sample flags display654 insn_cnt - instruction count for determining instructions-per-cycle (IPC)655 cyc_cnt - cycle count for determining IPC656 addr_correlates_sym - addr can correlate to a symbol657 addr_dso - addr dso658 addr_symbol - addr symbol659 addr_symoff - addr symbol offset660 661Some fields have sub items:662 663brstack:664 from, to, from_dsoname, to_dsoname, mispred,665 predicted, in_tx, abort, cycles.666 667brstacksym:668 items: from, to, pred, in_tx, abort (converted string)669 670For example,671We can use this code to print brstack "from", "to", "cycles".672 673if 'brstack' in dict:674 for entry in dict['brstack']:675 print "from %s, to %s, cycles %s" % (entry["from"], entry["to"], entry["cycles"])676 677SEE ALSO678--------679linkperf:perf-script[1]680