Loading...
1perf-script-python(1)
2====================
3
4NAME
5----
6perf-script-python - Process trace data with a Python script
7
8SYNOPSIS
9--------
10[verse]
11'perf script' [-s [Python]:script[.py] ]
12
13DESCRIPTION
14-----------
15
16This perf script option is used to process perf script 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 script 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 script
33scripts via 'perf script -l'. As such, this script also shows how to
34integrate your script into the list of general-purpose 'perf script'
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
39of its output (syscall names are not yet supported, they will appear
40as numbers):
41
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 -a -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 script' 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 script -g python
114generated Python script: perf-script.py
115
116The output file created also in the current directory is named
117perf-script.py. Here's the file in its entirety:
118
119# perf script event handlers, generated by perf script -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-script-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 script 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 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-script.py syscall-counts.py
193# perf script -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 dictionary 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
274entirety below (syscall_name() helper is not yet available, you can
275only deal with id's for now):
276
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 script -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 script -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 script -l' command e.g.:
335
336----
337root@tropicana:~# perf script -l
338List of available trace scripts:
339 wakeup-latency system-wide min/max/avg wakeup latency
340 rw-by-file <comm> r/w activity for a program, by file
341 rw-by-pid system-wide r/w activity
342----
343
344A nice side effect of doing this is that you also then capture the
345probably lengthy 'perf record' command needed to record the events for
346the script.
347
348To have the script appear as a 'built-in' script, you write two simple
349scripts, one for recording and one for 'reporting'.
350
351The 'record' script is a shell script with the same base name as your
352script, but with -record appended. The shell script should be put
353into the perf/scripts/python/bin directory in the kernel source tree.
354In that script, you write the 'perf record' command-line needed for
355your script:
356
357----
358# cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-record
359
360#!/bin/bash
361perf record -a -e raw_syscalls:sys_enter
362----
363
364The 'report' script is also a shell script with the same base name as
365your script, but with -report appended. It should also be located in
366the perf/scripts/python/bin directory. In that script, you write the
367'perf script -s' command-line needed for running your script:
368
369----
370# cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-report
371
372#!/bin/bash
373# description: system-wide syscall counts
374perf script -s ~/libexec/perf-core/scripts/python/syscall-counts.py
375----
376
377Note that the location of the Python script given in the shell script
378is in the libexec/perf-core/scripts/python directory - this is where
379the script will be copied by 'make install' when you install perf.
380For the installation to install your script there, your script needs
381to be located in the perf/scripts/python directory in the kernel
382source tree:
383
384----
385# ls -al kernel-source/tools/perf/scripts/python
386
387root@tropicana:/home/trz/src/tip# ls -al tools/perf/scripts/python
388total 32
389drwxr-xr-x 4 trz trz 4096 2010-01-26 22:30 .
390drwxr-xr-x 4 trz trz 4096 2010-01-26 22:29 ..
391drwxr-xr-x 2 trz trz 4096 2010-01-26 22:29 bin
392-rw-r--r-- 1 trz trz 2548 2010-01-26 22:29 check-perf-script.py
393drwxr-xr-x 3 trz trz 4096 2010-01-26 22:49 Perf-Trace-Util
394-rw-r--r-- 1 trz trz 1462 2010-01-26 22:30 syscall-counts.py
395----
396
397Once you've done that (don't forget to do a new 'make install',
398otherwise your script won't show up at run-time), 'perf script -l'
399should show a new entry for your script:
400
401----
402root@tropicana:~# perf script -l
403List of available trace scripts:
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
410You can now perform the record step via 'perf script record':
411
412 # perf script record syscall-counts
413
414and display the output using 'perf script report':
415
416 # perf script report syscall-counts
417
418STARTER SCRIPTS
419---------------
420
421You can quickly get started writing a script for a particular set of
422trace data by generating a skeleton script using 'perf script -g
423python' in the same directory as an existing perf.data trace file.
424That will generate a starter script containing a handler for each of
425the event types in the trace file; it simply prints every available
426field for each event in the trace file.
427
428You can also look at the existing scripts in
429~/libexec/perf-core/scripts/python for typical examples showing how to
430do basic things like aggregate event data, print results, etc. Also,
431the check-perf-script.py script, while not interesting for its results,
432attempts to exercise all of the main scripting features.
433
434EVENT HANDLERS
435--------------
436
437When perf script is invoked using a trace script, a user-defined
438'handler function' is called for each event in the trace. If there's
439no handler function defined for a given event type, the event is
440ignored (or passed to a 'trace_handled' function, see below) and the
441next event is processed.
442
443Most of the event's field values are passed as arguments to the
444handler function; some of the less common ones aren't - those are
445available as calls back into the perf executable (see below).
446
447As an example, the following perf record command can be used to record
448all sched_wakeup events in the system:
449
450 # perf record -a -e sched:sched_wakeup
451
452Traces meant to be processed using a script should be recorded with
453the above option: -a to enable system-wide collection.
454
455The format file for the sched_wakep event defines the following fields
456(see /sys/kernel/debug/tracing/events/sched/sched_wakeup/format):
457
458----
459 format:
460 field:unsigned short common_type;
461 field:unsigned char common_flags;
462 field:unsigned char common_preempt_count;
463 field:int common_pid;
464
465 field:char comm[TASK_COMM_LEN];
466 field:pid_t pid;
467 field:int prio;
468 field:int success;
469 field:int target_cpu;
470----
471
472The handler function for this event would be defined as:
473
474----
475def sched__sched_wakeup(event_name, context, common_cpu, common_secs,
476 common_nsecs, common_pid, common_comm,
477 comm, pid, prio, success, target_cpu):
478 pass
479----
480
481The handler function takes the form subsystem__event_name.
482
483The common_* arguments in the handler's argument list are the set of
484arguments passed to all event handlers; some of the fields correspond
485to the common_* fields in the format file, but some are synthesized,
486and some of the common_* fields aren't common enough to to be passed
487to every event as arguments but are available as library functions.
488
489Here's a brief description of each of the invariant event args:
490
491 event_name the name of the event as text
492 context an opaque 'cookie' used in calls back into perf
493 common_cpu the cpu the event occurred on
494 common_secs the secs portion of the event timestamp
495 common_nsecs the nsecs portion of the event timestamp
496 common_pid the pid of the current task
497 common_comm the name of the current process
498
499All of the remaining fields in the event's format file have
500counterparts as handler function arguments of the same name, as can be
501seen in the example above.
502
503The above provides the basics needed to directly access every field of
504every event in a trace, which covers 90% of what you need to know to
505write a useful trace script. The sections below cover the rest.
506
507SCRIPT LAYOUT
508-------------
509
510Every perf script Python script should start by setting up a Python
511module search path and 'import'ing a few support modules (see module
512descriptions below):
513
514----
515 import os
516 import sys
517
518 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
519 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
520
521 from perf_trace_context import *
522 from Core import *
523----
524
525The rest of the script can contain handler functions and support
526functions in any order.
527
528Aside from the event handler functions discussed above, every script
529can implement a set of optional functions:
530
531*trace_begin*, if defined, is called before any event is processed and
532gives scripts a chance to do setup tasks:
533
534----
535def trace_begin:
536 pass
537----
538
539*trace_end*, if defined, is called after all events have been
540 processed and gives scripts a chance to do end-of-script tasks, such
541 as display results:
542
543----
544def trace_end:
545 pass
546----
547
548*trace_unhandled*, if defined, is called after for any event that
549 doesn't have a handler explicitly defined for it. The standard set
550 of common arguments are passed into it:
551
552----
553def trace_unhandled(event_name, context, common_cpu, common_secs,
554 common_nsecs, common_pid, common_comm):
555 pass
556----
557
558The remaining sections provide descriptions of each of the available
559built-in perf script Python modules and their associated functions.
560
561AVAILABLE MODULES AND FUNCTIONS
562-------------------------------
563
564The following sections describe the functions and variables available
565via the various perf script Python modules. To use the functions and
566variables from the given module, add the corresponding 'from XXXX
567import' line to your perf script script.
568
569Core.py Module
570~~~~~~~~~~~~~~
571
572These functions provide some essential functions to user scripts.
573
574The *flag_str* and *symbol_str* functions provide human-readable
575strings for flag and symbolic fields. These correspond to the strings
576and values parsed from the 'print fmt' fields of the event format
577files:
578
579 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
580 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
581
582The *autodict* function returns a special kind of Python
583dictionary that implements Perl's 'autovivifying' hashes in Python
584i.e. with autovivifying hashes, you can assign nested hash values
585without having to go to the trouble of creating intermediate levels if
586they don't exist.
587
588 autodict() - returns an autovivifying dictionary instance
589
590
591perf_trace_context Module
592~~~~~~~~~~~~~~~~~~~~~~~~~
593
594Some of the 'common' fields in the event format file aren't all that
595common, but need to be made accessible to user scripts nonetheless.
596
597perf_trace_context defines a set of functions that can be used to
598access this data in the context of the current event. Each of these
599functions expects a context variable, which is the same as the
600context variable passed into every event handler as the second
601argument.
602
603 common_pc(context) - returns common_preempt count for the current event
604 common_flags(context) - returns common_flags for the current event
605 common_lock_depth(context) - returns common_lock_depth for the current event
606
607Util.py Module
608~~~~~~~~~~~~~~
609
610Various utility functions for use with perf script:
611
612 nsecs(secs, nsecs) - returns total nsecs given secs/nsecs pair
613 nsecs_secs(nsecs) - returns whole secs portion given nsecs
614 nsecs_nsecs(nsecs) - returns nsecs remainder given nsecs
615 nsecs_str(nsecs) - returns printable string in the form secs.nsecs
616 avg(total, n) - returns average given a sum and a total number of values
617
618SEE ALSO
619--------
620linkperf:perf-script[1]
1perf-script-python(1)
2====================
3
4NAME
5----
6perf-script-python - Process trace data with a Python script
7
8SYNOPSIS
9--------
10[verse]
11'perf script' [-s [Python]:script[.py] ]
12
13DESCRIPTION
14-----------
15
16This perf script option is used to process perf script 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 script 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 script
33scripts via 'perf script -l'. As such, this script also shows how to
34integrate your script into the list of general-purpose 'perf script'
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
39of its output (syscall names are not yet supported, they will appear
40as numbers):
41
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 -a -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 script' 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 script -g python
114generated Python script: perf-script.py
115
116The output file created also in the current directory is named
117perf-script.py. Here's the file in its entirety:
118
119# perf script event handlers, generated by perf script -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-script-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, event_fields_dict):
153 print ' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())])
154
155def 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----
159
160At the top is a comment block followed by some import statements and a
161path append which every perf script script should include.
162
163Following that are a couple generated functions, trace_begin() and
164trace_end(), which are called at the beginning and the end of the
165script respectively (for more details, see the SCRIPT_LAYOUT section
166below).
167
168Following those are the 'event handler' functions generated one for
169every event in the 'perf record' output. The handler functions take
170the form subsystem\__event_name, and contain named parameters, one for
171each field in the event; in this case, there's only one event,
172raw_syscalls__sys_enter(). (see the EVENT HANDLERS section below for
173more info on event handlers).
174
175The final couple of functions are, like the begin and end functions,
176generated for every script. The first, trace_unhandled(), is called
177every time the script finds an event in the perf.data file that
178doesn't correspond to any event handler in the script. This could
179mean either that the record step recorded event types that it wasn't
180really interested in, or the script was run against a trace file that
181doesn't correspond to the script.
182
183The script generated by -g option simply prints a line for each
184event found in the trace stream i.e. it basically just dumps the event
185and its parameter values to stdout. The print_header() function is
186simply a utility function used for that purpose. Let's rename the
187script and run it to see the default output:
188
189----
190# mv perf-script.py syscall-counts.py
191# perf script -s syscall-counts.py
192
193raw_syscalls__sys_enter 1 00840.847582083 7506 perf id=1, args=
194raw_syscalls__sys_enter 1 00840.847595764 7506 perf id=1, args=
195raw_syscalls__sys_enter 1 00840.847620860 7506 perf id=1, args=
196raw_syscalls__sys_enter 1 00840.847710478 6533 npviewer.bin id=78, args=
197raw_syscalls__sys_enter 1 00840.847719204 6533 npviewer.bin id=142, args=
198raw_syscalls__sys_enter 1 00840.847755445 6533 npviewer.bin id=3, args=
199raw_syscalls__sys_enter 1 00840.847775601 6533 npviewer.bin id=3, args=
200raw_syscalls__sys_enter 1 00840.847781820 6533 npviewer.bin id=3, args=
201.
202.
203.
204----
205
206Of course, for this script, we're not interested in printing every
207trace event, but rather aggregating it in a useful way. So we'll get
208rid of everything to do with printing as well as the trace_begin() and
209trace_unhandled() functions, which we won't be using. That leaves us
210with this minimalistic skeleton:
211
212----
213import os
214import sys
215
216sys.path.append(os.environ['PERF_EXEC_PATH'] + \
217 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
218
219from perf_trace_context import *
220from Core import *
221
222def trace_end():
223 print "in trace_end"
224
225def raw_syscalls__sys_enter(event_name, context, common_cpu,
226 common_secs, common_nsecs, common_pid, common_comm,
227 id, args):
228----
229
230In trace_end(), we'll simply print the results, but first we need to
231generate some results to print. To do that we need to have our
232sys_enter() handler do the necessary tallying until all events have
233been counted. A hash table indexed by syscall id is a good way to
234store that information; every time the sys_enter() handler is called,
235we simply increment a count associated with that hash entry indexed by
236that syscall id:
237
238----
239 syscalls = autodict()
240
241 try:
242 syscalls[id] += 1
243 except TypeError:
244 syscalls[id] = 1
245----
246
247The syscalls 'autodict' object is a special kind of Python dictionary
248(implemented in Core.py) that implements Perl's 'autovivifying' hashes
249in Python i.e. with autovivifying hashes, you can assign nested hash
250values without having to go to the trouble of creating intermediate
251levels if they don't exist e.g syscalls[comm][pid][id] = 1 will create
252the intermediate hash levels and finally assign the value 1 to the
253hash entry for 'id' (because the value being assigned isn't a hash
254object itself, the initial value is assigned in the TypeError
255exception. Well, there may be a better way to do this in Python but
256that's what works for now).
257
258Putting that code into the raw_syscalls__sys_enter() handler, we
259effectively end up with a single-level dictionary keyed on syscall id
260and having the counts we've tallied as values.
261
262The print_syscall_totals() function iterates over the entries in the
263dictionary and displays a line for each entry containing the syscall
264name (the dictionary keys contain the syscall ids, which are passed to
265the Util function syscall_name(), which translates the raw syscall
266numbers to the corresponding syscall name strings). The output is
267displayed after all the events in the trace have been processed, by
268calling the print_syscall_totals() function from the trace_end()
269handler called at the end of script processing.
270
271The final script producing the output shown above is shown in its
272entirety below (syscall_name() helper is not yet available, you can
273only deal with id's for now):
274
275----
276import os
277import sys
278
279sys.path.append(os.environ['PERF_EXEC_PATH'] + \
280 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
281
282from perf_trace_context import *
283from Core import *
284from Util import *
285
286syscalls = autodict()
287
288def trace_end():
289 print_syscall_totals()
290
291def 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
299def 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
314The script can be run just as before:
315
316 # perf script -s syscall-counts.py
317
318So those are the essential steps in writing and running a script. The
319process can be generalized to any tracepoint or set of tracepoints
320you're interested in - basically find the tracepoint(s) you're
321interested in by looking at the list of available events shown by
322'perf list' and/or look in /sys/kernel/tracing/events/ for
323detailed event and field info, record the corresponding trace data
324using 'perf record', passing it the list of interesting events,
325generate a skeleton script using 'perf script -g python' and modify the
326code to aggregate and display it for your particular needs.
327
328After you've done that you may end up with a general-purpose script
329that you want to keep around and have available for future use. By
330writing a couple of very simple shell scripts and putting them in the
331right place, you can have your script listed alongside the other
332scripts listed by the 'perf script -l' command e.g.:
333
334----
335# perf script -l
336List 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----
341
342A nice side effect of doing this is that you also then capture the
343probably lengthy 'perf record' command needed to record the events for
344the script.
345
346To have the script appear as a 'built-in' script, you write two simple
347scripts, one for recording and one for 'reporting'.
348
349The 'record' script is a shell script with the same base name as your
350script, but with -record appended. The shell script should be put
351into the perf/scripts/python/bin directory in the kernel source tree.
352In that script, you write the 'perf record' command-line needed for
353your script:
354
355----
356# cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-record
357
358#!/bin/bash
359perf record -a -e raw_syscalls:sys_enter
360----
361
362The 'report' script is also a shell script with the same base name as
363your script, but with -report appended. It should also be located in
364the perf/scripts/python/bin directory. In that script, you write the
365'perf script -s' command-line needed for running your script:
366
367----
368# cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-report
369
370#!/bin/bash
371# description: system-wide syscall counts
372perf script -s ~/libexec/perf-core/scripts/python/syscall-counts.py
373----
374
375Note that the location of the Python script given in the shell script
376is in the libexec/perf-core/scripts/python directory - this is where
377the script will be copied by 'make install' when you install perf.
378For the installation to install your script there, your script needs
379to be located in the perf/scripts/python directory in the kernel
380source tree:
381
382----
383# ls -al kernel-source/tools/perf/scripts/python
384total 32
385drwxr-xr-x 4 trz trz 4096 2010-01-26 22:30 .
386drwxr-xr-x 4 trz trz 4096 2010-01-26 22:29 ..
387drwxr-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
389drwxr-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----
392
393Once you've done that (don't forget to do a new 'make install',
394otherwise your script won't show up at run-time), 'perf script -l'
395should show a new entry for your script:
396
397----
398# perf script -l
399List 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----
405
406You can now perform the record step via 'perf script record':
407
408 # perf script record syscall-counts
409
410and display the output using 'perf script report':
411
412 # perf script report syscall-counts
413
414STARTER SCRIPTS
415---------------
416
417You can quickly get started writing a script for a particular set of
418trace data by generating a skeleton script using 'perf script -g
419python' in the same directory as an existing perf.data trace file.
420That will generate a starter script containing a handler for each of
421the event types in the trace file; it simply prints every available
422field for each event in the trace file.
423
424You can also look at the existing scripts in
425~/libexec/perf-core/scripts/python for typical examples showing how to
426do basic things like aggregate event data, print results, etc. Also,
427the check-perf-script.py script, while not interesting for its results,
428attempts to exercise all of the main scripting features.
429
430EVENT HANDLERS
431--------------
432
433When 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
435no handler function defined for a given event type, the event is
436ignored (or passed to a 'trace_unhandled' function, see below) and the
437next event is processed.
438
439Most of the event's field values are passed as arguments to the
440handler function; some of the less common ones aren't - those are
441available as calls back into the perf executable (see below).
442
443As an example, the following perf record command can be used to record
444all sched_wakeup events in the system:
445
446 # perf record -a -e sched:sched_wakeup
447
448Traces meant to be processed using a script should be recorded with
449the above option: -a to enable system-wide collection.
450
451The format file for the sched_wakeup event defines the following fields
452(see /sys/kernel/tracing/events/sched/sched_wakeup/format):
453
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;
460
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----
467
468The handler function for this event would be defined as:
469
470----
471def 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----
476
477The handler function takes the form subsystem__event_name.
478
479The common_* arguments in the handler's argument list are the set of
480arguments passed to all event handlers; some of the fields correspond
481to the common_* fields in the format file, but some are synthesized,
482and some of the common_* fields aren't common enough to to be passed
483to every event as arguments but are available as library functions.
484
485Here's a brief description of each of the invariant event args:
486
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
494
495All of the remaining fields in the event's format file have
496counterparts as handler function arguments of the same name, as can be
497seen in the example above.
498
499The above provides the basics needed to directly access every field of
500every event in a trace, which covers 90% of what you need to know to
501write a useful trace script. The sections below cover the rest.
502
503SCRIPT LAYOUT
504-------------
505
506Every perf script Python script should start by setting up a Python
507module search path and 'import'ing a few support modules (see module
508descriptions below):
509
510----
511 import os
512 import sys
513
514 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
515 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
516
517 from perf_trace_context import *
518 from Core import *
519----
520
521The rest of the script can contain handler functions and support
522functions in any order.
523
524Aside from the event handler functions discussed above, every script
525can implement a set of optional functions:
526
527*trace_begin*, if defined, is called before any event is processed and
528gives scripts a chance to do setup tasks:
529
530----
531def trace_begin():
532 pass
533----
534
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:
538
539----
540def trace_end():
541 pass
542----
543
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:
547
548----
549def trace_unhandled(event_name, context, event_fields_dict):
550 pass
551----
552
553*process_event*, if defined, is called for any non-tracepoint event
554
555----
556def process_event(param_dict):
557 pass
558----
559
560*context_switch*, if defined, is called for any context switch
561
562----
563def context_switch(ts, cpu, pid, tid, np_pid, np_tid, machine_pid, out, out_preempt, *x):
564 pass
565----
566
567*auxtrace_error*, if defined, is called for any AUX area tracing error
568
569----
570def auxtrace_error(typ, code, cpu, pid, tid, ip, ts, msg, cpumode, *x):
571 pass
572----
573
574The remaining sections provide descriptions of each of the available
575built-in perf script Python modules and their associated functions.
576
577AVAILABLE MODULES AND FUNCTIONS
578-------------------------------
579
580The following sections describe the functions and variables available
581via the various perf script Python modules. To use the functions and
582variables from the given module, add the corresponding 'from XXXX
583import' line to your perf script script.
584
585Core.py Module
586~~~~~~~~~~~~~~
587
588These functions provide some essential functions to user scripts.
589
590The *flag_str* and *symbol_str* functions provide human-readable
591strings for flag and symbolic fields. These correspond to the strings
592and values parsed from the 'print fmt' fields of the event format
593files:
594
595 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
596 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
597
598The *autodict* function returns a special kind of Python
599dictionary that implements Perl's 'autovivifying' hashes in Python
600i.e. with autovivifying hashes, you can assign nested hash values
601without having to go to the trouble of creating intermediate levels if
602they don't exist.
603
604 autodict() - returns an autovivifying dictionary instance
605
606
607perf_trace_context Module
608~~~~~~~~~~~~~~~~~~~~~~~~~
609
610Some of the 'common' fields in the event format file aren't all that
611common, but need to be made accessible to user scripts nonetheless.
612
613perf_trace_context defines a set of functions that can be used to
614access this data in the context of the current event. Each of these
615functions expects a context variable, which is the same as the
616context variable passed into every tracepoint event handler as the second
617argument. For non-tracepoint events, the context variable is also present
618as perf_trace_context.perf_script_context .
619
620 common_pc(context) - returns common_preempt count for the current event
621 common_flags(context) - returns common_flags for the current event
622 common_lock_depth(context) - returns common_lock_depth for the current event
623 perf_sample_insn(context) - returns the machine code instruction
624 perf_set_itrace_options(context, itrace_options) - set --itrace options if they have not been set already
625 perf_sample_srcline(context) - returns source_file_name, line_number
626 perf_sample_srccode(context) - returns source_file_name, line_number, source_line
627
628
629Util.py Module
630~~~~~~~~~~~~~~
631
632Various utility functions for use with perf script:
633
634 nsecs(secs, nsecs) - returns total nsecs given secs/nsecs pair
635 nsecs_secs(nsecs) - returns whole secs portion given nsecs
636 nsecs_nsecs(nsecs) - returns nsecs remainder given nsecs
637 nsecs_str(nsecs) - returns printable string in the form secs.nsecs
638 avg(total, n) - returns average given a sum and a total number of values
639
640SUPPORTED FIELDS
641----------------
642
643Currently supported fields:
644
645ev_name, comm, pid, tid, cpu, ip, time, period, phys_addr, addr,
646symbol, symoff, dso, time_enabled, time_running, values, callchain,
647brstack, brstacksym, datasrc, datasrc_decode, iregs, uregs,
648weight, transaction, raw_buf, attr, cpumode.
649
650Fields that may also be present:
651
652 flags - sample flags
653 flags_disp - sample flags display
654 insn_cnt - instruction count for determining instructions-per-cycle (IPC)
655 cyc_cnt - cycle count for determining IPC
656 addr_correlates_sym - addr can correlate to a symbol
657 addr_dso - addr dso
658 addr_symbol - addr symbol
659 addr_symoff - addr symbol offset
660
661Some fields have sub items:
662
663brstack:
664 from, to, from_dsoname, to_dsoname, mispred,
665 predicted, in_tx, abort, cycles.
666
667brstacksym:
668 items: from, to, pred, in_tx, abort (converted string)
669
670For example,
671We can use this code to print brstack "from", "to", "cycles".
672
673if 'brstack' in dict:
674 for entry in dict['brstack']:
675 print "from %s, to %s, cycles %s" % (entry["from"], entry["to"], entry["cycles"])
676
677SEE ALSO
678--------
679linkperf:perf-script[1]