1PERF-SCRIPT-PYTHON(1)             perf Manual            PERF-SCRIPT-PYTHON(1)
2
3
4

NAME

6       perf-script-python - Process trace data with a Python script
7

SYNOPSIS

9       perf script [-s [Python]:script[.py] ]
10

DESCRIPTION

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

A QUICK EXAMPLE

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
25       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
31       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
36
37           .ft C
38           syscall events:
39
40           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
68
69       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
74       ·   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
81       ·   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
86       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
90
91           .ft C
92           # perf record -a -e raw_syscalls:sys_enter
93
94           ^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
98
99       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
104       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
109
110           .ft C
111           # perf script -g python
112           generated Python script: perf-script.py
113
114           The output file created also in the current directory is named
115           perf-script.py.  Here's the file in its entirety:
116
117           # perf script event handlers, generated by perf script -g python
118           # Licensed under the terms of the GNU GPL License version 2
119
120           # 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
126           import os
127           import sys
128
129           sys.path.append(os.environ['PERF_EXEC_PATH'] + \
130                   '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
131
132           from perf_trace_context import *
133           from Core import *
134
135           def trace_begin():
136                   print "in trace_begin"
137
138           def trace_end():
139                   print "in trace_end"
140
141           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
147                           print "id=%d, args=%s\n" % \
148                           (id, args),
149
150           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
153           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
158
159       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
162       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
167       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
174       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
182       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
188
189           .ft C
190           # mv perf-script.py syscall-counts.py
191           # perf script -s syscall-counts.py
192
193           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
206
207       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
213
214           .ft C
215           import os
216           import sys
217
218           sys.path.append(os.environ['PERF_EXEC_PATH'] + \
219                   '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
220
221           from perf_trace_context import *
222           from Core import *
223
224           def trace_end():
225                   print "in trace_end"
226
227           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
232
233       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
241
242           .ft C
243             syscalls = autodict()
244
245             try:
246               syscalls[id] += 1
247             except TypeError:
248               syscalls[id] = 1
249           .ft
250
251
252       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
263       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
267       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
276       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
280
281           .ft C
282           import os
283           import sys
284
285           sys.path.append(os.environ['PERF_EXEC_PATH'] + \
286                   '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
287
288           from perf_trace_context import *
289           from Core import *
290           from Util import *
291
292           syscalls = autodict()
293
294           def trace_end():
295                   print_syscall_totals()
296
297           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
305           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
311               print "%-40s  %10s\n" % ("event", "count"),
312               print "%-40s  %10s\n" % ("----------------------------------------", \
313                                            "-----------"),
314
315               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
320
321       The script can be run just as before:
322
323           # perf script -s syscall-counts.py
324
325       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
335       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
341
342           .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
350
351       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
355       To have the script appear as a built-in script, you write two simple
356       scripts, one for recording and one for reporting.
357
358       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
364
365           .ft C
366           # cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-record
367
368           #!/bin/bash
369           perf record -a -e raw_syscalls:sys_enter
370           .ft
371
372
373       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
378
379           .ft C
380           # cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-report
381
382           #!/bin/bash
383           # description: system-wide syscall counts
384           perf script -s ~/libexec/perf-core/scripts/python/syscall-counts.py
385           .ft
386
387
388       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
394
395           .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
406
407       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
411
412           .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
421
422       You can now perform the record step via perf script record:
423
424           # perf script record syscall-counts
425
426       and display the output using perf script report:
427
428           # perf script report syscall-counts
429

STARTER SCRIPTS

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
438       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

EVENT HANDLERS

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
451       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
455       As an example, the following perf record command can be used to record
456       all sched_wakeup events in the system:
457
458           # perf record -a -e sched:sched_wakeup
459
460       Traces meant to be processed using a script should be recorded with the
461       above option: -a to enable system-wide collection.
462
463       The format file for the sched_wakep event defines the following fields
464       (see /sys/kernel/debug/tracing/events/sched/sched_wakeup/format):
465
466
467           .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
474                   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
481
482       The handler function for this event would be defined as:
483
484
485           .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
492
493       The handler function takes the form subsystem__event_name.
494
495       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
501       Here’s a brief description of each of the invariant event args:
502
503           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
511       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
515       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

SCRIPT LAYOUT

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
524
525           .ft C
526            import os
527            import sys
528
529            sys.path.append(os.environ['PERF_EXEC_PATH'] + \
530                         '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
531
532            from perf_trace_context import *
533            from Core import *
534           .ft
535
536
537       The rest of the script can contain handler functions and support
538       functions in any order.
539
540       Aside from the event handler functions discussed above, every script
541       can implement a set of optional functions:
542
543       trace_begin, if defined, is called before any event is processed and
544       gives scripts a chance to do setup tasks:
545
546
547           .ft C
548           def trace_begin():
549               pass
550           .ft
551
552
553       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
557
558           .ft C
559           def trace_end():
560               pass
561           .ft
562
563
564       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
568
569           .ft C
570           def trace_unhandled(event_name, context, event_fields_dict):
571               pass
572           .ft
573
574
575       The remaining sections provide descriptions of each of the available
576       built-in perf script Python modules and their associated functions.
577

AVAILABLE MODULES AND FUNCTIONS

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
584   Core.py Module
585       These functions provide some essential functions to user scripts.
586
587       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
591           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
594       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
600           autodict() - returns an autovivifying dictionary instance
601
602   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
606       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
611           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
615   Util.py Module
616       Various utility functions for use with perf script:
617
618           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

SUPPORTED FIELDS

625       Currently supported fields:
626
627       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
632       Some fields have sub items:
633
634       brstack: from, to, from_dsoname, to_dsoname, mispred, predicted, in_tx,
635       abort, cycles.
636
637       brstacksym: items: from, to, pred, in_tx, abort (converted string)
638
639       For example, We can use this code to print brstack "from", "to",
640       "cycles".
641
642       if brstack in dict: for entry in dict[brstack]: print "from %s, to %s,
643       cycles %s" % (entry["from"], entry["to"], entry["cycles"])
644

SEE ALSO

646       perf-script(1)
647
648
649
650perf                              03/30/2021             PERF-SCRIPT-PYTHON(1)
Impressum