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