contents/getting-started/viewing-and-analyzing.md

   1 ---
   2 id: viewing-and-analyzing-your-traces
   3 ---
   4
   5 This section describes how to visualize the data gathered after tracing
   6 the Linux kernel or a user space application.
   7
   8 Many ways exist to read your LTTng traces:
   9
  10   * **`babeltrace`** is a command line utility which converts trace formats;
  11     it supports the format used by LTTng,
  12     <abbr title="Common Trace Format">CTF</abbr>, as well as a basic
  13     text output which may be `grep`ed. The `babeltrace` command is
  14     part of the
  15     <a href="http://www.efficios.com/babeltrace" class="ext">Babeltrace</a> project.
  16   * Babeltrace also includes a **Python binding** so that you may
  17     easily open and read an LTTng trace with your own script, benefiting
  18     from the power of Python.
  19   * The **<a href="https://eclipse.org/downloads/packages/eclipse-ide-cc-developers/lunar" class="ext">
  20     Eclise IDE for C/C++ Developers</a>**
  21     includes the Tracing and Monitoring Framework (TMF) plugin which
  22     supports LTTng traces, amongst others.
  23   * <a href="http://projects.eclipse.org/projects/tools.tracecompass">Trace Compass</a>
  24     is an Eclipse plugin, the TMF plugin mentioned above moved to its own
  25     project, used to visualize and analyze various types of traces,
  26     including LTTng. It also comes as a standalone application and can be
  27     downloaded from
  28     <a href="http://secretaire.dorsal.polymtl.ca/~gbastien/TracingRCP/TraceCompass/">here</a>
  29     for a daily build of the latest source code. A version containing some
  30     experimental features like Virtual Machine analysis and Critical Path
  31     analysis is also available
  32     <a href="http://secretaire.dorsal.polymtl.ca/~gbastien/TracingRCP/DorsalExperimental/">here</a>.
  33
  34 LTTng trace files are usually recorded in the `~/lttng-traces` directory.
  35 Let's now view the trace and perform a basic analysis using
  36 `babeltrace`.
  37
  38 The simplest way to list all the recorded events of a trace is to pass its
  39 path to `babeltrace` with no options:
  40
  41 <pre class="term">
  42 babeltrace ~/lttng-traces/my-session
  43 </pre>
  44
  45 `babeltrace` will find all traces within the given path recursively and
  46 output all their events, merging them intelligently.
  47
  48 Listing all the system calls of a Linux kernel trace with their arguments is
  49 easy with `babeltrace` and `grep`:
  50
  51 <pre class="term">
  52 babeltrace ~/lttng-traces/my-kernel-session | grep sys_
  53 </pre>
  54
  55 Counting events is also straightforward:
  56
  57 <pre class="term">
  58 babeltrace ~/lttng-traces/my-kernel-session | grep sys_read | wc -l
  59 </pre>
  60
  61 The text output of `babeltrace` is useful for isolating events by simple
  62 matching using `grep` and similar utilities. However, more elaborate filters
  63 such as keeping only events with a field value falling within a specific range
  64 are not trivial to write using a shell. Moreover, reductions and even the
  65 most basic computations involving multiple events are virtually impossible
  66 to implement.
  67
  68 Fortunately, Babeltrace ships with a Python 3 binding which makes it
  69 really easy to read the events of an LTTng trace sequentially and compute
  70 the desired information.
  71
  72 Here's a simple example using the Babeltrace Python binding. The following
  73 script accepts an LTTng Linux kernel trace path as its first argument and
  74 outputs the short names of the top 5 running processes on CPU 0 during the
  75 whole trace:
  76
  77 ~~~ python
  78 import sys
  79 from collections import Counter
  80 import babeltrace
  81
  82
  83 def top5proc():
  84     if len(sys.argv) != 2:
  85         msg = 'Usage: python {} TRACEPATH'.format(sys.argv[0])
  86         raise ValueError(msg)
  87
  88     # a trace collection holds one to many traces
  89     col = babeltrace.TraceCollection()
  90
  91     # add the trace provided by the user
  92     # (LTTng traces always have the 'ctf' format)
  93     if col.add_trace(sys.argv[1], 'ctf') is None:
  94         raise RuntimeError('Cannot add trace')
  95
  96     # this counter dict will hold execution times:
  97     #
  98     #   task command name -> total execution time (ns)
  99     exec_times = Counter()
 100
 101     # this holds the last `sched_switch` timestamp
 102     last_ts = None
 103
 104     # iterate events
 105     for event in col.events:
 106         # keep only `sched_switch` events
 107         if event.name != 'sched_switch':
 108             continue
 109
 110         # keep only events which happened on CPU 0
 111         if event['cpu_id'] != 0:
 112             continue
 113
 114         # event timestamp
 115         cur_ts = event.timestamp
 116
 117         if last_ts is None:
 118             # we start here
 119             last_ts = cur_ts
 120
 121         # previous task command (short) name
 122         prev_comm = event['prev_comm']
 123
 124         # initialize entry in our dict if not yet done
 125         if prev_comm not in exec_times:
 126             exec_times[prev_comm] = 0
 127
 128         # compute previous command execution time
 129         diff = cur_ts - last_ts
 130
 131         # update execution time of this command
 132         exec_times[prev_comm] += diff
 133
 134         # update last timestamp
 135         last_ts = cur_ts
 136
 137     # display top 10
 138     for name, ns in exec_times.most_common()[:5]:
 139         s = ns / 1000000000
 140         print('{:20}{} s'.format(name, s))
 141
 142
 143 if __name__ == '__main__':
 144     top5proc()
 145 ~~~
 146
 147 Save this script as `top5proc.py` and run it with Python 3, providing the
 148 path to an LTTng Linux kernel trace as the first argument:
 149
 150 <pre class="term">
 151 python3 top5proc.py ~/lttng-sessions/my-session-.../kernel
 152 </pre>
 153
 154 Make sure the path you provide is the directory containing actual trace
 155 files (`channel0_0`, `metadata`, etc.): the `babeltrace` utility recurses
 156 directories, but the Python binding does not.
 157
 158 Here's an example of output:
 159
 160 ~~~ text
 161 swapper/0           48.607245889 s
 162 chromium            7.192738188 s
 163 pavucontrol         0.709894415 s
 164 Compositor          0.660867933 s
 165 Xorg.bin            0.616753786 s
 166 ~~~
 167
 168 Note that `swapper/0` is the "idle" process of CPU 0 on Linux; since we
 169 weren't using the CPU that much when tracing, its first position in the list
 170 makes sense.