libtraceio

A library for tracing I/O system calls and function call graph

Usage

1. (Optional but recommended) Add the following flags to the compiler's command line:

   -finstrument-functions \
   -finstrument-functions-exclude-file-list=/usr/include \
   -rdynamic -g
   

   What are these flags and why are they optional?

   • When the flag -finstrument-functions is set, compiler generates calls to __cyg_profile_func_enter on function enter and __cyg_profile_func_exit on function exit for all functions (including inlined ones).

     The signatures of the two instrumentation functions are shown below:

     void __cyg_profile_func_enter(void *this_fn, void *call_site);
     void __cyg_profile_func_exit(void *this_fn, void *call_site);

     The two arguments are the address of the function being called and the address of the call site.

     Our library implements these functions to gather the function call trace and generate the backtrace for I/O system calls. If the flag is not set, then our library cannot gather the call trace (i.e., TRACE_TRACE_FN=1 will have no effect). The backtrace can still be generated using backtrace(3). Since backtrace generates trace using the stack frame, some functions (i.e., inlined functions) might not be shown due to omission of the frame pointers (See -fomit-frame-pointer enabled at -O1 and higher.).

   • The -finstrument-functions-exclude-file-list flag specifies a list of files to exclude from the instrumentation. If the flag is not set, then the call traces for all files are generated, including those in the standard library. For example, a single construction and destruction of std::string can generate 70 lines of call trace.

   • The -Wl,--export-dynamic flag adds all symbols to the dynamic symbol table in the .dynsym section.

     For function name resolution, given a function address, we use first dladdr(3) to obtain the function name if it is present in the dynamic symbol table. This method does not work for static functions, since they are not exported by the flag. If verbose mode is enabled ( i.e., TRACE_VERBOSE_FN=1 or TRACE_VERBOSE_IO=1), then we also use libbfd to obtain the function name, source file name, and line number by reading the ELF file.

     If the flag is not set and/or verbosity is not enabled, then you may see lines like 0x11a0 in trace_basic in the trace output. One can manually use nm to resolve the function name:

     nm -C trace_basic | grep 11a0 # prints `00000000000011a0 T main`

   • The -g flag enables the generation of debugging information, so that the source file and line number can be obtained.

2. Run your program with libtraceio.so loaded.

Example

Compile sample/basic.cpp and run it with libtraceio.so:

g++ sample/basic.cpp -g -O3 -finstrument-functions -finstrument-functions-exclude-file-list=/usr/include -rdynamic
make # compile libtraceio.so
TRACE_FN_VERBOSITY=3 LD_PRELOAD=./build/libtraceio.so ./a.out

Output:

> main(...) in /home/szhong/IOTrace/sample/basic.cpp:18
 > some_namespace::inline_fn() in /home/szhong/IOTrace/sample/basic.cpp:15
  > some_namespace::static_fn(int, int) in /home/szhong/IOTrace/sample/basic.cpp:11
   > some_namespace::io_fn(char const*) in /home/szhong/IOTrace/sample/basic.cpp:5
    > open("/dev/null", 0) = 4 in 6606ns
     = backtraces:
     = [3] some_namespace::io_fn(char const*) in /home/szhong/IOTrace/sample/basic.cpp:5
     = [2] some_namespace::static_fn(int, int) in /home/szhong/IOTrace/sample/basic.cpp:11
     = [1] some_namespace::inline_fn() in /home/szhong/IOTrace/sample/basic.cpp:15
     = [0] main(...) in /home/szhong/IOTrace/sample/basic.cpp:18
    < open(...)
    > read(4, 0x7ffcce260f10, 0) = 0 in 308ns
     = backtraces:
     = [3] some_namespace::io_fn(char const*) in /home/szhong/IOTrace/sample/basic.cpp:5
     = [2] some_namespace::static_fn(int, int) in /home/szhong/IOTrace/sample/basic.cpp:11
     = [1] some_namespace::inline_fn() in /home/szhong/IOTrace/sample/basic.cpp:15
     = [0] main(...) in /home/szhong/IOTrace/sample/basic.cpp:18
    < read(...)
    > close(4) = 0 in 1176ns
     = backtraces:
     = [3] some_namespace::io_fn(char const*) in /home/szhong/IOTrace/sample/basic.cpp:5
     = [2] some_namespace::static_fn(int, int) in /home/szhong/IOTrace/sample/basic.cpp:11
     = [1] some_namespace::inline_fn() in /home/szhong/IOTrace/sample/basic.cpp:15
     = [0] main(...) in /home/szhong/IOTrace/sample/basic.cpp:18
    < close(...)
   < some_namespace::io_fn(char const*) in /home/szhong/IOTrace/sample/basic.cpp:5
  < some_namespace::static_fn(int, int) in /home/szhong/IOTrace/sample/basic.cpp:11
 < some_namespace::inline_fn() in /home/szhong/IOTrace/sample/basic.cpp:15
< main(...) in /home/szhong/IOTrace/sample/basic.cpp:18

Sample Traces

• LevelDB basic: put a single value into the database, get it back, and delete it.

  • Source code: sample/leveldb.cpp

  • I/O trace: traces/leveldb-io.txt

  • Full trace: traces/leveldb-full.txt

  make trace_leveldb
  TRACE_FN_VERBOSITY=0 TRACE_LOG_FILE=traces/leveldb-io.txt ./build/sample/trace_leveldb
  TRACE_FN_VERBOSITY=2 TRACE_LOG_FILE=traces/leveldb-full.txt ./build/sample/trace_leveldb

• LevelDB benchmark

  • Source code: leveldb/benchmarks/db_bench.cc

  • I/O trace: traces/leveldb_bench.txt

  make db_bench
  TRACE_FN_VERBOSITY=0 TRACE_LOG_FILE=traces/leveldb_bench.txt build/_deps/leveldb-build/db_bench --num=100

• SQLite

  • Source code: sample/sqlite.cpp

  • I/O trace: traces/sqlite-io.txt

  • Full trace: traces/sqlite-full.txt

  make trace_sqlite
  TRACE_FN_VERBOSITY=0 TRACE_LOG_FILE=traces/sqlite-io.txt ./build/sample/trace_sqlite
  TRACE_FN_VERBOSITY=2 TRACE_LOG_FILE=traces/sqlite-full.txt ./build/sample/trace_sqlite