1PERF-SCRIPT-PYTHON(1) perf Manual PERF-SCRIPT-PYTHON(1)
2
6 perf-script-python - Process trace data with a Python script
7
9 perf script [-s [Python]:script[.py] ]
10
12 This perf script option is used to process perf script data using
13 perf’s built-in Python interpreter. It reads and processes the input
14 file and displays the results of the trace analysis implemented in the
15 given Python script, if any.
16
18 This section shows the process, start to finish, of creating a working
19 Python script that aggregates and extracts useful information from a
20 raw perf script stream. You can avoid reading the rest of this document
21 if an example is enough for you; the rest of the document provides more
22 details on each step and lists the library functions available to
23 script writers.
24 This example actually details the steps that were used to create the
26 syscall-counts script you see when you list the available perf script
27 scripts via perf script -l. As such, this script also shows how to
28 integrate your script into the list of general-purpose perf script
29 scripts listed by that command.
30 The syscall-counts script is a simple script, but demonstrates all the
32 basic ideas necessary to create a useful script. Here’s an example of
33 its output (syscall names are not yet supported, they will appear as
34 numbers):
35 .ft C
38 syscall events:
39 event count
41 ---------------------------------------- -----------
42 sys_write 455067
43 sys_getdents 4072
44 sys_close 3037
45 sys_swapoff 1769
46 sys_read 923
47 sys_sched_setparam 826
48 sys_open 331
49 sys_newfstat 326
50 sys_mmap 217
51 sys_munmap 216
52 sys_futex 141
53 sys_select 102
54 sys_poll 84
55 sys_setitimer 12
56 sys_writev 8
57 15 8
58 sys_lseek 7
59 sys_rt_sigprocmask 6
60 sys_wait4 3
61 sys_ioctl 3
62 sys_set_robust_list 1
63 sys_exit 1
64 56 1
65 sys_access 1
66 .ft
67 Basically our task is to keep a per-syscall tally that gets updated
70 every time a system call occurs in the system. Our script will do that,
71 but first we need to record the data that will be processed by that
72 script. Theoretically, there are a couple of ways we could do that:
73 · we could enable every event under the tracing/events/syscalls
75 directory, but this is over 600 syscalls, well beyond the number
76 allowable by perf. These individual syscall events will however be
77 useful if we want to later use the guidance we get from the
78 general-purpose scripts to drill down and get more detail about
79 individual syscalls of interest.
80 · we can enable the sys_enter and/or sys_exit syscalls found under
82 tracing/events/raw_syscalls. These are called for all syscalls; the
83 id field can be used to distinguish between individual syscall
84 numbers.
85 For this script, we only need to know that a syscall was entered; we
87 don’t care how it exited, so we’ll use perf record to record only the
88 sys_enter events:
89 .ft C
92 # perf record -a -e raw_syscalls:sys_enter
93 ^C[ perf record: Woken up 1 times to write data ]
95 [ perf record: Captured and wrote 56.545 MB perf.data (~2470503 samples) ]
96 .ft
97 The options basically say to collect data for every syscall event
100 system-wide and multiplex the per-cpu output into a single stream. That
101 single stream will be recorded in a file in the current directory
102 called perf.data.
103 Once we have a perf.data file containing our data, we can use the -g
105 perf script option to generate a Python script that will contain a
106 callback handler for each event type found in the perf.data trace
107 stream (for more details, see the STARTER SCRIPTS section).
108 .ft C
111 # perf script -g python
112 generated Python script: perf-script.py
113 The output file created also in the current directory is named
115 perf-script.py. Here's the file in its entirety:
116 # perf script event handlers, generated by perf script -g python
118 # Licensed under the terms of the GNU GPL License version 2
119 # The common_* event handler fields are the most useful fields common to
121 # all events. They don't necessarily correspond to the 'common_*' fields
122 # in the format files. Those fields not available as handler params can
123 # be retrieved using Python functions of the form common_*(context).
124 # See the perf-script-python Documentation for the list of available functions.
125 import os
127 import sys
128 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
130 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
131 from perf_trace_context import *
133 from Core import *
134 def trace_begin():
136 print "in trace_begin"
137 def trace_end():
139 print "in trace_end"
140 def raw_syscalls__sys_enter(event_name, context, common_cpu,
142 common_secs, common_nsecs, common_pid, common_comm,
143 id, args):
144 print_header(event_name, common_cpu, common_secs, common_nsecs,
145 common_pid, common_comm)
146 print "id=%d, args=%s\n" % \
148 (id, args),
149 def trace_unhandled(event_name, context, event_fields_dict):
151 print ' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())])
152 def print_header(event_name, cpu, secs, nsecs, pid, comm):
154 print "%-20s %5u %05u.%09u %8u %-20s " % \
155 (event_name, cpu, secs, nsecs, pid, comm),
156 .ft
157 At the top is a comment block followed by some import statements and a
160 path append which every perf script script should include.
161 Following that are a couple generated functions, trace_begin() and
163 trace_end(), which are called at the beginning and the end of the
164 script respectively (for more details, see the SCRIPT_LAYOUT section
165 below).
166 Following those are the event handler functions generated one for every
168 event in the perf record output. The handler functions take the form
169 subsystemevent_name, and contain named parameters, one for each field
170 in the event; in this case, there’s only one event,
171 raw_syscallssys_enter(). (see the EVENT HANDLERS section below for more
172 info on event handlers).
173 The final couple of functions are, like the begin and end functions,
175 generated for every script. The first, trace_unhandled(), is called
176 every time the script finds an event in the perf.data file that doesn’t
177 correspond to any event handler in the script. This could mean either
178 that the record step recorded event types that it wasn’t really
179 interested in, or the script was run against a trace file that doesn’t
180 correspond to the script.
181 The script generated by -g option simply prints a line for each event
183 found in the trace stream i.e. it basically just dumps the event and
184 its parameter values to stdout. The print_header() function is simply a
185 utility function used for that purpose. Let’s rename the script and run
186 it to see the default output:
187 .ft C
190 # mv perf-script.py syscall-counts.py
191 # perf script -s syscall-counts.py
192 raw_syscalls__sys_enter 1 00840.847582083 7506 perf id=1, args=
194 raw_syscalls__sys_enter 1 00840.847595764 7506 perf id=1, args=
195 raw_syscalls__sys_enter 1 00840.847620860 7506 perf id=1, args=
196 raw_syscalls__sys_enter 1 00840.847710478 6533 npviewer.bin id=78, args=
197 raw_syscalls__sys_enter 1 00840.847719204 6533 npviewer.bin id=142, args=
198 raw_syscalls__sys_enter 1 00840.847755445 6533 npviewer.bin id=3, args=
199 raw_syscalls__sys_enter 1 00840.847775601 6533 npviewer.bin id=3, args=
200 raw_syscalls__sys_enter 1 00840.847781820 6533 npviewer.bin id=3, args=
201 .
202 .
203 .
204 .ft
205 Of course, for this script, we’re not interested in printing every
208 trace event, but rather aggregating it in a useful way. So we’ll get
209 rid of everything to do with printing as well as the trace_begin() and
210 trace_unhandled() functions, which we won’t be using. That leaves us
211 with this minimalistic skeleton:
212 .ft C
215 import os
216 import sys
217 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
219 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
220 from perf_trace_context import *
222 from Core import *
223 def trace_end():
225 print "in trace_end"
226 def raw_syscalls__sys_enter(event_name, context, common_cpu,
228 common_secs, common_nsecs, common_pid, common_comm,
229 id, args):
230 .ft
231 In trace_end(), we’ll simply print the results, but first we need to
234 generate some results to print. To do that we need to have our
235 sys_enter() handler do the necessary tallying until all events have
236 been counted. A hash table indexed by syscall id is a good way to store
237 that information; every time the sys_enter() handler is called, we
238 simply increment a count associated with that hash entry indexed by
239 that syscall id:
240 .ft C
243 syscalls = autodict()
244 try:
246 syscalls[id] += 1
247 except TypeError:
248 syscalls[id] = 1
249 .ft
250 The syscalls autodict object is a special kind of Python dictionary
253 (implemented in Core.py) that implements Perl’s autovivifying hashes in
254 Python i.e. with autovivifying hashes, you can assign nested hash
255 values without having to go to the trouble of creating intermediate
256 levels if they don’t exist e.g syscalls[comm][pid][id] = 1 will create
257 the intermediate hash levels and finally assign the value 1 to the hash
258 entry for id (because the value being assigned isn’t a hash object
259 itself, the initial value is assigned in the TypeError exception. Well,
260 there may be a better way to do this in Python but that’s what works
261 for now).
262 Putting that code into the raw_syscalls__sys_enter() handler, we
264 effectively end up with a single-level dictionary keyed on syscall id
265 and having the counts we’ve tallied as values.
266 The print_syscall_totals() function iterates over the entries in the
268 dictionary and displays a line for each entry containing the syscall
269 name (the dictionary keys contain the syscall ids, which are passed to
270 the Util function syscall_name(), which translates the raw syscall
271 numbers to the corresponding syscall name strings). The output is
272 displayed after all the events in the trace have been processed, by
273 calling the print_syscall_totals() function from the trace_end()
274 handler called at the end of script processing.
275 The final script producing the output shown above is shown in its
277 entirety below (syscall_name() helper is not yet available, you can
278 only deal with id’s for now):
279 .ft C
282 import os
283 import sys
284 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
286 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
287 from perf_trace_context import *
289 from Core import *
290 from Util import *
291 syscalls = autodict()
293 def trace_end():
295 print_syscall_totals()
296 def raw_syscalls__sys_enter(event_name, context, common_cpu,
298 common_secs, common_nsecs, common_pid, common_comm,
299 id, args):
300 try:
301 syscalls[id] += 1
302 except TypeError:
303 syscalls[id] = 1
304 def print_syscall_totals():
306 if for_comm is not None:
307 print "\nsyscall events for %s:\n\n" % (for_comm),
308 else:
309 print "\nsyscall events:\n\n",
310 print "%-40s %10s\n" % ("event", "count"),
312 print "%-40s %10s\n" % ("----------------------------------------", \
313 "-----------"),
314 for id, val in sorted(syscalls.iteritems(), key = lambda(k, v): (v, k), \
316 reverse = True):
317 print "%-40s %10d\n" % (syscall_name(id), val),
318 .ft
319 The script can be run just as before:
322 # perf script -s syscall-counts.py
324 So those are the essential steps in writing and running a script. The
326 process can be generalized to any tracepoint or set of tracepoints
327 you’re interested in - basically find the tracepoint(s) you’re
328 interested in by looking at the list of available events shown by perf
329 list and/or look in /sys/kernel/debug/tracing/events/ for detailed
330 event and field info, record the corresponding trace data using perf
331 record, passing it the list of interesting events, generate a skeleton
332 script using perf script -g python and modify the code to aggregate and
333 display it for your particular needs.
334 After you’ve done that you may end up with a general-purpose script
336 that you want to keep around and have available for future use. By
337 writing a couple of very simple shell scripts and putting them in the
338 right place, you can have your script listed alongside the other
339 scripts listed by the perf script -l command e.g.:
340 .ft C
343 # perf script -l
344 List of available trace scripts:
345 wakeup-latency system-wide min/max/avg wakeup latency
346 rw-by-file <comm> r/w activity for a program, by file
347 rw-by-pid system-wide r/w activity
348 .ft
349 A nice side effect of doing this is that you also then capture the
352 probably lengthy perf record command needed to record the events for
353 the script.
354 To have the script appear as a built-in script, you write two simple
356 scripts, one for recording and one for reporting.
357 The record script is a shell script with the same base name as your
359 script, but with -record appended. The shell script should be put into
360 the perf/scripts/python/bin directory in the kernel source tree. In
361 that script, you write the perf record command-line needed for your
362 script:
363 .ft C
366 # cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-record
367 #!/bin/bash
369 perf record -a -e raw_syscalls:sys_enter
370 .ft
371 The report script is also a shell script with the same base name as
374 your script, but with -report appended. It should also be located in
375 the perf/scripts/python/bin directory. In that script, you write the
376 perf script -s command-line needed for running your script:
377 .ft C
380 # cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-report
381 #!/bin/bash
383 # description: system-wide syscall counts
384 perf script -s ~/libexec/perf-core/scripts/python/syscall-counts.py
385 .ft
386 Note that the location of the Python script given in the shell script
389 is in the libexec/perf-core/scripts/python directory - this is where
390 the script will be copied by make install when you install perf. For
391 the installation to install your script there, your script needs to be
392 located in the perf/scripts/python directory in the kernel source tree:
393 .ft C
396 # ls -al kernel-source/tools/perf/scripts/python
397 total 32
398 drwxr-xr-x 4 trz trz 4096 2010-01-26 22:30 .
399 drwxr-xr-x 4 trz trz 4096 2010-01-26 22:29 ..
400 drwxr-xr-x 2 trz trz 4096 2010-01-26 22:29 bin
401 -rw-r--r-- 1 trz trz 2548 2010-01-26 22:29 check-perf-script.py
402 drwxr-xr-x 3 trz trz 4096 2010-01-26 22:49 Perf-Trace-Util
403 -rw-r--r-- 1 trz trz 1462 2010-01-26 22:30 syscall-counts.py
404 .ft
405 Once you’ve done that (don’t forget to do a new make install, otherwise
408 your script won’t show up at run-time), perf script -l should show a
409 new entry for your script:
410 .ft C
413 # perf script -l
414 List of available trace scripts:
415 wakeup-latency system-wide min/max/avg wakeup latency
416 rw-by-file <comm> r/w activity for a program, by file
417 rw-by-pid system-wide r/w activity
418 syscall-counts system-wide syscall counts
419 .ft
420 You can now perform the record step via perf script record:
423 # perf script record syscall-counts
425 and display the output using perf script report:
427 # perf script report syscall-counts
429
431 You can quickly get started writing a script for a particular set of
432 trace data by generating a skeleton script using perf script -g python
433 in the same directory as an existing perf.data trace file. That will
434 generate a starter script containing a handler for each of the event
435 types in the trace file; it simply prints every available field for
436 each event in the trace file.
437 You can also look at the existing scripts in
439 ~/libexec/perf-core/scripts/python for typical examples showing how to
440 do basic things like aggregate event data, print results, etc. Also,
441 the check-perf-script.py script, while not interesting for its results,
442 attempts to exercise all of the main scripting features.
443
445 When perf script is invoked using a trace script, a user-defined
446 handler function is called for each event in the trace. If there’s no
447 handler function defined for a given event type, the event is ignored
448 (or passed to a trace_unhandled function, see below) and the next event
449 is processed.
450 Most of the event’s field values are passed as arguments to the handler
452 function; some of the less common ones aren’t - those are available as
453 calls back into the perf executable (see below).
454 As an example, the following perf record command can be used to record
456 all sched_wakeup events in the system:
457 # perf record -a -e sched:sched_wakeup
459 Traces meant to be processed using a script should be recorded with the
461 above option: -a to enable system-wide collection.
462 The format file for the sched_wakep event defines the following fields
464 (see /sys/kernel/debug/tracing/events/sched/sched_wakeup/format):
465 .ft C
468 format:
469 field:unsigned short common_type;
470 field:unsigned char common_flags;
471 field:unsigned char common_preempt_count;
472 field:int common_pid;
473 field:char comm[TASK_COMM_LEN];
475 field:pid_t pid;
476 field:int prio;
477 field:int success;
478 field:int target_cpu;
479 .ft
480 The handler function for this event would be defined as:
483 .ft C
486 def sched__sched_wakeup(event_name, context, common_cpu, common_secs,
487 common_nsecs, common_pid, common_comm,
488 comm, pid, prio, success, target_cpu):
489 pass
490 .ft
491 The handler function takes the form subsystem__event_name.
494 The common_* arguments in the handler’s argument list are the set of
496 arguments passed to all event handlers; some of the fields correspond
497 to the common_* fields in the format file, but some are synthesized,
498 and some of the common_* fields aren’t common enough to to be passed to
499 every event as arguments but are available as library functions.
500 Here’s a brief description of each of the invariant event args:
502 event_name the name of the event as text
504 context an opaque 'cookie' used in calls back into perf
505 common_cpu the cpu the event occurred on
506 common_secs the secs portion of the event timestamp
507 common_nsecs the nsecs portion of the event timestamp
508 common_pid the pid of the current task
509 common_comm the name of the current process
510 All of the remaining fields in the event’s format file have
512 counterparts as handler function arguments of the same name, as can be
513 seen in the example above.
514 The above provides the basics needed to directly access every field of
516 every event in a trace, which covers 90% of what you need to know to
517 write a useful trace script. The sections below cover the rest.
518
520 Every perf script Python script should start by setting up a Python
521 module search path and 'import’ing a few support modules (see module
522 descriptions below):
523 .ft C
526 import os
527 import sys
528 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
530 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
531 from perf_trace_context import *
533 from Core import *
534 .ft
535 The rest of the script can contain handler functions and support
538 functions in any order.
539 Aside from the event handler functions discussed above, every script
541 can implement a set of optional functions:
542 trace_begin, if defined, is called before any event is processed and
544 gives scripts a chance to do setup tasks:
545 .ft C
548 def trace_begin():
549 pass
550 .ft
551 trace_end, if defined, is called after all events have been processed
554 and gives scripts a chance to do end-of-script tasks, such as display
555 results:
556 .ft C
559 def trace_end():
560 pass
561 .ft
562 trace_unhandled, if defined, is called after for any event that doesn’t
565 have a handler explicitly defined for it. The standard set of common
566 arguments are passed into it:
567 .ft C
570 def trace_unhandled(event_name, context, event_fields_dict):
571 pass
572 .ft
573 The remaining sections provide descriptions of each of the available
576 built-in perf script Python modules and their associated functions.
577
579 The following sections describe the functions and variables available
580 via the various perf script Python modules. To use the functions and
581 variables from the given module, add the corresponding from XXXX import
582 line to your perf script script.
583 Core.py Module
585 These functions provide some essential functions to user scripts.
586 The flag_str and symbol_str functions provide human-readable strings
588 for flag and symbolic fields. These correspond to the strings and
589 values parsed from the print fmt fields of the event format files:
590 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_name
592 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_name
593 The autodict function returns a special kind of Python dictionary that
595 implements Perl’s autovivifying hashes in Python i.e. with
596 autovivifying hashes, you can assign nested hash values without having
597 to go to the trouble of creating intermediate levels if they don’t
598 exist.
599 autodict() - returns an autovivifying dictionary instance
601 perf_trace_context Module
603 Some of the common fields in the event format file aren’t all that
604 common, but need to be made accessible to user scripts nonetheless.
605 perf_trace_context defines a set of functions that can be used to
607 access this data in the context of the current event. Each of these
608 functions expects a context variable, which is the same as the context
609 variable passed into every event handler as the second argument.
610 common_pc(context) - returns common_preempt count for the current event
612 common_flags(context) - returns common_flags for the current event
613 common_lock_depth(context) - returns common_lock_depth for the current event
614 Util.py Module
616 Various utility functions for use with perf script:
617 nsecs(secs, nsecs) - returns total nsecs given secs/nsecs pair
619 nsecs_secs(nsecs) - returns whole secs portion given nsecs
620 nsecs_nsecs(nsecs) - returns nsecs remainder given nsecs
621 nsecs_str(nsecs) - returns printable string in the form secs.nsecs
622 avg(total, n) - returns average given a sum and a total number of values
623
625 Currently supported fields:
626 ev_name, comm, pid, tid, cpu, ip, time, period, phys_addr, addr,
628 symbol, dso, time_enabled, time_running, values, callchain, brstack,
629 brstacksym, datasrc, datasrc_decode, iregs, uregs, weight, transaction,
630 raw_buf, attr.
631 Some fields have sub items:
633 brstack: from, to, from_dsoname, to_dsoname, mispred, predicted, in_tx,
635 abort, cycles.
636 brstacksym: items: from, to, pred, in_tx, abort (converted string)
638 For example, We can use this code to print brstack "from", "to",
640 "cycles".
641 if brstack in dict: for entry in dict[brstack]: print "from %s, to %s,
643 cycles %s" % (entry["from"], entry["to"], entry["cycles"])
644
646 perf-script(1)
647perf 06/03/2019 PERF-SCRIPT-PYTHON(1)