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