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