Merge tag 'block-5.9-2020-08-14' of git://git.kernel.dk/linux-block
[linux/fpc-iii.git] / tools / perf / Documentation / perf-script-python.txt
blob0fb9eda3cbcac90a338a823f72bb0c88f2a83903
1 perf-script-python(1)
2 ====================
4 NAME
5 ----
6 perf-script-python - Process trace data with a Python script
8 SYNOPSIS
9 --------
10 [verse]
11 'perf script' [-s [Python]:script[.py] ]
13 DESCRIPTION
14 -----------
16 This perf script option is used to process perf script data using perf's
17 built-in Python interpreter.  It reads and processes the input file and
18 displays the results of the trace analysis implemented in the given
19 Python script, if any.
21 A QUICK EXAMPLE
22 ---------------
24 This section shows the process, start to finish, of creating a working
25 Python script that aggregates and extracts useful information from a
26 raw perf script stream.  You can avoid reading the rest of this
27 document if an example is enough for you; the rest of the document
28 provides more details on each step and lists the library functions
29 available to script writers.
31 This example actually details the steps that were used to create the
32 'syscall-counts' script you see when you list the available perf script
33 scripts via 'perf script -l'.  As such, this script also shows how to
34 integrate your script into the list of general-purpose 'perf script'
35 scripts listed by that command.
37 The syscall-counts script is a simple script, but demonstrates all the
38 basic ideas necessary to create a useful script.  Here's an example
39 of its output (syscall names are not yet supported, they will appear
40 as numbers):
42 ----
43 syscall events:
45 event                                          count
46 ----------------------------------------  -----------
47 sys_write                                     455067
48 sys_getdents                                    4072
49 sys_close                                       3037
50 sys_swapoff                                     1769
51 sys_read                                         923
52 sys_sched_setparam                               826
53 sys_open                                         331
54 sys_newfstat                                     326
55 sys_mmap                                         217
56 sys_munmap                                       216
57 sys_futex                                        141
58 sys_select                                       102
59 sys_poll                                          84
60 sys_setitimer                                     12
61 sys_writev                                         8
62 15                                                 8
63 sys_lseek                                          7
64 sys_rt_sigprocmask                                 6
65 sys_wait4                                          3
66 sys_ioctl                                          3
67 sys_set_robust_list                                1
68 sys_exit                                           1
69 56                                                 1
70 sys_access                                         1
71 ----
73 Basically our task is to keep a per-syscall tally that gets updated
74 every time a system call occurs in the system.  Our script will do
75 that, but first we need to record the data that will be processed by
76 that script.  Theoretically, there are a couple of ways we could do
77 that:
79 - we could enable every event under the tracing/events/syscalls
80   directory, but this is over 600 syscalls, well beyond the number
81   allowable by perf.  These individual syscall events will however be
82   useful if we want to later use the guidance we get from the
83   general-purpose scripts to drill down and get more detail about
84   individual syscalls of interest.
86 - we can enable the sys_enter and/or sys_exit syscalls found under
87   tracing/events/raw_syscalls.  These are called for all syscalls; the
88   'id' field can be used to distinguish between individual syscall
89   numbers.
91 For this script, we only need to know that a syscall was entered; we
92 don't care how it exited, so we'll use 'perf record' to record only
93 the sys_enter events:
95 ----
96 # perf record -a -e raw_syscalls:sys_enter
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 ----
102 The options basically say to collect data for every syscall event
103 system-wide and multiplex the per-cpu output into a single stream.
104 That single stream will be recorded in a file in the current directory
105 called perf.data.
107 Once we have a perf.data file containing our data, we can use the -g
108 'perf script' option to generate a Python script that will contain a
109 callback handler for each event type found in the perf.data trace
110 stream (for more details, see the STARTER SCRIPTS section).
112 ----
113 # perf script -g python
114 generated Python script: perf-script.py
116 The output file created also in the current directory is named
117 perf-script.py.  Here's the file in its entirety:
119 # perf script event handlers, generated by perf script -g python
120 # Licensed under the terms of the GNU GPL License version 2
122 # The common_* event handler fields are the most useful fields common to
123 # all events.  They don't necessarily correspond to the 'common_*' fields
124 # in the format files.  Those fields not available as handler params can
125 # be retrieved using Python functions of the form common_*(context).
126 # See the perf-script-python Documentation for the list of available functions.
128 import os
129 import sys
131 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
132         '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
134 from perf_trace_context import *
135 from Core import *
137 def trace_begin():
138         print "in trace_begin"
140 def trace_end():
141         print "in trace_end"
143 def 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)
149                 print "id=%d, args=%s\n" % \
150                 (id, args),
152 def 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())])
155 def 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 ----
160 At the top is a comment block followed by some import statements and a
161 path append which every perf script script should include.
163 Following that are a couple generated functions, trace_begin() and
164 trace_end(), which are called at the beginning and the end of the
165 script respectively (for more details, see the SCRIPT_LAYOUT section
166 below).
168 Following those are the 'event handler' functions generated one for
169 every event in the 'perf record' output.  The handler functions take
170 the form subsystem__event_name, and contain named parameters, one for
171 each field in the event; in this case, there's only one event,
172 raw_syscalls__sys_enter().  (see the EVENT HANDLERS section below for
173 more info on event handlers).
175 The final couple of functions are, like the begin and end functions,
176 generated for every script.  The first, trace_unhandled(), is called
177 every time the script finds an event in the perf.data file that
178 doesn't correspond to any event handler in the script.  This could
179 mean either that the record step recorded event types that it wasn't
180 really interested in, or the script was run against a trace file that
181 doesn't correspond to the script.
183 The script generated by -g option simply prints a line for each
184 event found in the trace stream i.e. it basically just dumps the event
185 and its parameter values to stdout.  The print_header() function is
186 simply a utility function used for that purpose.  Let's rename the
187 script and run it to see the default output:
189 ----
190 # mv perf-script.py syscall-counts.py
191 # perf script -s syscall-counts.py
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=
204 ----
206 Of course, for this script, we're not interested in printing every
207 trace event, but rather aggregating it in a useful way.  So we'll get
208 rid of everything to do with printing as well as the trace_begin() and
209 trace_unhandled() functions, which we won't be using.  That leaves us
210 with this minimalistic skeleton:
212 ----
213 import os
214 import sys
216 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
217         '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
219 from perf_trace_context import *
220 from Core import *
222 def trace_end():
223         print "in trace_end"
225 def raw_syscalls__sys_enter(event_name, context, common_cpu,
226         common_secs, common_nsecs, common_pid, common_comm,
227         id, args):
228 ----
230 In trace_end(), we'll simply print the results, but first we need to
231 generate some results to print.  To do that we need to have our
232 sys_enter() handler do the necessary tallying until all events have
233 been counted.  A hash table indexed by syscall id is a good way to
234 store that information; every time the sys_enter() handler is called,
235 we simply increment a count associated with that hash entry indexed by
236 that syscall id:
238 ----
239   syscalls = autodict()
241   try:
242     syscalls[id] += 1
243   except TypeError:
244     syscalls[id] = 1
245 ----
247 The syscalls 'autodict' object is a special kind of Python dictionary
248 (implemented in Core.py) that implements Perl's 'autovivifying' hashes
249 in Python i.e. with autovivifying hashes, you can assign nested hash
250 values without having to go to the trouble of creating intermediate
251 levels if they don't exist e.g syscalls[comm][pid][id] = 1 will create
252 the intermediate hash levels and finally assign the value 1 to the
253 hash entry for 'id' (because the value being assigned isn't a hash
254 object itself, the initial value is assigned in the TypeError
255 exception.  Well, there may be a better way to do this in Python but
256 that's what works for now).
258 Putting that code into the raw_syscalls__sys_enter() handler, we
259 effectively end up with a single-level dictionary keyed on syscall id
260 and having the counts we've tallied as values.
262 The print_syscall_totals() function iterates over the entries in the
263 dictionary and displays a line for each entry containing the syscall
264 name (the dictionary keys contain the syscall ids, which are passed to
265 the Util function syscall_name(), which translates the raw syscall
266 numbers to the corresponding syscall name strings).  The output is
267 displayed after all the events in the trace have been processed, by
268 calling the print_syscall_totals() function from the trace_end()
269 handler called at the end of script processing.
271 The final script producing the output shown above is shown in its
272 entirety below (syscall_name() helper is not yet available, you can
273 only deal with id's for now):
275 ----
276 import os
277 import sys
279 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
280         '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
282 from perf_trace_context import *
283 from Core import *
284 from Util import *
286 syscalls = autodict()
288 def trace_end():
289         print_syscall_totals()
291 def 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] += 1
296         except TypeError:
297                 syscalls[id] = 1
299 def 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",
305     print "%-40s  %10s\n" % ("event", "count"),
306     print "%-40s  %10s\n" % ("----------------------------------------", \
307                                  "-----------"),
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 ----
314 The script can be run just as before:
316   # perf script -s syscall-counts.py
318 So those are the essential steps in writing and running a script.  The
319 process can be generalized to any tracepoint or set of tracepoints
320 you're interested in - basically find the tracepoint(s) you're
321 interested in by looking at the list of available events shown by
322 'perf list' and/or look in /sys/kernel/debug/tracing/events/ for
323 detailed event and field info, record the corresponding trace data
324 using 'perf record', passing it the list of interesting events,
325 generate a skeleton script using 'perf script -g python' and modify the
326 code to aggregate and display it for your particular needs.
328 After you've done that you may end up with a general-purpose script
329 that you want to keep around and have available for future use.  By
330 writing a couple of very simple shell scripts and putting them in the
331 right place, you can have your script listed alongside the other
332 scripts listed by the 'perf script -l' command e.g.:
334 ----
335 # perf script -l
336 List of available trace scripts:
337   wakeup-latency                       system-wide min/max/avg wakeup latency
338   rw-by-file <comm>                    r/w activity for a program, by file
339   rw-by-pid                            system-wide r/w activity
340 ----
342 A nice side effect of doing this is that you also then capture the
343 probably lengthy 'perf record' command needed to record the events for
344 the script.
346 To have the script appear as a 'built-in' script, you write two simple
347 scripts, one for recording and one for 'reporting'.
349 The 'record' script is a shell script with the same base name as your
350 script, but with -record appended.  The shell script should be put
351 into the perf/scripts/python/bin directory in the kernel source tree.
352 In that script, you write the 'perf record' command-line needed for
353 your script:
355 ----
356 # cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-record
358 #!/bin/bash
359 perf record -a -e raw_syscalls:sys_enter
360 ----
362 The 'report' script is also a shell script with the same base name as
363 your script, but with -report appended.  It should also be located in
364 the perf/scripts/python/bin directory.  In that script, you write the
365 'perf script -s' command-line needed for running your script:
367 ----
368 # cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-report
370 #!/bin/bash
371 # description: system-wide syscall counts
372 perf script -s ~/libexec/perf-core/scripts/python/syscall-counts.py
373 ----
375 Note that the location of the Python script given in the shell script
376 is in the libexec/perf-core/scripts/python directory - this is where
377 the script will be copied by 'make install' when you install perf.
378 For the installation to install your script there, your script needs
379 to be located in the perf/scripts/python directory in the kernel
380 source tree:
382 ----
383 # ls -al kernel-source/tools/perf/scripts/python
384 total 32
385 drwxr-xr-x 4 trz trz 4096 2010-01-26 22:30 .
386 drwxr-xr-x 4 trz trz 4096 2010-01-26 22:29 ..
387 drwxr-xr-x 2 trz trz 4096 2010-01-26 22:29 bin
388 -rw-r--r-- 1 trz trz 2548 2010-01-26 22:29 check-perf-script.py
389 drwxr-xr-x 3 trz trz 4096 2010-01-26 22:49 Perf-Trace-Util
390 -rw-r--r-- 1 trz trz 1462 2010-01-26 22:30 syscall-counts.py
391 ----
393 Once you've done that (don't forget to do a new 'make install',
394 otherwise your script won't show up at run-time), 'perf script -l'
395 should show a new entry for your script:
397 ----
398 # perf script -l
399 List of available trace scripts:
400   wakeup-latency                       system-wide min/max/avg wakeup latency
401   rw-by-file <comm>                    r/w activity for a program, by file
402   rw-by-pid                            system-wide r/w activity
403   syscall-counts                       system-wide syscall counts
404 ----
406 You can now perform the record step via 'perf script record':
408   # perf script record syscall-counts
410 and display the output using 'perf script report':
412   # perf script report syscall-counts
414 STARTER SCRIPTS
415 ---------------
417 You can quickly get started writing a script for a particular set of
418 trace data by generating a skeleton script using 'perf script -g
419 python' in the same directory as an existing perf.data trace file.
420 That will generate a starter script containing a handler for each of
421 the event types in the trace file; it simply prints every available
422 field for each event in the trace file.
424 You can also look at the existing scripts in
425 ~/libexec/perf-core/scripts/python for typical examples showing how to
426 do basic things like aggregate event data, print results, etc.  Also,
427 the check-perf-script.py script, while not interesting for its results,
428 attempts to exercise all of the main scripting features.
430 EVENT HANDLERS
431 --------------
433 When perf script is invoked using a trace script, a user-defined
434 'handler function' is called for each event in the trace.  If there's
435 no handler function defined for a given event type, the event is
436 ignored (or passed to a 'trace_unhandled' function, see below) and the
437 next event is processed.
439 Most of the event's field values are passed as arguments to the
440 handler function; some of the less common ones aren't - those are
441 available as calls back into the perf executable (see below).
443 As an example, the following perf record command can be used to record
444 all sched_wakeup events in the system:
446  # perf record -a -e sched:sched_wakeup
448 Traces meant to be processed using a script should be recorded with
449 the above option: -a to enable system-wide collection.
451 The format file for the sched_wakep event defines the following fields
452 (see /sys/kernel/debug/tracing/events/sched/sched_wakeup/format):
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;
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 ----
468 The handler function for this event would be defined as:
470 ----
471 def 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        pass
475 ----
477 The handler function takes the form subsystem__event_name.
479 The common_* arguments in the handler's argument list are the set of
480 arguments passed to all event handlers; some of the fields correspond
481 to the common_* fields in the format file, but some are synthesized,
482 and some of the common_* fields aren't common enough to to be passed
483 to every event as arguments but are available as library functions.
485 Here's a brief description of each of the invariant event args:
487  event_name                 the name of the event as text
488  context                    an opaque 'cookie' used in calls back into perf
489  common_cpu                 the cpu the event occurred on
490  common_secs                the secs portion of the event timestamp
491  common_nsecs               the nsecs portion of the event timestamp
492  common_pid                 the pid of the current task
493  common_comm                the name of the current process
495 All of the remaining fields in the event's format file have
496 counterparts as handler function arguments of the same name, as can be
497 seen in the example above.
499 The above provides the basics needed to directly access every field of
500 every event in a trace, which covers 90% of what you need to know to
501 write a useful trace script.  The sections below cover the rest.
503 SCRIPT LAYOUT
504 -------------
506 Every perf script Python script should start by setting up a Python
507 module search path and 'import'ing a few support modules (see module
508 descriptions below):
510 ----
511  import os
512  import sys
514  sys.path.append(os.environ['PERF_EXEC_PATH'] + \
515               '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
517  from perf_trace_context import *
518  from Core import *
519 ----
521 The rest of the script can contain handler functions and support
522 functions in any order.
524 Aside from the event handler functions discussed above, every script
525 can implement a set of optional functions:
527 *trace_begin*, if defined, is called before any event is processed and
528 gives scripts a chance to do setup tasks:
530 ----
531 def trace_begin():
532     pass
533 ----
535 *trace_end*, if defined, is called after all events have been
536  processed and gives scripts a chance to do end-of-script tasks, such
537  as display results:
539 ----
540 def trace_end():
541     pass
542 ----
544 *trace_unhandled*, if defined, is called after for any event that
545  doesn't have a handler explicitly defined for it.  The standard set
546  of common arguments are passed into it:
548 ----
549 def trace_unhandled(event_name, context, event_fields_dict):
550     pass
551 ----
553 The remaining sections provide descriptions of each of the available
554 built-in perf script Python modules and their associated functions.
556 AVAILABLE MODULES AND FUNCTIONS
557 -------------------------------
559 The following sections describe the functions and variables available
560 via the various perf script Python modules.  To use the functions and
561 variables from the given module, add the corresponding 'from XXXX
562 import' line to your perf script script.
564 Core.py Module
565 ~~~~~~~~~~~~~~
567 These functions provide some essential functions to user scripts.
569 The *flag_str* and *symbol_str* functions provide human-readable
570 strings for flag and symbolic fields.  These correspond to the strings
571 and values parsed from the 'print fmt' fields of the event format
572 files:
574   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
575   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
577 The *autodict* function returns a special kind of Python
578 dictionary that implements Perl's 'autovivifying' hashes in Python
579 i.e. with autovivifying hashes, you can assign nested hash values
580 without having to go to the trouble of creating intermediate levels if
581 they don't exist.
583   autodict() - returns an autovivifying dictionary instance
586 perf_trace_context Module
587 ~~~~~~~~~~~~~~~~~~~~~~~~~
589 Some of the 'common' fields in the event format file aren't all that
590 common, but need to be made accessible to user scripts nonetheless.
592 perf_trace_context defines a set of functions that can be used to
593 access this data in the context of the current event.  Each of these
594 functions expects a context variable, which is the same as the
595 context variable passed into every event handler as the second
596 argument.
598  common_pc(context) - returns common_preempt count for the current event
599  common_flags(context) - returns common_flags for the current event
600  common_lock_depth(context) - returns common_lock_depth for the current event
602 Util.py Module
603 ~~~~~~~~~~~~~~
605 Various utility functions for use with perf script:
607   nsecs(secs, nsecs) - returns total nsecs given secs/nsecs pair
608   nsecs_secs(nsecs) - returns whole secs portion given nsecs
609   nsecs_nsecs(nsecs) - returns nsecs remainder given nsecs
610   nsecs_str(nsecs) - returns printable string in the form secs.nsecs
611   avg(total, n) - returns average given a sum and a total number of values
613 SUPPORTED FIELDS
614 ----------------
616 Currently supported fields:
618 ev_name, comm, pid, tid, cpu, ip, time, period, phys_addr, addr,
619 symbol, dso, time_enabled, time_running, values, callchain,
620 brstack, brstacksym, datasrc, datasrc_decode, iregs, uregs,
621 weight, transaction, raw_buf, attr.
623 Some fields have sub items:
625 brstack:
626     from, to, from_dsoname, to_dsoname, mispred,
627     predicted, in_tx, abort, cycles.
629 brstacksym:
630     items: from, to, pred, in_tx, abort (converted string)
632 For example,
633 We can use this code to print brstack "from", "to", "cycles".
635 if 'brstack' in dict:
636         for entry in dict['brstack']:
637                 print "from %s, to %s, cycles %s" % (entry["from"], entry["to"], entry["cycles"])
639 SEE ALSO
640 --------
641 linkperf:perf-script[1]