1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
|
<!--
Note: DO NOT EDIT THE HTML FILES!
The documentation is written using the markdown. The .html files are
generated from the .text files. If you want to update the
documentation you must edit the .text file and re-generate the
corresponding .html file by executing make.
See
http://code.google.com/p/python-markdown2/
and
http://daringfireball.net/projects/markdown/
for further information.
Note: PLEASE UPDATE THE CHANGE HISTORY AT THE END OF THE FILE WHEN YOU
UPDATE THIS FILE.
# The following line is picked up bye the gen_html script.
TITLE=Tracing with LITMUS^RT
-->
Tracing with LITMUS<sup>RT</sup>
================================
<div class="preamble">
This document is part of the documentation of the <a href="../index.html">LITMUS<sup>RT</sup> project</a>.
</div>
As of version 2008.2, there are three tracing mechanisms available in LITMUS<sup>RT</sup>:
1. `litmus_log`: This trace contains text messages (created with the `TRACE()`
macro, see `litmus.h`) that convey information useful for debugging. There is one global
`litmus_log` buffer for the whole system. The `litmus_log` facility is essentially a replacement for `printk()`, which cannot be invoked from scheduling code without risking deadlock. Debug tracing must be enabled at compile time. Note that debug tracing creates significant overhead because string formatting takes place.
2. `ft_trace`: This trace contains binary-encoded time stamps. It is used for overhead tracing. There is one global `ft_trace` buffer for the whole system. The "ft" stands for [Feather-Trace](http://www.cs.unc.edu/~bbb/feather-trace). Feather-Trace is designed to create only negligible overhead when event sources are disabled, and to incur only low overhead when recording time stamps.
3. `sched_trace`: This trace contains binary-encoded scheduling event information, *e.g.*, an event can be recorded whenever a task got scheduled, a job was released, a job completed, etc. There is one `sched_trace` buffer per processor. `sched_trace` is based on Feather-Trace and hence also incurs only negligible overhead when event sources are disabled.
Accessing Trace Buffers
-----------------------
Currently, all three traces are exported to user space through character device drivers. The major numbers allocated by the drivers can be discovered by looking at `/proc/devices`. Usually, the major numbers are 251, 252, and 253 respectively.
The per-processor buffers are accessible via the minor numbers of the drivers. Hence, proper device files can be created with the following script.
#!/bin/bash
LITMUS_LOG_MAJOR=`grep litmus_log /proc/devices | awk '{print $1}'`
FT_TRACE_MAJOR=`grep ft_trace /proc/devices | awk '{print $1}'`
SCHED_TRACE_MAJOR=`grep sched_trace /proc/devices | awk '{print $1}'`
mknod litmus_log c $LITMUS_LOG_MAJOR 0
mknod ft_trace c $FT_TRACE_MAJOR 0
NUM_PROCS=$((`grep 'processor' /proc/cpuinfo | wc -l` - 1))
for P in `seq 0 $NUM_PROCS`
do
mknod "sched_trace$P" c $SCHED_TRACE_MAJOR $P
done
Alternatively, one can setup `udev` rules to create the devices on demand. This, however, is beyond the scope of this document.
Recording Debug Traces
----------------------
The `litmus_log` buffer can be read by simply opening the file and reading its contents:
cat litmus_log > my_debug_log
Kill the `cat` process to stop recording debug messages.
No post-processing is required since the debug messages are plain text. However, note that messages may appear in an order that differs from the sequence of events at runtime. If order is important (for example when debugging race conditions), then recorded messages can be sorted offline with the help of the *sequence number* at the start of each recorded message.
Example:
sort -n my_debug_log > my_sorted_debug_log
**Hint**: One can use `netcat(1)` to send the debug messages to another machine via UDP to avoid filesystem activity.
Recording Overhead Traces
--------------------------
Feather-Trace allows for much more fine-grained tracing than the simple debug stream realized by `litmus_log` and hence requires special-purpose tools to be used. These tools are available as part of the `ft_tools` package, which is available on the [LITMUS<sup>RT</sup> download page](../index.html#download).
Feather-Trace events can be enabled on a per-event basis. Each event is identified by a unique 32-bit ID. Initially, when the device buffer is not being accessed by any user space programs (*i.e.*, when the device driver is unused), all events are disabled. Events can be enabled (and subsequently disabled again) by writing binary commands to the buffer device file. Once events are enabled they can generate trace records, which are stored in the trace buffer. User space programs can obtain these records by reading from the device file. Reading a trace record removes it from the buffer, *i.e.*, each record can be read exactly once. Records should be consumed shortly after they were created since buffer capacity is limited.
The tool `ftcat`, which is part of the `ft_tools` package (see above), automates the process of enabling events and retrieving trace records. It takes the name of the `ft_trace` device file and the events of interest as arguments:
ftcat <ft device> <event 1> <event 2> <event 3> ...
The tool enables the specified events and copies all recorded events to `stdout`.
Events can be specified either by their ID (see `include/litmus/trace.h` in the kernel directory for a list of time stamp generating events) or by their symbolic name. The following symbolic names are recognized:
- `SCHED_START`, `SCHED_END`:
Used to measure the time spent to make a scheduling decision.
- `CXS_START`, `CXS_END`:
Used to record the time spent to make a context switch.
- `SCHED2_START`, `SCHED2_END`:
Used to measure the time spent to perform post-context-switch cleanup and management activities. This is part of the scheduling overhead but for technical reasons cannot be measured as part of the interval [`SCHED_START`, `SCHED_END`].
- `TICK_START`, `TICK_END`:
Used to measure the overhead incurred at the beginning of a scheduling quantum.
- `PLUGIN_TICK_START`, `PLUGIN_TICK_END`:
Like [`TICK_START`, `TICK_END`], but only measures the time spent by the active scheduling plugin.
- `PLUGIN_SCHED_START`, `PLUGIN_SCHED_END`:
Like [`SCHED_START`, `SCHED_END`], but only measures the time spent by the active scheduling plugin. There is no equivalent `SCHED2` counterpart because the scheduling plugins do not directly compute to the `SCHED2` overhead.
- `RELEASE_START`, `RELEASE_END`:
Used to measure the time spent to enqueue a newly-released job in a ready queue.
For example, the following command can be used to store the length of context switches and scheduling decisions in the file `my_trace`.
$ ftcat ft_trace CXS_START CXS_END SCHED_START SCHED_END SCHED2_START SCHED2_END > my_trace
The tracing can be stopped by interrupting `ftcat` with `^C` or by sending `SIGTERM` with `kill(1)`.
Note that the recorded trace is stored in the byte order of the host.
Post-Processing Overhead Traces
-------------------------------
The binary event stream recorded by `ftcat` is of course of limited direct use—the data has yet to be exported for analysis. This can be achieved with the tool `ft2csv`, which is also part of the `ft_tools` package.
As the name suggests, `ft2csv` extracts intervals defined by pairs of time stamps in a recorded trace and displays them as *comma-separated values* (CSV). It takes the name of an overhead trace and one start event as arguments:
ft2csv <start event> <overhead trace>
Events are specified in the same way as with `ftcat`. For example, the following command can be used to print the context-switch lengths that were recorded in the example above to `stdout`.
$ ft2csv CXS_START my_trace
2397634444579592, 2397634444583328, 3736
2397634477323130, 2397634477326686, 3556
2397634477346366, 2397634477348986, 2620
2397634611910924, 2397634611914348, 3424
...
For each event, the start time (in clock cycles) is given in the first column, the end time is given in the second column, and the length is given in the third column (again, in cycles).
`ft2csv` accepts a few options that affect how events are filtered. By default, events that do not involve real-time tasks are ignored. This can be changed by specifying the `-b` option. If one happens to be processing output on a little-endian host that was produced on a big-endian host then the `-e` option can come in handy.
Once the recorded overheads have been exported to CSV files they can be easily analyzed with tools such as Python's `csv` module, Octave, or Matlab.
Recording Scheduling Traces
---------------------------
Scheduling traces are also recorded using Feather-Trace. However, a different binary format is used. The definition and an explanation of the format can be found in the file `include/litmus/sched_trace.h` (in the kernel directory).
Since `sched_trace` uses per-processor buffers several `ftcat` instances have to be launched. The `ft_tools` package includes a wrapper script called `st_trace` that automates this setup procedure. Note that one may have to modify `st_trace` to change the default location of the `sched_trace` device files. `st_trace` accepts a tag as the only argument. The tag is used to assign a unique name to the trace files.
The following example illustrates how `st_trace` is used with the tag `global-exp`.
$ st_trace global-exp
CPU 0: 8204 > st-global-exp-0.bin [0]
CPU 1: 8205 > st-global-exp-1.bin [0]
CPU 2: 8206 > st-global-exp-2.bin [0]
CPU 3: 8207 > st-global-exp-3.bin [0]
Press Enter to end tracing... # enter pressed
Disabling 9 events.
Disabling 9 events.
Disabling 9 events.
Disabling 9 events.
/home/litmus/log0: 1234 bytes read.
/home/litmus/log1: 1234 bytes read.
/home/litmus/log2: 1234 bytes read.
/home/litmus/log3: 1234 bytes read.
Note that `st_trace` may have to be modified to change the default `sched_trace` device locations.
**Hint**: The dummy real-time task `rtspin` (distributed as part of the `liblitmus` package) may be useful when studying/testing the behavior of a scheduler plugin.
Post-Processing Scheduling Traces
---------------------------------
The user space library and tools package `liblitmus` contains the necessary headers to write `sched_trace` post-processing and analysis tools (see `include/sched_trace.h` and `src/sched_trace.c`).
The tool `showst` (distributed as part of `liblitmus`) can be used to inspect the binary traces recorded with `st_trace` and may provide a good starting point for the development of custom analysis tools.
Concluding Remarks
------------------
At this point we only offer data *acquisition* tools since we have not yet had the time to develop release-quality *analysis* tools. **Patches that improve the existing tools and contributions of new analysis and visualization tools are very much welcome!**
For any questions please contact the current LITMUS<sup>RT</sup> maintainer (as indicated on the [LITMUS<sup>RT</sup> homepage](../index.html#collaborators)).
Change History
--------------
- Initially written by <a href="http://www.cs.unc.edu/~bbb">Bjoern B. Brandenburg</a> (bbb at cs.unc.edu) on 12/09/2008.
|
