This section shows the process, start to finish, of creating a
working Python script that aggregates and extracts useful
information from a raw perf script stream. You can avoid reading
the rest of this document if an example is enough for you; the
rest of the document provides more details on each step and lists
the library functions available to script writers.
This example actually details the steps that were used to create
the syscall-counts script you see when you list the available
perf script scripts via perf script -l. As such, this script also
shows how to integrate your script into the list of
general-purpose perf script scripts listed by that command.
The syscall-counts script is a simple script, but demonstrates
all the basic ideas necessary to create a useful script. Here's
an example of its output (syscall names are not yet supported,
they will appear as numbers):
.ft C
syscall events:
event count
---------------------------------------- -----------
sys_write 455067
sys_getdents 4072
sys_close 3037
sys_swapoff 1769
sys_read 923
sys_sched_setparam 826
sys_open 331
sys_newfstat 326
sys_mmap 217
sys_munmap 216
sys_futex 141
sys_select 102
sys_poll 84
sys_setitimer 12
sys_writev 8
15 8
sys_lseek 7
sys_rt_sigprocmask 6
sys_wait4 3
sys_ioctl 3
sys_set_robust_list 1
sys_exit 1
56 1
sys_access 1
.ft
Basically our task is to keep a per-syscall tally that gets
updated every time a system call occurs in the system. Our script
will do that, but first we need to record the data that will be
processed by that script. Theoretically, there are a couple of
ways we could do that:
• we could enable every event under the tracing/events/syscalls
directory, but this is over 600 syscalls, well beyond the
number allowable by perf. These individual syscall events
will however be useful if we want to later use the guidance
we get from the general-purpose scripts to drill down and get
more detail about individual syscalls of interest.
• we can enable the sys_enter and/or sys_exit syscalls found
under tracing/events/raw_syscalls. These are called for all
syscalls; the id field can be used to distinguish between
individual syscall numbers.
For this script, we only need to know that a syscall was entered;
we don't care how it exited, so we'll use perf record to record
only the sys_enter events:
.ft C
# perf record -a -e raw_syscalls:sys_enter
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 56.545 MB perf.data (~2470503 samples) ]
.ft
The options basically say to collect data for every syscall event
system-wide and multiplex the per-cpu output into a single
stream. That single stream will be recorded in a file in the
current directory called perf.data.
Once we have a perf.data file containing our data, we can use the
-g perf script option to generate a Python script that will
contain a callback handler for each event type found in the
perf.data trace stream (for more details, see the STARTER SCRIPTS
section).
.ft C
# perf script -g python
generated Python script: perf-script.py
The output file created also in the current directory is named
perf-script.py. Here's the file in its entirety:
# perf script event handlers, generated by perf script -g python
# Licensed under the terms of the GNU GPL License version 2
# The common_* event handler fields are the most useful fields common to
# all events. They don't necessarily correspond to the 'common_*' fields
# in the format files. Those fields not available as handler params can
# be retrieved using Python functions of the form common_*(context).
# See the perf-script-python Documentation for the list of available functions.
import os
import sys
sys.path.append(os.environ['PERF_EXEC_PATH'] + \
'/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
from perf_trace_context import *
from Core import *
def trace_begin():
print "in trace_begin"
def trace_end():
print "in trace_end"
def raw_syscalls__sys_enter(event_name, context, common_cpu,
common_secs, common_nsecs, common_pid, common_comm,
id, args):
print_header(event_name, common_cpu, common_secs, common_nsecs,
common_pid, common_comm)
print "id=%d, args=%s\n" % \
(id, args),
def trace_unhandled(event_name, context, event_fields_dict):
print ' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())])
def print_header(event_name, cpu, secs, nsecs, pid, comm):
print "%-20s %5u %05u.%09u %8u %-20s " % \
(event_name, cpu, secs, nsecs, pid, comm),
.ft
At the top is a comment block followed by some import statements
and a path append which every perf script script should include.
Following that are a couple generated functions, trace_begin()
and trace_end(), which are called at the beginning and the end of
the script respectively (for more details, see the SCRIPT_LAYOUT
section below).
Following those are the event handler functions generated one for
every event in the perf record output. The handler functions take
the form subsystemevent_name, and contain named parameters, one
for each field in the event; in this case, there's only one
event, raw_syscallssys_enter(). (see the EVENT HANDLERS section
below for more info on event handlers).
The final couple of functions are, like the begin and end
functions, generated for every script. The first,
trace_unhandled(), is called every time the script finds an event
in the perf.data file that doesn't correspond to any event
handler in the script. This could mean either that the record
step recorded event types that it wasn't really interested in, or
the script was run against a trace file that doesn't correspond
to the script.
The script generated by -g option simply prints a line for each
event found in the trace stream i.e. it basically just dumps the
event and its parameter values to stdout. The print_header()
function is simply a utility function used for that purpose.
Let's rename the script and run it to see the default output:
.ft C
# mv perf-script.py syscall-counts.py
# perf script -s syscall-counts.py
raw_syscalls__sys_enter 1 00840.847582083 7506 perf id=1, args=
raw_syscalls__sys_enter 1 00840.847595764 7506 perf id=1, args=
raw_syscalls__sys_enter 1 00840.847620860 7506 perf id=1, args=
raw_syscalls__sys_enter 1 00840.847710478 6533 npviewer.bin id=78, args=
raw_syscalls__sys_enter 1 00840.847719204 6533 npviewer.bin id=142, args=
raw_syscalls__sys_enter 1 00840.847755445 6533 npviewer.bin id=3, args=
raw_syscalls__sys_enter 1 00840.847775601 6533 npviewer.bin id=3, args=
raw_syscalls__sys_enter 1 00840.847781820 6533 npviewer.bin id=3, args=
.
.
.
.ft
Of course, for this script, we're not interested in printing
every trace event, but rather aggregating it in a useful way. So
we'll get rid of everything to do with printing as well as the
trace_begin() and trace_unhandled() functions, which we won't be
using. That leaves us with this minimalistic skeleton:
.ft C
import os
import sys
sys.path.append(os.environ['PERF_EXEC_PATH'] + \
'/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
from perf_trace_context import *
from Core import *
def trace_end():
print "in trace_end"
def raw_syscalls__sys_enter(event_name, context, common_cpu,
common_secs, common_nsecs, common_pid, common_comm,
id, args):
.ft
In trace_end(), we'll simply print the results, but first we need
to generate some results to print. To do that we need to have our
sys_enter() handler do the necessary tallying until all events
have been counted. A hash table indexed by syscall id is a good
way to store that information; every time the sys_enter() handler
is called, we simply increment a count associated with that hash
entry indexed by that syscall id:
.ft C
syscalls = autodict()
try:
syscalls[id] += 1
except TypeError:
syscalls[id] = 1
.ft
The syscalls autodict object is a special kind of Python
dictionary (implemented in Core.py) that implements Perl's
autovivifying hashes in Python i.e. with autovivifying hashes,
you can assign nested hash values without having to go to the
trouble of creating intermediate levels if they don't exist e.g
syscalls[comm][pid][id] = 1 will create the intermediate hash
levels and finally assign the value 1 to the hash entry for id
(because the value being assigned isn't a hash object itself, the
initial value is assigned in the TypeError exception. Well, there
may be a better way to do this in Python but that's what works
for now).
Putting that code into the raw_syscalls__sys_enter() handler, we
effectively end up with a single-level dictionary keyed on
syscall id and having the counts we've tallied as values.
The print_syscall_totals() function iterates over the entries in
the dictionary and displays a line for each entry containing the
syscall name (the dictionary keys contain the syscall ids, which
are passed to the Util function syscall_name(), which translates
the raw syscall numbers to the corresponding syscall name
strings). The output is displayed after all the events in the
trace have been processed, by calling the print_syscall_totals()
function from the trace_end() handler called at the end of script
processing.
The final script producing the output shown above is shown in its
entirety below (syscall_name() helper is not yet available, you
can only deal with id's for now):
.ft C
import os
import sys
sys.path.append(os.environ['PERF_EXEC_PATH'] + \
'/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
from perf_trace_context import *
from Core import *
from Util import *
syscalls = autodict()
def trace_end():
print_syscall_totals()
def raw_syscalls__sys_enter(event_name, context, common_cpu,
common_secs, common_nsecs, common_pid, common_comm,
id, args):
try:
syscalls[id] += 1
except TypeError:
syscalls[id] = 1
def print_syscall_totals():
if for_comm is not None:
print "\nsyscall events for %s:\n\n" % (for_comm),
else:
print "\nsyscall events:\n\n",
print "%-40s %10s\n" % ("event", "count"),
print "%-40s %10s\n" % ("----------------------------------------", \
"-----------"),
for id, val in sorted(syscalls.iteritems(), key = lambda(k, v): (v, k), \
reverse = True):
print "%-40s %10d\n" % (syscall_name(id), val),
.ft
The script can be run just as before:
# perf script -s syscall-counts.py
So those are the essential steps in writing and running a script.
The process can be generalized to any tracepoint or set of
tracepoints you're interested in - basically find the
tracepoint(s) you're interested in by looking at the list of
available events shown by perf list and/or look in
/sys/kernel/debug/tracing/events/ for detailed event and field
info, record the corresponding trace data using perf record,
passing it the list of interesting events, generate a skeleton
script using perf script -g python and modify the code to
aggregate and display it for your particular needs.
After you've done that you may end up with a general-purpose
script that you want to keep around and have available for future
use. By writing a couple of very simple shell scripts and putting
them in the right place, you can have your script listed
alongside the other scripts listed by the perf script -l command
e.g.:
.ft C
# perf script -l
List of available trace scripts:
wakeup-latency system-wide min/max/avg wakeup latency
rw-by-file <comm> r/w activity for a program, by file
rw-by-pid system-wide r/w activity
.ft
A nice side effect of doing this is that you also then capture
the probably lengthy perf record command needed to record the
events for the script.
To have the script appear as a built-in script, you write two
simple scripts, one for recording and one for reporting.
The record script is a shell script with the same base name as
your script, but with -record appended. The shell script should
be put into the perf/scripts/python/bin directory in the kernel
source tree. In that script, you write the perf record
command-line needed for your script:
.ft C
# cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-record
#!/bin/bash
perf record -a -e raw_syscalls:sys_enter
.ft
The report script is also a shell script with the same base name
as your script, but with -report appended. It should also be
located in the perf/scripts/python/bin directory. In that script,
you write the perf script -s command-line needed for running your
script:
.ft C
# cat kernel-source/tools/perf/scripts/python/bin/syscall-counts-report
#!/bin/bash
# description: system-wide syscall counts
perf script -s ~/libexec/perf-core/scripts/python/syscall-counts.py
.ft
Note that the location of the Python script given in the shell
script is in the libexec/perf-core/scripts/python directory -
this is where the script will be copied by make install when you
install perf. For the installation to install your script there,
your script needs to be located in the perf/scripts/python
directory in the kernel source tree:
.ft C
# ls -al kernel-source/tools/perf/scripts/python
total 32
drwxr-xr-x 4 trz trz 4096 2010-01-26 22:30 .
drwxr-xr-x 4 trz trz 4096 2010-01-26 22:29 ..
drwxr-xr-x 2 trz trz 4096 2010-01-26 22:29 bin
-rw-r--r-- 1 trz trz 2548 2010-01-26 22:29 check-perf-script.py
drwxr-xr-x 3 trz trz 4096 2010-01-26 22:49 Perf-Trace-Util
-rw-r--r-- 1 trz trz 1462 2010-01-26 22:30 syscall-counts.py
.ft
Once you've done that (don't forget to do a new make install,
otherwise your script won't show up at run-time), perf script -l
should show a new entry for your script:
.ft C
# perf script -l
List of available trace scripts:
wakeup-latency system-wide min/max/avg wakeup latency
rw-by-file <comm> r/w activity for a program, by file
rw-by-pid system-wide r/w activity
syscall-counts system-wide syscall counts
.ft
You can now perform the record step via perf script record:
# perf script record syscall-counts
and display the output using perf script report:
# perf script report syscall-counts
