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