How to process DINAMITE binary traces

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 readseq. 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 DINAMITE to make sure you chose the right library.

1. 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
   

2. 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:

   % DINAMITE_TRACE_PARSER="dinamite-binary-trace-parser-directory/trace_parser"
   

To make sure the variable sticks around, add the directive to your shell resource file, such as .bashrc.

1. 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 /tmp and you compiled the program in $BUILD_DIR directory, 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 pthread thread ids or with application-specific thread ids.

2. 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_TOOLKIT to 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.

3. 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.sql file will have data in the following format:

• 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 rdtsc instruction to obtain it. We used to use clock_gettime on 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 corresponding 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 trace.bin.*.summary.txt and 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 interpret them.