Added a section on connecting the tracing framework to Aquarium 2 directly in the...
[barrelfish] / doc / 008-tracing / Tracing.tex
1 %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
2 % Copyright (c) 2011, ETH Zurich.
3 % All rights reserved.
4 %
5 % This file is distributed under the terms in the attached LICENSE file.
6 % If you do not find this file, copies can be found by writing to:
7 % ETH Zurich D-INFK, Universitaetstr. 6, CH-8092 Zurich. Attn: Systems Group.
8 %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
9
10 \documentclass[a4paper,11pt,twoside]{report}
11 \usepackage{bftn}
12 \usepackage{calc}
13 \usepackage{verbatim}
14 \usepackage{xspace}
15 \usepackage{pifont}
16 \usepackage{textcomp}
17 \usepackage{amsmath}
18 \usepackage{hyperref}
19
20 % Disable ugly boxes
21 \hypersetup{
22     colorlinks=false,
23     pdfborder={0 0 0},
24 }
25
26 % Include the listings-package
27 \usepackage{listings}
28 \lstset{
29         basicstyle=\footnotesize\ttfamily,
30         framexbottommargin=4pt,
31         frame=single,
32         captionpos=b,
33         language=c
34 }
35
36 \usepackage{float}
37 \newfloat{code}{H}{myc}
38
39 \usepackage{bytefield}
40
41 \newcommand{\HRule}{\rule{\linewidth}{0.5mm}}
42
43 \title{Tracing and Visualisation}
44 \author{Barrelfish project}
45 % \date{\today}         % Uncomment (if needed) - date is automatic
46 \tnnumber{8}
47 \tnkey{Tracing}
48
49 \begin{document}
50 \maketitle                      % Uncomment for final draft
51
52 \begin{versionhistory}
53 \vhEntry{1.0}{28.02.2013}{Alexander Grest, David Stolz}{Initial version}
54 \end{versionhistory}
55
56 % \intro{Abstract}              % Insert abstract here
57 % \intro{Acknowledgements}      % Uncomment (if needed) for acknowledgements
58 \tableofcontents                % Uncomment (if needed) for final draft
59 % \listoffigures                % Uncomment (if needed) for final draft
60 % \listoftables                 % Uncomment (if needed) for final draft
61
62
63 \chapter{Overview}
64
65 The tracing framework in Barrelfish consists of three major components:
66
67 \begin{itemize}
68         \item The tracing library.
69         \item Bfscope (a Barrelfish program).
70         \item Aquarium 2.
71 \end{itemize}
72
73 The tracing library can be used to instrument code in order to trace events.
74 The events are stored core local and can later be flushed, either to console
75 or -- with the help of Bfscope -- to a remote machine. On the remote machine
76 you can analyze the trace data using Aquarium 2. Aquarium 2 can be customized with scripts,
77 making it easy to integrate specific needs into the existing analysis framework.
78 In addition it supports various export functionalities that allow you to analyze
79 trace data with external tools in an easy fashion.
80
81 \chapter{Design and Implementation of the Tracing Framework in Barrelfish}
82
83 \section{Overview\label{sec:trace-overview}}
84
85 The tracing framework inside of Barrelfish existed already before this project
86 has been started. In order to break as little as possible in existing code to
87 work with the tracing system (e.g.~tools that have been developed analyzing
88 trace logs) we decided to change as little as possible on the interface of the
89 tracing framework. In the end the structure of the trace logs that are generated
90 did not change, but only some mappings between constants in code and their
91 interpretation. 
92
93 In this section we want to look at the part of the tracing framework that is
94 implemented in Barrelfish, i.e.~the actual functionality that developers use in
95 order to create trace logs. One part of the tracing framework allows developers
96 to trace events at any point in the code, where the data that is actually stored
97 is defined in the Section \ref{sec:trace-event}. The second part is responsible
98 for delivering the generated trace logs to Aquarium. To achieve the second goal
99 we changed the existing Barrelfish application Bfscope in such a way, that it
100 integrates with the new version of the tracing framework. Bfscope is described
101 in Section \ref{sec:bfscope}.
102
103 The typical lifecycle of using the tracing framework in Barrelfish looks like
104 this:
105
106 \begin{description}
107         \item[0.a (Optional)] Prepare the tracing framework.
108         \item[0.b (Optional)] Specify which Subsystems should be logged.
109         \item[1.] Define the type of event that will trigger the start of tracing.
110         \item[2.] \emph{Execute your code, that will log the events.}
111         \item[3.] Flush the logged events, e.g.~on the console.
112 \end{description}
113
114 To get more information about the optional steps, see Sections
115 \ref{sec:preparing} and \ref{sec:enabling-disabling}. The first mandatory step
116 is to define the type of the event that will start the logging process. Having a
117 mechanism for starting and stopping the actual tracing may seem like a benefit,
118 but not like a necessity at first -- but our experiments have shown that even
119 with rather small instrumentation of code (i.e.~number of events that actually
120 generate an entry in the trace log), having the tracing framework log events all
121 the time is no option. Thus having the possibility to start and stop the tracing
122 framework is essential. Having the flexibility of specifying a type of trace
123 event that will trigger the start and stop of the logging is an additional
124 benefit compared to having simple ``start'' and ``stop'' commands, as it allows
125 developers to easily vary the portion of code they want to trace, without
126 changing the placement of a ``start'' and ``stop'' command all the time.
127
128 While the second mandatory step is pretty self-explanatory, the third step is
129 more interesting again: The old version of the tracing system allowed only for
130 dumping the stored trace into a provided buffer. This functionality has now been
131 improved in such a way that we offer developers a method to flush the current
132 trace log, and the flush functionality automatically detects the best way to
133 flush. Currently there are two possible destinations onto which can be flushed:
134 The console and the network. The tracing framework detects automatically if
135 Bfscope is running and someone is connected to it -- if so, it flushes over the
136 network -- else it will flush to the console. The flushing functionality could
137 also be extended, a possible idea would be to store the trace log in a file. In
138 Figure \ref{fig:flush} you can see a sequence diagram illustrating the process
139 of invoking the new flushing functionality.
140
141 \begin{figure}[t]
142         \begin{center}
143                 \includegraphics{images/flush.pdf}
144         \end{center}
145         \caption{A sequence diagram illustrating the flow of events when using the
146         flush functionality. ``Application'' is the application that is using the
147 tracing framework, and chips is the Barrelfish nameserver. The grey boxes
148 indicate the destination onto which is flushed.}
149         \label{fig:flush}
150 \end{figure}
151
152
153 \section{Definition of a Trace Event\label{sec:trace-event}}
154
155 Let us now define the structure of events that can be traced. Each event
156 belongs to a Subsystem and an Event, and has an optional payload called Argument
157 that can hold 32 bits of arbitrary information. Both the Subsystem and the Event
158 are 16 bit identifiers, allowing us to have up to 65535 Subsystems and for each
159 Subsystem 65535 Events. Note that the Events are relative to the Subsystems,
160 i.e.~a Subsystem called \emph{kernel} might have the Event \emph{Context Switch}
161 with the identifier 0, but the same Event identifier 0 has an entirely different
162 meaning in every other Subsystem.
163
164 Having all these different Subsystem and Event identifier available, we think
165 that the tracing framework will have sufficient space to deal with future change
166 in Barrelfish\footnote{Currently there exist 16 different Subsystems.}.
167
168 In addition to the Subsystem, Event and Argument information, the tracing
169 framework adds a timestamp to each event that gets logged (the timestamp is
170 measured in CPU cycles) and remembers the core on which the event was logged. The core is
171 only implicitly stored, as we have a separate tracing buffer on each core,
172 allowing us to identify the core for an event at a later stage automatically,
173 without storing it for each event.
174
175 As timestamps are stored as a 64 bit number, we need a total of 128 bits
176 (respectively 16 bytes) per event that has been logged. The data structure
177 layout of a single event can be seen in Figure \ref{fig:trace-event}.
178
179 \begin{figure}[t]
180         \begin{center}
181
182           \begin{bytefield}{64}
183             \bitheader{0,16,32,48,63} \\
184             \bitbox{64}{Timestamp} \\
185             \bitbox{16}{Subsystem}
186             \bitbox{16}{Event}
187             \bitbox{32}{Argument}
188           \end{bytefield}
189
190         \end{center}
191         \caption{Representation of a single trace event in memory in Barrelfish.}
192         \label{fig:trace-event}
193 \end{figure}
194
195 \section{Pleco: A new Domain Specific Language}
196
197 \subsection{Overview}
198
199 As trace events are identified by the type of their Subsystem and Event (which
200 is a two tier hierarchical structure), the best way to specify those Subsystems
201 and Events is using a domain specific language. For this purpose we designed a
202 new domain specific language called \emph{pleco}, that resembles the domain
203 specific language for error codes in Barrelfish (called fugu) a lot -- due to
204 the fact that it solves a very similar task.
205
206 Pleco allows programmer to easily add new Subsystems to the tracing framework
207 and to extend existing Subsystems with new Events. Note that the Argument
208 parameter of the trace events is not specified in Pleco, as this parameter is
209 intended to be a payload, and not to be a means to distinguish different trace
210 events. A small sample pleco file can be seen in Listing
211 \ref{lst:pleco-file}. In this file we define two Subsystems: \texttt{kernel} and
212 \texttt{memserv}. Note that the keyword \emph{subsystem} is used to define a new
213 Subsystem. The Events for a Subsystem are defined in the block following its
214 name. Events have both a name and a verbose description, following the keyword
215 \emph{event}. The textual description is \emph{not used} in the tracing framework
216 inside of Barrelfish, but Aquarium will use the textual description to display
217 it when analyzing generated traces. Note that the textual description is not a
218 strict requirement; if the empty string is provided, during the interpretation
219 of the pleco file, the name of the event will be substituted for the textual
220 description.
221
222 \begin{code}
223 \begin{lstlisting}[frame=single, caption={A small example pleco file with two
224         Subsystems.}, label={lst:pleco-file}]
225 subsystem kernel {
226
227         event CSWITCH               "Context Switch",
228         event BZERO                 "Buffer zeroing",
229         event TIMER                 "", 
230         event TIMER_SYNC            "", 
231
232 };
233
234 subsystem memserv {
235
236         event ALLOC                  "", 
237 };
238 \end{lstlisting}
239 \end{code}
240
241 \subsection{Interpreting Pleco Files}
242
243 Parsing and interpreting of pleco files is part of the Barrelfish build process,
244 meaning that the according tools are written in Haskell and are integrated into
245 the Hake build process.  An overview of how pleco files are integrated into the
246 Barrelfish toolchain can be seen in Figure \ref{fig:pleco-process}. Note that
247 the header file that is created during the build process is directly used in the
248 very same build process, i.e.~it is just an intermediate file.
249
250 \begin{figure}[t]
251         \begin{center}
252                 \includegraphics{images/pleco-process.pdf}
253         \end{center}
254         \caption{Pleco files get translated into both a C header file and a JSON
255         file. This translation is taking place during the regular build process of
256 Barrelfish.}
257         \label{fig:pleco-process}
258 \end{figure}
259
260 \subsection{The Generated Header File}
261
262 For the pleco file of Listing \ref{lst:pleco-file}, the header file shown in
263 Listing \ref{lst:headerfile} has been generated during the build process. In
264 Barrelfish source code, this file can be included with the statement:
265
266 \begin{lstlisting}
267 #include <trace_definitions/trace_defs.h>
268 \end{lstlisting}
269
270 Note that the macro that are created for events also contain the subsystem name,
271 so that there will not be any name collisions when two different subsystem
272 define an Event with the same name.
273
274 The generated numbers are not randomized. The reason for this is not that people
275 can avoid using macros, but rather for a new feature that has been introduced
276 into the tracing framework to work: enabling and disabling of Subsystems that
277 are logged. See Section \ref{sec:enabling-disabling} for detailed information.
278
279 \begin{code}
280 \begin{lstlisting}[frame=single, caption={A header file that has been generated
281         based on the pleco file shown in Listing \ref{lst:pleco-file}.}, label={lst:headerfile}]
282 #ifndef TRACE_DEFS_BARRELFISH__                                                          
283 #define TRACE_DEFS_BARRELFISH__
284
285 #define TRACE_SUBSYS_KERNEL 0
286 #define TRACE_EVENT_KERNEL_CSWITCH  0
287 #define TRACE_EVENT_KERNEL_BZERO    1
288 #define TRACE_EVENT_KERNEL_TIMER    2
289 #define TRACE_EVENT_KERNEL_TIMER_SYNC   3
290
291 #define TRACE_SUBSYS_MEMSERV    1
292 #define TRACE_EVENT_MEMSERV_ALLOC   0
293
294
295 #define TRACE_NUM_SUBSYSTEMS    2
296
297 #endif // TRACE_DEFS_BARRELFISH__ 
298
299 \end{lstlisting}
300 \end{code}
301
302 \subsection{The Generated JSON File}
303
304 As the pleco file shown in Listing  \ref{lst:pleco-file} does not only get
305 translated into a header file, but also into a JSON file, we want to have a look
306 at this file now. The JSON file that has been generated for said pleco file can
307 be seen in Listing \ref{lst:jsonfile}.
308
309 \begin{code}
310 \begin{lstlisting}[frame=single, caption={A JSON file that has been generated
311         based on the pleco file shown in Listing \ref{lst:pleco-file}. This file can
312 be used by Aquarium to decode log traces.}, label={lst:jsonfile}]
313 {                                                                                        
314 0 : { 
315     "name" : "kernel",
316     "events" : { 
317         0 : "Context Switch",
318         1 : "Buffer zeroing",
319         2 : "TIMER",
320         3 : "TIMER_SYNC"
321     }   
322 },
323 1 : { 
324     "name" : "memserv",
325     "events" : { 
326         0 : "ALLOC"
327     }   
328 }
329 }
330 \end{lstlisting}
331 \end{code}
332
333 As you can see, the textual description in the pleco file was used where
334 provided, and where it wasn't, the name of the Event has been used as a
335 substitution. The generated numbers are the same as the ones in the header file.
336 This is no coincidence, as the usage of this JSON file is exactly to decode the
337 numbers from the trace logs into human readable events again.
338
339 For the purpose of decoding the events, the old version of Aquarium had the
340 mapping from numbers to human readable events directly hard coded into the
341 source code. This new way of defining Subsystems and Events in pleco files
342 allows programmers to omit duplicate work (and having to check that both programs
343 are always consistent), and provides them with an automated way of having a
344 consistent tracing framework and analysis tool.
345
346 \section{Feature Overview}
347 \subsection{Preparing the Tracing Framework\label{sec:preparing}}
348
349 The tracing framework does not strictly need any extra preparation, nevertheless
350 depending on the environment, a preparation might be necessary. For this reason
351 we added the functionality to prepare the tracing framework. Currently the
352 preparation process estimates the offset between the CPU cycle counters on the
353 different cores. This functionality is not needed on machines that have
354 synchronized cycle counters, but in the future it might be possible to run a
355 single instance of Barrelfish on multiple machines, and in this case the
356 different cycle counters will not be synchronized anymore.
357
358 The cycle counter offsets are all measured relative to core $0$. To measure the
359 offset between a core $i$ and core $0$, we execute the Network Time Protocol
360 clock synchronization algorithm 
361 between the two cores. Figure \ref{fig:ntp} illustrates the steps of the clock
362 synchronization between two cores. Four time measurements are performed and the
363 estimated offset $\theta$ between the two cores is calculated as follows:
364
365 \begin{equation}
366         \theta =  \frac{(t_1-t_0)+(t_2-t_3)}{2}
367 \end{equation}
368
369 \begin{figure}[t]
370         \begin{center}
371                 \includegraphics{images/ntp.pdf}
372         \end{center}
373         \caption{NTP clock synchronization. Four time measurements $t_0$ to $t_3$
374         are performed. }
375         \label{fig:ntp}
376 \end{figure}
377
378 The tracing framework performs measurements between every core $i$ ($i > 0$) and
379 core $0$ sequentially, so that the measurements are as precise as possible. The
380 messages needed to perform those measurements are sent using the monitor,
381 meaning that the tracing framework does not need to setup any new channel.
382
383 \subsection{Enabling and Disabling of Events\label{sec:enabling-disabling}}
384
385 With the new version of Aquarium it is possible to filter out events in the
386 analysis for a given trace log. But it showed that this functionality is not
387 sufficient, as there are use cases where applications log so many events, that
388 filtering must already be performed on the fly, i.e.~already during the tracing
389 process itself. An application where this is currently necessary in Barrelfish
390 is the tracing of the network stack. The current way of achieving this filtering
391 is introducing preprocessor statements at different locations in the code.
392 Having the new domain specific language available, we implemented a mechanism to
393 enable and disable Subsystems directly at runtime, using the Subsystem
394 identifier generated from the pleco file.
395
396 It is now possible to change which Subsystems are logged directly at runtime,
397 removing the need of recompiling the entire tracing framework just because the
398 type of events that a developer is interested changed. With the hierarchical
399 structure of Subsystems and Events it was possible to implement this enabling
400 facility in a lightweight manner, as the number of Subsystems is quite small.
401
402
403 \subsection{Automatic Flushing}
404
405 The flush procedure described in Section \ref{sec:trace-overview} can be
406 triggered by manually calling the according trace framework function. In
407 addition to the manually triggered flushing, we added a new functionality,
408 namely the one that the trace buffer is flushed automatically. This
409 functionality is implemented with in Bfscope, as we think the main use-case for
410 automatic flushing is when the generated logs are automatically forwarded to a
411 remote machine\footnote{Having the console cluttered with events from the
412 tracing framework can render the application unusable rather quickly.}. When a
413 developer decides to enable the automatic flushing and Bfscope is running,
414 Bfscope will automatically flush the content of the trace buffers periodically.
415 This feature removes the need of having to call the flush procedure manually,
416 but it developers should note that if timing is critical for your application,
417 the automatic flushing functionality can lead to issues. The issues that can
418 arise come from the fact that it is possible that Bfscope flushes in the middle
419 of your application executing its code -- this does not lead to a problem of
420 correctness, but it can heavily skew the flow of events in the Barrelfish as a
421 whole.
422
423 \section{Bfscope\label{sec:bfscope}}
424
425 Bfscope is a Barrelfish program that enhances the functionality of the tracing
426 framework by the possibility to directly flush trace logs over the network. Note
427 that the tracing in the Barrelfish code itself runs independently of Bfscope --
428 and it even notices when Bfscope is running and changes its behavior
429 accordingly. Bfscope allows developers to connect from a remote machine to the
430 Barrelfish OS, using a TCP connection and to get the trace logs directly onto
431 the remote machine. Note that when a remote machine is connected, regular flush
432 commands in Barrelfish will automatically be redirected onto the network, and
433 you will not see the trace logs on the console any longer.
434
435 As the remote machine is merely a utility that wants to get the trace log data,
436 there are no messages exchanged as part of a protocol -- Bfscope simply sends
437 the trace log data onto the TCP connection, once the flush command is issued (or
438 periodically if automatic flushing is enabled). This has, beneath being a simple
439 protocol, the additional benefit that it is no longer necessary to run Aquarium
440 in order to be able to get the trace log onto a remote machine, but you rather
441 can use any tool that allows you to open a TCP connection, such as netcat. Using
442 such a tool will allow you to get the trace log data on a different machine,
443 where you can either later analyze it with Aquarium, or with custom scripts.
444
445 Nevertheless the main intention is to directly connect to Bfscope using
446 Aquarium, which can interpret and visualize the trace log data directly on the
447 fly.
448
449 % ----------------
450 \chapter{Design and Implementation of the Analysis Tool Aquarium\label{sec:aquarium}}
451
452 \section{Design of Aquarium}
453
454 \subsection{Goals}
455
456 When we designed Aquarium we had several goals in mind, namely the following
457 ones:
458
459 \begin{enumerate}
460         \item Support for live tracing.
461         \item Support for different ways of input (e.g.~reading from file or
462                 receiving data over the network).
463         \item Being able to handle large trace log data.
464         \item Being extensible and easily customizable.
465         \item Aquarium must run on different operating systems.
466 \end{enumerate}
467
468 We decided to tackle the first three goals with the design of the architecture
469 of Aquarium, which we will discuss in Section \ref{sec:aquarium-architecture}.
470 The fourth goal also did influence the architecture on one hand, but also
471 led to the idea of making Aquarium scriptable, i.e.~to create an interface that
472 allows developers to add their own scripts to Aquarium. Since those scripts do
473 not work on the raw trace log data, but rather on already from Aquarium
474 interpreted data, it offers developers on one hand a more powerful means to
475 write scripts in a very easy way, and on the other hand the scripts are directly
476 integrated into the visualization of Aquarium, alleviating the need to write
477 visualization code for custom developer scripts. In Section \ref{sec:scripts} we
478 will discuss the different ways how Aquarium can be extended with scripts.
479
480 The fifth goal, i.e.~the goal that people should be able to run Aquarium on
481 different Operating Systems, such as Linux and Windows, arose from a shortcoming
482 in the old version of Aquarium -- namely that it was written in C\# and only
483 runs on Windows. To tackle this requirement we decided to implement our version
484 of Aquarium in Java, so that cross platform portability will certainly not
485 become an issue.
486
487 \subsection{Architecture\label{sec:aquarium-architecture}}
488
489 When you analyze trace log data with Aquarium, the main object is a
490 TracingSession object. Each trace log data is at runtime represented by exactly
491 one TracingSession object. Figure \ref{fig:classdiag-input} shows the most
492 important classes that are dealing with getting from trace log data to the
493 according TracingSession. A TracingSession is associated with a single event
494 provider, currently there are two different input ways implemented:
495
496 \begin{itemize}
497         \item Reading trace log data from a file, using a LogfileReader.
498         \item Reading trace log data directly from a Barrelfish machine, using a
499                 NetworkReader.
500 \end{itemize}
501
502 The actual interpretation of the trace log data is done using an EventParser;
503 EventParser objects are independent of the type of data source. Note that the
504 EventConfigurtion is the responsible for interpreting the JSON file that has
505 been generated during the build process of Barrelfish, based on the pleco file.
506
507 The trace log data gets interpreted to Events and Activities, that are stored in
508 the TracingSession object. Note that the flow of data is push based, i.e.~it is
509 the data source that actively creates new Events as soon as more data is
510 available, and pushes the Events to the TracingSession. Having an active data
511 source allows us to treat different types of data sources uniformly.
512
513 While Events are quite self explanatory, i.e.~they are the Aquarium
514 representation of the actual events in the trace log data, Activities are a new
515 concept that we introduced in Aquarium. An Activity is a sequence of Events,
516 that are grouped into a single activity. Activities are a typical constructs
517 that are needed when analyzing trace log data; an example for that is when
518 analyzing the network stack, the fact that memory has been allocated (a single
519 event) might not be very interesting, but the duration of the entire
520 construction of the packet (an Activity) is what is actually very interesting.
521 Thinking about Activities, it becomes immediately clear that the different types
522 of Activities must be flexibly definable. We achieved this by allowing
523 developers to create their own scripts that decode Activities. 
524
525 \begin{figure}[htb]
526         \includegraphics[width=1\textwidth]{images/classdiag-input.png}
527         \caption{UML class diagram showing the main classes that are concerned with
528                 dealing with input.}
529         \label{fig:classdiag-input}
530 \end{figure}
531
532 Let us now look at how events are processed once the TracingSession retrieves a new Event.
533 A class diagram illustrating the handling of Events and Activities can be seen
534 in Figure \ref{fig:classdiag-output}. A TracingSession stores both a list with
535 the Events that have been extracted from the trace log data, as a list with all
536 the activities that have been created based on those events. Once an Event is
537 received by the TracingSession, it notifies all registered EventHandlers to
538 handle the new Event. Such EventHandlers can either be UI elements, such as an
539 EventListUpdateHandler (an object being responsible to present a list of all
540 interpreted Events in the UI), or an ActivityDecoder. ActivityDecoders are
541 objects that create Activities, and one possibility for that is, as already
542 mentioned, to have external scripts which decode Activities. If an
543 ActivityDecoder creates a new Activity, this Activity will be added to the
544 TracingSession and all registered ActivityHandlers will receive it. As you can
545 see, the only module that is currently both receiving Events and Activities is
546 the GraphViewUpdateHandler, an object that is responsible for visualizing the
547 trace log data graphically.
548
549 When developing Aquarium, we initially planned to add a statistics module as
550 well. Due to a lack of time, we had to omit it in the end. Nevertheless from the
551 design it can be seen, that such a module could easily be added to Aquarium: It
552 would simply have to be an EventHandler and an ActivityHandler. Note that the
553 design with having the TracingSession at the core, we achieved that all handler
554 classes are always in a consistent state. For example if an activity is seen by
555 one handler, it is always also seen by all other handlers. This becomes
556 especially handy when considering the filtering functionality of Aquarium. In
557 Aquarium we added the functionality to filter out Events based on various
558 different criteria, ranging from the core on which the Event happened, over the
559 Subsystem type up to custom scripts that developers can write to create their
560 own filter. When a filter is applied, it is always applied on the
561 TracingSession, and not on e.g.~a UI element. With this globally applied
562 filtering mechanism a new Handler that is created to extend Aquarium would
563 immediately benefit from the filtering functionality, without having to take
564 care of it at all.
565
566 \begin{figure}[htb]
567         \includegraphics[width=1\textwidth]{images/classdiag-output.png}
568         \caption{UML class diagram showing the main classes that are concerned with
569         handling events and activities.}
570         \label{fig:classdiag-output}
571 \end{figure}
572
573 \section{Extending Aquarium with Scripts\label{sec:scripts}}
574
575 As mentioned in Section \ref{sec:aquarium-architecture}, it is possible to
576 extend the functionality of Aquarium by adding custom scripts. The scripts are
577 interpreted using the Java Scripting API, and currently JavaScript is the
578 language for which support in Aquarium has been implemented. Based on the Java
579 Scripting API support for other languages could be added.
580
581 \subsection{Script Filters}
582
583 Script filters are custom scripts that can be written by developers to filter
584 out events in which they are not interested. Aquarium itself already provides
585 the possibility to filter out events based on the following criteria:
586
587 \begin{itemize}
588         \item Filter out entire cores (e.g.~filter out core 1).
589         \item Filter out entire Subsystems (e.g.~filter out the \emph{kernel}
590                 Subsystem).
591         \item Filter out Events from a Subsystem (e.g.~filter out \emph{ALLOC}
592                 Events from the Subsystem \emph{memserv}).
593         \item Filter out trace events based on their application (e.g.~filter out
594                 all events that the application \emph{monitor} logged).
595 \end{itemize}
596
597 If a user is not satisfied with these possibilities to filter out events,
598 Aquarium can be extended with script filters. An example for a script filter
599 would be to filter out all events, except those that are an \emph{ALLOC} Event
600 initiated by the monitor. Such scripts allow users to quickly spot specific
601 events, even when they are analyzing large trace logs.
602
603 \subsection{Script Activities}
604
605 Another possibility to extend Aquarium with the help of scripts is to write
606 custom activity scripts. Such a script works in the following way: It receives
607 all events that exist in the trace log, in the order they exist in the trace log
608 itself, and based on these events it can create activities, and deliver them to
609 Aquarium. In Figure \ref{fig:classdiag-output} we can see that such a Script is
610 wrapped in a ScriptActivityDecoder inside of Aquarium, which is -- as just
611 described -- an EventHandler.
612
613 An example for an activity script could be to create an activity for  all the
614 \emph{MUTEX\_LOCK} and \emph{MUTEX\_UNLOCK} pairs -- in order to analyze the
615 locking behaviour. For each activity, certain parameters such as the duration of
616 each activity, is automatically calculated by Aquarium.
617
618 \section{Working with Aquarium}
619
620 In this section we briefly want to look at how some of the already described
621 functionality looks in Aquarium with the help of some examples. Figure
622 \ref{fig:aquarium} shows a screenshot displaying a single trace log data file opened in
623 Aquarium. The largest part of the GUI is used by the so called \emph{GraphView},
624 presenting the information contained in the log in a two dimensional manner.
625 From left to right we see the timestamps (measured in clock cycles), and on the
626 vertical axis we see the different cores.
627
628 For each core we show the actual events that have been traced, indicated using
629 black circles on the bar of the core. The color of the bar shows which
630 application was running on the core on that time, where the colors are shown as
631 well in the left menu labeled \emph{Filter}. In addition to the per core events,
632 arrows are drawn where messages have been sent between the cores, indicating
633 the send and receive event. As the messages have the potential to clutter up the
634 GUI quite a bit, the arrows can be hidden easily using the envelope button on
635 the right top corner.
636
637 Below the GraphView we see a list representation of the event data. With the
638 help of the \emph{sync} button (shown on the right top corner of the list), the
639 GraphView and the list can be linked, meaning that if you select an event in
640 either of the two, the other view scrolls to that event. Using this
641 functionality coarse navigation can be done using the GraphView, to then allow
642 for detailed analysis by quickly looking at the list.
643
644 On the left part of the GUI we see the Filter menu. It allows to filter out
645 events based on the different criteria, as already described. Scripts can be
646 added using the Scripts tab, and afterwards they will directly appear in the
647 Filter menu as well.
648
649 \begin{figure}[htb]
650         \includegraphics[width=1\textwidth]{images/aquarium.png}
651         \caption{Screenshot of Aquarium displaying one trace log file.}
652         \label{fig:aquarium}
653 \end{figure}
654
655 As we can see in the screenshot shown in Figure \ref{fig:aquarium-activities},
656 for all the objects in the GraphView exist tooltips, when you hover over the
657 according object with the mouse cursor. On this screenshot you can see that two
658 custom script activities have been added, and they have already been evaluated.
659 The created activities are integrated into the GraphView (on a per core basis)
660 as well as in the Activity tab next to the Events list on the bottom of a
661 Aquarium. All created activities can also be seen in a list fashion there.
662
663 \begin{figure}[htb]
664         \includegraphics[width=1\textwidth]{images/aquarium-activities.png}
665         \caption{Screenshot of Aquarium displaying two script activities, one for
666         mutex activities and one for the monitor application.}
667         \label{fig:aquarium-activities}
668 \end{figure}
669
670 In Figure \ref{fig:aquarium-filters} we activated several filters, thus compared
671 to what we saw in Figure \ref{fig:aquarium-activities}, the information
672 displayed in Aquarium has been reduced. We filtered out several things:
673
674 \begin{itemize}
675         \item The entire core 0.
676         \item The Event MUTEX\_UNLOCK.
677         \item The Subsystems for sending and receiving messages, hence the message
678                 arrows are filtered as a consequence as well.
679         \item Events belonging to the application spawnd.
680 \end{itemize}
681
682 You can see that using the filter mechanism, it is possible to quickly find the
683 part of the trace log data, that is interesting to you.
684
685 \begin{figure}[htb]
686         \includegraphics[width=1\textwidth]{images/aquarium-filters.png}
687         \caption{Screenshot of Aquarium where core 0 is filtered out, as well as
688         certain events and applications.}
689         \label{fig:aquarium-filters}
690 \end{figure}
691
692 \chapter{Usage}
693
694 This chapter describes how to use the Tracing framework in Barrelfish.
695
696 \begin{itemize}
697 \item Add trace events to \lstinline{trace_definitions/trace_defs.pleco}
698 \item Enable tracing in \lstinline{hake/Config.hs}
699 \item Add \lstinline{addLibraries = [ ``trace'' ],} to your Hakefile
700 \item Modify the source code of your programs as described in
701   Listing~\ref{lst:app_example}
702 \item Download and compile Aquarium2 as described in the README as
703   part of the source code
704 \end{itemize}
705
706 \begin{code}
707 \begin{lstlisting}[frame=single, caption={Enable tracing for an application}, label={lst:app_example}]
708 #include <trace/trace.h>
709
710 int main(..) {
711
712   // initialize the trace framework
713   trace_reset_all();
714   trace_prepare(..); // do clock synchronization
715
716   // tell the framework when to start recording
717   err = trace_control(TRACE_EVENT_XXX_AAA, TRACE_EVENT_XXX_BBB, _duration);
718
719   // enable the subsystems that should be traced
720   trace_set_subsys_enabled(TRACE_SUBSYS_XXX, true);
721   // or activate for all:
722   trace_set_all_subsys_enabled(true);
723
724   // fire the event that triggers start of recording
725   trace_event(TRACE_SUBSYS_XXX, TRACE_EVENT_XXX_AAA, _payload);
726
727   execute_something_useful();
728   
729   // fire the event that triggers end of recording
730   trace_event(TRACE_SUBSYS_XXX, TRACE_EVENT_XXX_BBB, _payload);
731
732   // Flush the buffer
733   trace_flush(MKCLOSURE(..));
734 }  
735 \end{lstlisting}
736 \end{code}
737
738 \section{Getting traces to Aquarium 2 over the network}
739
740 Assuming you have network hardware that works with Barrelfish you can also
741 connect Aquarium 2 directly to the tracing infrastructure inside Barrelfish. The
742 current default port for that is \verb!6666!.  If your Barrelfish and Aquarium 2
743 machines are on the same subnet you can just connect to the Barrelfish machine's
744 IP or host name from Aquarium 2.  Otherwise, if you have ssh access to a machine
745 that can talk to the Barrelfish machines you can use ssh port-forwarding to
746 connect Aquarium 2 to Barrelfish directly using the ssh invocation below.
747
748 \begin{code}
749 ssh -L 6666:<IP of Barrelfish machine>:6666 <ssh-machine>
750 \end{code}
751
752 \chapter{Performance Analysis}
753
754 \section{Introduction}
755
756 This chapter analyzes the performance of the tracing framework only inside of
757 Barrelfish. The analysis tool Aquarium is not analyzed for its performance, as
758 it is intended to run \emph{``offline''} in the sense that if it is fast enough
759 the consume the data on live mode from a Barrelfish machine, it is considered to
760 be fast enough. The impact on performance is also a lot bigger on the tracing
761 inside of Barrelfish; This stems from the fact that if you do not want to
762 analyze trace data, you simply do not start Aquarium, and if you want to analyze
763 data, you are willing to wait until the analysis is performed. Looking at the
764 tracing framework in Barrelfish, it is on one hand less easy to disable -- once
765 compiled into the system, a certain overhead will exist -- and on the other hand
766 it is important that the tracing does not affect measured code too heavily, or
767 it will become useless.
768
769 \section{Memory Overhead}
770
771 The memory overhead for buffers inside the tracing framework is constant during
772 the entire runtime of Barrelfish, as the only used buffers are allocated at
773 startup of the system. The used buffer space currently consists of two main
774 parts that exist for each core:
775
776 \begin{description}
777         \item[Application Buffer] Up to 128 currently running applications can be
778                 stored per core.
779         \item[Event Buffer] Up to 8000 Events can be stored per core, where
780                 ringbuffer containing these events is cleared during a flush process.
781 \end{description}
782
783 To store an event or an application 16 bytes are used. As the tracing framework
784 works independently of the actual number of cores, the number of cores is
785 bounded assuming a limit of 64 cores. This leads to the following memory usage:
786
787 \begin{equation}
788         M = (128 + 8000) * 16 \textrm{B} * 64 = 8323072 \approx 8 \textrm{MB}
789 \end{equation}
790
791 In addition to those buffers, a handful of pointers are stored, which in total
792 use less than 1 KB of memory. Therefore that the total amount of memory that the
793 tracing framework uses is 8 MB, which does not vary over time.
794
795 \section{Execution Time Overhead}
796
797 \subsection{Cost to Trace a Single Event}
798
799 We benchmarked the number of cycles that it takes to trace a single event in the
800 tracing framework. We tested both the case where the Subsystem is enabled,
801 i.e.~we are interested in the event for which the \texttt{trace\_event} function
802 is called, and the case where we are not interested in the even that is traced,
803 i.e.~the Subsystem is disabled. The \emph{``enabled''} case is straightforward
804 to benchmark, but we also think the \emph{``disabled''} case is interesting, as
805 it might be often the case that code is instrumented with a lot
806 \texttt{trace\_event} calls, even though you are currently not interesting in
807 analyzing this part of the code. Since we added the functionality do dynamically
808 disable the appropriate Subsytems, it is also important to know by what degree
809 the execution of the code will be slower, compared to removing the statement
810 from the actual code.
811
812 The results of the benchmark can be seen in Figure \ref{fig:boxplot}. The
813 benchmark shows that on the machine \texttt{nos5}, the average number of cycles
814 that it takes to trace an event, when the Subsystem is enabled is 40.384. The
815 average number of cycles for a call, when the Subsystem is disabled is 9.950.
816
817 It can be seen that both benchmarks returned very stable results - there are a
818 few outliers, but the vast majority of the events are closely around the
819 average. Both benchmarks have been run twice with 1000 measurements each run.
820
821 \begin{figure}[htb]
822         \includegraphics[width=1\textwidth]{images/boxplot.pdf}
823         \caption{Boxplots showing the number of cycles that it takes to trace a
824         single event. On the left: The Subsystem is enabled, i.e.~the event is
825 stored in the buffer. On the right: The Subsystem is disabled, i.e.~the event is
826 not stored in the buffer.}
827         \label{fig:boxplot}
828 \end{figure}
829
830 \subsection{Cost to Flush}
831
832 The cost to flush the collected trace data can vary a lot depending on the
833 destination onto which is flushed: Directly on the console, using Bfscope to
834 send it over the network, etc. As the tracing framework is not intended to be
835 used in a way where flushing is performed during a measurement, but afterwards,
836 we did not do measurements for the different flushing methods. We only want to
837 mention that flushing, especially over the network, is not to be considered a
838 lightweight operation that can be done at any time during your code, without
839 potentially affecting the outcome of the tracing heavily.
840
841 % vim:set spell spelllang=en_us tw=80:
842
843
844
845 \end{document}