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