linux/tools/perf/Documentation/perf-trace-python.txt
<<
>>
Prefs
   1perf-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
  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 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 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
 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 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 -a -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 -a -e sched:sched_wakeup
 453
 454Traces meant to be processed using a script should be recorded with
 455the above option: -a to enable system-wide collection.
 456
 457The 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
 475The handler function for this event would be defined as:
 476
 477----
 478def 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
 484The handler function takes the form subsystem__event_name.
 485
 486The common_* arguments in the handler's argument list are the set of
 487arguments passed to all event handlers; some of the fields correspond
 488to the common_* fields in the format file, but some are synthesized,
 489and some of the common_* fields aren't common enough to to be passed
 490to every event as arguments but are available as library functions.
 491
 492Here'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
 502All of the remaining fields in the event's format file have
 503counterparts as handler function arguments of the same name, as can be
 504seen in the example above.
 505
 506The above provides the basics needed to directly access every field of
 507every event in a trace, which covers 90% of what you need to know to
 508write a useful trace script.  The sections below cover the rest.
 509
 510SCRIPT LAYOUT
 511-------------
 512
 513Every perf trace Python script should start by setting up a Python
 514module search path and 'import'ing a few support modules (see module
 515descriptions 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
 528The rest of the script can contain handler functions and support
 529functions in any order.
 530
 531Aside from the event handler functions discussed above, every script
 532can implement a set of optional functions:
 533
 534*trace_begin*, if defined, is called before any event is processed and
 535gives scripts a chance to do setup tasks:
 536
 537----
 538def 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----
 547def 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----
 556def trace_unhandled(event_name, context, common_cpu, common_secs,
 557        common_nsecs, common_pid, common_comm):
 558    pass
 559----
 560
 561The remaining sections provide descriptions of each of the available
 562built-in perf trace Python modules and their associated functions.
 563
 564AVAILABLE MODULES AND FUNCTIONS
 565-------------------------------
 566
 567The following sections describe the functions and variables available
 568via the various perf trace Python modules.  To use the functions and
 569variables from the given module, add the corresponding 'from XXXX
 570import' line to your perf trace script.
 571
 572Core.py Module
 573~~~~~~~~~~~~~~
 574
 575These functions provide some essential functions to user scripts.
 576
 577The *flag_str* and *symbol_str* functions provide human-readable
 578strings for flag and symbolic fields.  These correspond to the strings
 579and values parsed from the 'print fmt' fields of the event format
 580files:
 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
 585The *autodict* function returns a special kind of Python
 586dictionary that implements Perl's 'autovivifying' hashes in Python
 587i.e. with autovivifying hashes, you can assign nested hash values
 588without having to go to the trouble of creating intermediate levels if
 589they don't exist.
 590
 591  autodict() - returns an autovivifying dictionary instance
 592
 593
 594perf_trace_context Module
 595~~~~~~~~~~~~~~~~~~~~~~~~~
 596
 597Some of the 'common' fields in the event format file aren't all that
 598common, but need to be made accessible to user scripts nonetheless.
 599
 600perf_trace_context defines a set of functions that can be used to
 601access this data in the context of the current event.  Each of these
 602functions expects a context variable, which is the same as the
 603context variable passed into every event handler as the second
 604argument.
 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
 610Util.py Module
 611~~~~~~~~~~~~~~
 612
 613Various 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
 621SEE ALSO
 622--------
 623linkperf:perf-trace[1]
 624
lxr.linux.no kindly hosted by Redpill Linpro AS, provider of Linux consulting and operations services since 1995.