perf/scripts: Add perf-trace-python Documentation
[linux-2.6.git] / tools / perf / Documentation / perf-trace-python.txt
1 perf-trace-python(1)
2 ==================
3
4 NAME
5 ----
6 perf-trace-python - Process trace data with a Python script
7
8 SYNOPSIS
9 --------
10 [verse]
11 'perf trace' [-s [Python]:script[.py] ]
12
13 DESCRIPTION
14 -----------
15
16 This perf trace option is used to process perf trace 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.
20
21 A QUICK EXAMPLE
22 ---------------
23
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 trace 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.
30
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 trace
33 scripts via 'perf trace -l'.  As such, this script also shows how to
34 integrate your script into the list of general-purpose 'perf trace'
35 scripts listed by that command.
36
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:
40
41 ----
42 syscall events:
43
44 event                                          count
45 ----------------------------------------  -----------
46 sys_write                                     455067
47 sys_getdents                                    4072
48 sys_close                                       3037
49 sys_swapoff                                     1769
50 sys_read                                         923
51 sys_sched_setparam                               826
52 sys_open                                         331
53 sys_newfstat                                     326
54 sys_mmap                                         217
55 sys_munmap                                       216
56 sys_futex                                        141
57 sys_select                                       102
58 sys_poll                                          84
59 sys_setitimer                                     12
60 sys_writev                                         8
61 15                                                 8
62 sys_lseek                                          7
63 sys_rt_sigprocmask                                 6
64 sys_wait4                                          3
65 sys_ioctl                                          3
66 sys_set_robust_list                                1
67 sys_exit                                           1
68 56                                                 1
69 sys_access                                         1
70 ----
71
72 Basically our task is to keep a per-syscall tally that gets updated
73 every time a system call occurs in the system.  Our script will do
74 that, but first we need to record the data that will be processed by
75 that script.  Theoretically, there are a couple of ways we could do
76 that:
77
78 - we could enable every event under the tracing/events/syscalls
79   directory, but this is over 600 syscalls, well beyond the number
80   allowable by perf.  These individual syscall events will however be
81   useful if we want to later use the guidance we get from the
82   general-purpose scripts to drill down and get more detail about
83   individual syscalls of interest.
84
85 - we can enable the sys_enter and/or sys_exit syscalls found under
86   tracing/events/raw_syscalls.  These are called for all syscalls; the
87   'id' field can be used to distinguish between individual syscall
88   numbers.
89
90 For this script, we only need to know that a syscall was entered; we
91 don't care how it exited, so we'll use 'perf record' to record only
92 the sys_enter events:
93
94 ----
95 # perf record -c 1 -f -a -M -R -e raw_syscalls:sys_enter
96
97 ^C[ perf record: Woken up 1 times to write data ]
98 [ perf record: Captured and wrote 56.545 MB perf.data (~2470503 samples) ]
99 ----
100
101 The options basically say to collect data for every syscall event
102 system-wide and multiplex the per-cpu output into a single stream.
103 That single stream will be recorded in a file in the current directory
104 called perf.data.
105
106 Once we have a perf.data file containing our data, we can use the -g
107 'perf trace' option to generate a Python script that will contain a
108 callback handler for each event type found in the perf.data trace
109 stream (for more details, see the STARTER SCRIPTS section).
110
111 ----
112 # perf trace -g python
113 generated Python script: perf-trace.py
114
115 The output file created also in the current directory is named
116 perf-trace.py.  Here's the file in its entirety:
117
118 # perf trace event handlers, generated by perf trace -g python
119 # Licensed under the terms of the GNU GPL License version 2
120
121 # The common_* event handler fields are the most useful fields common to
122 # all events.  They don't necessarily correspond to the 'common_*' fields
123 # in the format files.  Those fields not available as handler params can
124 # be retrieved using Python functions of the form common_*(context).
125 # See the perf-trace-python Documentation for the list of available functions.
126
127 import os
128 import sys
129
130 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
131         '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
132
133 from perf_trace_context import *
134 from Core import *
135
136 def trace_begin():
137         print "in trace_begin"
138
139 def trace_end():
140         print "in trace_end"
141
142 def raw_syscalls__sys_enter(event_name, context, common_cpu,
143         common_secs, common_nsecs, common_pid, common_comm,
144         id, args):
145                 print_header(event_name, common_cpu, common_secs, common_nsecs,
146                         common_pid, common_comm)
147
148                 print "id=%d, args=%s\n" % \
149                 (id, args),
150
151 def trace_unhandled(event_name, context, common_cpu, common_secs, common_nsecs,
152                 common_pid, common_comm):
153                 print_header(event_name, common_cpu, common_secs, common_nsecs,
154                 common_pid, common_comm)
155
156 def print_header(event_name, cpu, secs, nsecs, pid, comm):
157         print "%-20s %5u %05u.%09u %8u %-20s " % \
158         (event_name, cpu, secs, nsecs, pid, comm),
159 ----
160
161 At the top is a comment block followed by some import statements and a
162 path append which every perf trace script should include.
163
164 Following that are a couple generated functions, trace_begin() and
165 trace_end(), which are called at the beginning and the end of the
166 script respectively (for more details, see the SCRIPT_LAYOUT section
167 below).
168
169 Following those are the 'event handler' functions generated one for
170 every event in the 'perf record' output.  The handler functions take
171 the form subsystem__event_name, and contain named parameters, one for
172 each field in the event; in this case, there's only one event,
173 raw_syscalls__sys_enter().  (see the EVENT HANDLERS section below for
174 more info on event handlers).
175
176 The final couple of functions are, like the begin and end functions,
177 generated for every script.  The first, trace_unhandled(), is called
178 every time the script finds an event in the perf.data file that
179 doesn't correspond to any event handler in the script.  This could
180 mean either that the record step recorded event types that it wasn't
181 really interested in, or the script was run against a trace file that
182 doesn't correspond to the script.
183
184 The script generated by -g option option simply prints a line for each
185 event found in the trace stream i.e. it basically just dumps the event
186 and its parameter values to stdout.  The print_header() function is
187 simply a utility function used for that purpose.  Let's rename the
188 script and run it to see the default output:
189
190 ----
191 # mv perf-trace.py syscall-counts.py
192 # perf trace -s syscall-counts.py
193
194 raw_syscalls__sys_enter     1 00840.847582083     7506 perf                  id=1, args=
195 raw_syscalls__sys_enter     1 00840.847595764     7506 perf                  id=1, args=
196 raw_syscalls__sys_enter     1 00840.847620860     7506 perf                  id=1, args=
197 raw_syscalls__sys_enter     1 00840.847710478     6533 npviewer.bin          id=78, args=
198 raw_syscalls__sys_enter     1 00840.847719204     6533 npviewer.bin          id=142, args=
199 raw_syscalls__sys_enter     1 00840.847755445     6533 npviewer.bin          id=3, args=
200 raw_syscalls__sys_enter     1 00840.847775601     6533 npviewer.bin          id=3, args=
201 raw_syscalls__sys_enter     1 00840.847781820     6533 npviewer.bin          id=3, args=
202 .
203 .
204 .
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 import os
215 import sys
216
217 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
218         '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
219
220 from perf_trace_context import *
221 from Core import *
222
223 def trace_end():
224         print "in trace_end"
225
226 def raw_syscalls__sys_enter(event_name, context, common_cpu,
227         common_secs, common_nsecs, common_pid, common_comm,
228         id, args):
229 ----
230
231 In trace_end(), we'll simply print the results, but first we need to
232 generate some results to print.  To do that we need to have our
233 sys_enter() handler do the necessary tallying until all events have
234 been counted.  A hash table indexed by syscall id is a good way to
235 store that information; every time the sys_enter() handler is called,
236 we simply increment a count associated with that hash entry indexed by
237 that syscall id:
238
239 ----
240   syscalls = autodict()
241
242   try:
243     syscalls[id] += 1
244   except TypeError:
245     syscalls[id] = 1
246 ----
247
248 The syscalls 'autodict' object is a special kind of Python dictionary
249 (implemented in Core.py) that implements Perl's 'autovivifying' hashes
250 in Python i.e. with autovivifying hashes, you can assign nested hash
251 values without having to go to the trouble of creating intermediate
252 levels if they don't exist e.g syscalls[comm][pid][id] = 1 will create
253 the intermediate hash levels and finally assign the value 1 to the
254 hash entry for 'id' (because the value being assigned isn't a hash
255 object itself, the initial value is assigned in the TypeError
256 exception.  Well, there may be a better way to do this in Python but
257 that's what works for now).
258
259 Putting that code into the raw_syscalls__sys_enter() handler, we
260 effectively end up with a single-level dictionary keyed on syscall id
261 and having the counts we've tallied as values.
262
263 The print_syscall_totals() function iterates over the entries in the
264 dictionary and displays a line for each entry containing the syscall
265 name (the dictonary keys contain the syscall ids, which are passed to
266 the Util function syscall_name(), which translates the raw syscall
267 numbers to the corresponding syscall name strings).  The output is
268 displayed after all the events in the trace have been processed, by
269 calling the print_syscall_totals() function from the trace_end()
270 handler called at the end of script processing.
271
272 The final script producing the output shown above is shown in its
273 entirety below:
274
275 ----
276 import os
277 import sys
278
279 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
280         '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
281
282 from perf_trace_context import *
283 from Core import *
284 from Util import *
285
286 syscalls = autodict()
287
288 def trace_end():
289         print_syscall_totals()
290
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
298
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",
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
314 The script can be run just as before:
315
316   # perf trace -s syscall-counts.py
317
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 trace -g python' and modify the
326 code to aggregate and display it for your particular needs.
327
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 trace -l' command e.g.:
333
334 ----
335 root@tropicana:~# perf trace -l
336 List of available trace scripts:
337   workqueue-stats                      workqueue stats (ins/exe/create/destroy)
338   wakeup-latency                       system-wide min/max/avg wakeup latency
339   rw-by-file <comm>                    r/w activity for a program, by file
340   rw-by-pid                            system-wide r/w activity
341 ----
342
343 A nice side effect of doing this is that you also then capture the
344 probably lengthy 'perf record' command needed to record the events for
345 the script.
346
347 To have the script appear as a 'built-in' script, you write two simple
348 scripts, one for recording and one for 'reporting'.
349
350 The 'record' script is a shell script with the same base name as your
351 script, but with -record appended.  The shell script should be put
352 into the perf/scripts/python/bin directory in the kernel source tree.
353 In that script, you write the 'perf record' command-line needed for
354 your script:
355
356 ----
357 # cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-record
358
359 #!/bin/bash
360 perf record -c 1 -f -a -M -R -e raw_syscalls:sys_enter
361 ----
362
363 The 'report' script is also a shell script with the same base name as
364 your script, but with -report appended.  It should also be located in
365 the perf/scripts/python/bin directory.  In that script, you write the
366 'perf trace -s' command-line needed for running your script:
367
368 ----
369 # cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-report
370
371 #!/bin/bash
372 # description: system-wide syscall counts
373 perf trace -s ~/libexec/perf-core/scripts/python/syscall-counts.py
374 ----
375
376 Note that the location of the Python script given in the shell script
377 is in the libexec/perf-core/scripts/python directory - this is where
378 the script will be copied by 'make install' when you install perf.
379 For the installation to install your script there, your script needs
380 to be located in the perf/scripts/python directory in the kernel
381 source tree:
382
383 ----
384 # ls -al kernel-source/tools/perf/scripts/python
385
386 root@tropicana:/home/trz/src/tip# ls -al tools/perf/scripts/python
387 total 32
388 drwxr-xr-x 4 trz trz 4096 2010-01-26 22:30 .
389 drwxr-xr-x 4 trz trz 4096 2010-01-26 22:29 ..
390 drwxr-xr-x 2 trz trz 4096 2010-01-26 22:29 bin
391 -rw-r--r-- 1 trz trz 2548 2010-01-26 22:29 check-perf-trace.py
392 drwxr-xr-x 3 trz trz 4096 2010-01-26 22:49 Perf-Trace-Util
393 -rw-r--r-- 1 trz trz 1462 2010-01-26 22:30 syscall-counts.py
394 ----
395
396 Once you've done that (don't forget to do a new 'make install',
397 otherwise your script won't show up at run-time), 'perf trace -l'
398 should show a new entry for your script:
399
400 ----
401 root@tropicana:~# perf trace -l
402 List of available trace scripts:
403   workqueue-stats                      workqueue stats (ins/exe/create/destroy)
404   wakeup-latency                       system-wide min/max/avg wakeup latency
405   rw-by-file <comm>                    r/w activity for a program, by file
406   rw-by-pid                            system-wide r/w activity
407   syscall-counts                       system-wide syscall counts
408 ----
409
410 You can now perform the record step via 'perf trace record':
411
412   # perf trace record syscall-counts
413
414 and display the output using 'perf trace report':
415
416   # perf trace report syscall-counts
417
418 STARTER SCRIPTS
419 ---------------
420
421 You can quickly get started writing a script for a particular set of
422 trace data by generating a skeleton script using 'perf trace -g
423 python' in the same directory as an existing perf.data trace file.
424 That will generate a starter script containing a handler for each of
425 the event types in the trace file; it simply prints every available
426 field for each event in the trace file.
427
428 You can also look at the existing scripts in
429 ~/libexec/perf-core/scripts/python for typical examples showing how to
430 do basic things like aggregate event data, print results, etc.  Also,
431 the check-perf-trace.py script, while not interesting for its results,
432 attempts to exercise all of the main scripting features.
433
434 EVENT HANDLERS
435 --------------
436
437 When perf trace is invoked using a trace script, a user-defined
438 'handler function' is called for each event in the trace.  If there's
439 no handler function defined for a given event type, the event is
440 ignored (or passed to a 'trace_handled' function, see below) and the
441 next event is processed.
442
443 Most of the event's field values are passed as arguments to the
444 handler function; some of the less common ones aren't - those are
445 available as calls back into the perf executable (see below).
446
447 As an example, the following perf record command can be used to record
448 all sched_wakeup events in the system:
449
450  # perf record -c 1 -f -a -M -R -e sched:sched_wakeup
451
452 Traces meant to be processed using a script should be recorded with
453 the above options: -c 1 says to sample every event, -a to enable
454 system-wide collection, -M to multiplex the output, and -R to collect
455 raw samples.
456
457 The format file for the sched_wakep event defines the following fields
458 (see /sys/kernel/debug/tracing/events/sched/sched_wakeup/format):
459
460 ----
461  format:
462         field:unsigned short common_type;
463         field:unsigned char common_flags;
464         field:unsigned char common_preempt_count;
465         field:int common_pid;
466         field:int common_lock_depth;
467
468         field:char comm[TASK_COMM_LEN];
469         field:pid_t pid;
470         field:int prio;
471         field:int success;
472         field:int target_cpu;
473 ----
474
475 The handler function for this event would be defined as:
476
477 ----
478 def sched__sched_wakeup(event_name, context, common_cpu, common_secs,
479        common_nsecs, common_pid, common_comm,
480        comm, pid, prio, success, target_cpu):
481        pass
482 ----
483
484 The handler function takes the form subsystem__event_name.
485
486 The common_* arguments in the handler's argument list are the set of
487 arguments passed to all event handlers; some of the fields correspond
488 to the common_* fields in the format file, but some are synthesized,
489 and some of the common_* fields aren't common enough to to be passed
490 to every event as arguments but are available as library functions.
491
492 Here's a brief description of each of the invariant event args:
493
494  event_name                 the name of the event as text
495  context                    an opaque 'cookie' used in calls back into perf
496  common_cpu                 the cpu the event occurred on
497  common_secs                the secs portion of the event timestamp
498  common_nsecs               the nsecs portion of the event timestamp
499  common_pid                 the pid of the current task
500  common_comm                the name of the current process
501
502 All of the remaining fields in the event's format file have
503 counterparts as handler function arguments of the same name, as can be
504 seen in the example above.
505
506 The above provides the basics needed to directly access every field of
507 every event in a trace, which covers 90% of what you need to know to
508 write a useful trace script.  The sections below cover the rest.
509
510 SCRIPT LAYOUT
511 -------------
512
513 Every perf trace Python script should start by setting up a Python
514 module search path and 'import'ing a few support modules (see module
515 descriptions below):
516
517 ----
518  import os
519  import sys
520
521  sys.path.append(os.environ['PERF_EXEC_PATH'] + \
522               '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
523
524  from perf_trace_context import *
525  from Core import *
526 ----
527
528 The rest of the script can contain handler functions and support
529 functions in any order.
530
531 Aside from the event handler functions discussed above, every script
532 can implement a set of optional functions:
533
534 *trace_begin*, if defined, is called before any event is processed and
535 gives scripts a chance to do setup tasks:
536
537 ----
538 def trace_begin:
539     pass
540 ----
541
542 *trace_end*, if defined, is called after all events have been
543  processed and gives scripts a chance to do end-of-script tasks, such
544  as display results:
545
546 ----
547 def trace_end:
548     pass
549 ----
550
551 *trace_unhandled*, if defined, is called after for any event that
552  doesn't have a handler explicitly defined for it.  The standard set
553  of common arguments are passed into it:
554
555 ----
556 def trace_unhandled(event_name, context, common_cpu, common_secs,
557         common_nsecs, common_pid, common_comm):
558     pass
559 ----
560
561 The remaining sections provide descriptions of each of the available
562 built-in perf trace Python modules and their associated functions.
563
564 AVAILABLE MODULES AND FUNCTIONS
565 -------------------------------
566
567 The following sections describe the functions and variables available
568 via the various perf trace Python modules.  To use the functions and
569 variables from the given module, add the corresponding 'from XXXX
570 import' line to your perf trace script.
571
572 Core.py Module
573 ~~~~~~~~~~~~~~
574
575 These functions provide some essential functions to user scripts.
576
577 The *flag_str* and *symbol_str* functions provide human-readable
578 strings for flag and symbolic fields.  These correspond to the strings
579 and values parsed from the 'print fmt' fields of the event format
580 files:
581
582   flag_str(event_name, field_name, field_value) - returns the string represention corresponding to field_value for the flag field field_name of event event_name
583   symbol_str(event_name, field_name, field_value) - returns the string represention corresponding to field_value for the symbolic field field_name of event event_name
584
585 The *autodict* function returns a special special kind of Python
586 dictionary that implements Perl's 'autovivifying' hashes in Python
587 i.e. with autovivifying hashes, you can assign nested hash values
588 without having to go to the trouble of creating intermediate levels if
589 they don't exist.
590
591   autodict() - returns an autovivifying dictionary instance
592
593
594 perf_trace_context Module
595 ~~~~~~~~~~~~~~~~~~~~~~~~~
596
597 Some of the 'common' fields in the event format file aren't all that
598 common, but need to be made accessible to user scripts nonetheless.
599
600 perf_trace_context defines a set of functions that can be used to
601 access this data in the context of the current event.  Each of these
602 functions expects a context variable, which is the same as the
603 context variable passed into every event handler as the second
604 argument.
605
606  common_pc(context) - returns common_preempt count for the current event
607  common_flags(context) - returns common_flags for the current event
608  common_lock_depth(context) - returns common_lock_depth for the current event
609
610 Util.py Module
611 ~~~~~~~~~~~~~~
612
613 Various utility functions for use with perf trace:
614
615   nsecs(secs, nsecs) - returns total nsecs given secs/nsecs pair
616   nsecs_secs(nsecs) - returns whole secs portion given nsecs
617   nsecs_nsecs(nsecs) - returns nsecs remainder given nsecs
618   nsecs_str(nsecs) - returns printable string in the form secs.nsecs
619   avg(total, n) - returns average given a sum and a total number of values
620   syscall_name(id) - returns the syscall name for the specified syscall_nr
621
622 SEE ALSO
623 --------
624 linkperf:perf-trace[1]