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