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