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