| 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. |