How to process DINAMITE binary traces02 Dec 2016
In this post, we explain how to obtain a high-level summary of the execution using DINAMITE trace analysis tools.
After compiling WiredTiger with DINAMITE we ran it with the LevelDB dbbench workload called
This workload sequentially iterates over the btree. After obtaining the traces
we went over the following sequence of steps to visualize the execution.
Note: These instructions assume that you have obtained the traces using the
fastfunc instrumentation library. See our post on installing
to make sure you chose the right library.
Download the binary trace toolkit, which contains loads of useful scripts for processing and visualizing the traces, and build it:
% git clone https://github.com/dinamite-toolkit/dinamite-binary-trace-parser.git % cd dinamite-binary-trace-parser % INST_LIB=$LLVM_SOURCE/projects/dinamite/library make
After you successfully compile the trace parser, set an environment variable that will point to its location. This variable will be used later by the trace processing script:
To make sure the variable sticks around, add the directive to your shell resource
file, such as
For convenience, put the traces as well as all the
map_*files generated during the DINAMITE compilation into the working directory, where you will process the traces. Assuming your traces were placed into
/tmpand you compiled the program in
$BUILD_DIRdirectory, this will do the trick:
% mv /tmp/trace.bin.* . % cp $BUILD_DIR/map_* .
DINAMITE generates a trace file per thread, so you will have as many
trace.bin.*files as there were threads during your execution. The files will be numbered sequentially. These numbers are generated by the logging library in the order that threads invoke the library (i.e., the first thread that calls the instrumentation library will get the id of ‘1’, the second thread will get the id of ‘2’, etc.). They have nothing to do with
pthreadthread ids or with application-specific thread ids.
Now you will need to run a Python script located in the DINAMITE binary trace parser, which you downloaded in Step 1. This script needs to know where the binary trace toolkit lives, so you need to set the environment variable
$DINAMITE_BINTRACE_TOOLKITto indicate its location as you invoke the script:
% $DINAMITE_BINTRACE_TOOLKIT=/home/dinamite-binary-trace-parser % $DINAMITE_BINTRACE_TOOLKIT/process-logs.py trace.bin.*
Now sit back and relax or go get a coffee while the files are being processed. This might take a while depending on your traces sizes.
By default, the decoded traces will be put into a single giant file
trace.sql. This file has an SQL extension, because in addition to having all the trace records in human readable format, it contains commands allowing you to import this data into a SQL database and query it from there. The database is needed in order to integrate with our tools for visual analysis of the traces – there is another blog post on that. The
trace.sqlfile will have data in the following format:
|id||direction||function name||thread id||timestamp||duration|
id is the internally computed id for a function invocation. A function entry record will have the same id as its matching exit record.
direction is a binary variable that is equal to ‘0’ if a record corresponds to the function entry, and ‘1’ if it corresponds to the function exit.
function name is the name of the function. C++ function names may be shortened by our trace-parsing script, because they may be very long (with class names chained together) and ugly to look at. If a function kept track of its argument values the values would be concatenated with the function name and separated by a “::”.
thread id is the DINAMITE-generated thread ID. It is not the same as the ID assigned to the thread by the thread library or by the operating system.
timestamp is the timestamp. We use the x86
rdtscinstruction to obtain it. We used to use
clock_gettimeon Linux, but that generated a tremendous amount of overhead for CPU-intensive workloads. So what you are getting as a timestamp is measured in terms of CPU cycles. We currently do not perform a conversion.
duration is the duration of the function invocation measured in the same time units as the timestamp: CPU cycles.
Instead of the
trace.sql file, you can the script to create a single
plain text file for each binary file by giving it a
-t argument. In
that case, for each binary
trace.bin.* file there will be a
trace.bin.*.txt. The contents of the text file will
look kind of like this:
--> __wt_btcur_next 2 334888040634441 <-- __wt_btcur_next 2 334890966319815
The “–>” or “<–” arrows at the beginning of the line indicate whether this is the timestamp for entering or exiting the function: “–>” is for entering, “<–” is for exiting. The next word is the function name. The number after that is the thread id (redundant with thread id embedded in the name of the file). The huge number following the thread id is the timestamp.
In addition to the text traces, you will also have
trade.bin.*.summary.csv for each trace file.
Summary files tell you what functions were executed by
the corresponding thread, how many times each function was called, and how
much time it took to execute on average and in total. The text and csv files
carry equivalent information, but the latter are easier to parse.
But the best part is the visual summary of the traces, which can be
found in the
HTML directory – created in the same directory
where you processed the traces. Just open
HTML/index.html in your
browser. Our nextpost
shows examples of visual diagrams you will see and explains how to