
README for the Call-tree Patch to Cachegrind
============================================

Cachegrind-CT Version 0.2a
(C) Josef Weidendorfer

CONTENT

1. Why this patch?
2. Usage and additional options of Cachegrind-CT
3. Trace format and extensions
4. Change Log
5. Benchmarks
6. Technical details



1. Why this patch?
---------------------------------------------------------------------

Pure Cachegrind allows you to get a profile of your program
by logging some events while running your program on a simulated
CPU. It detects the events on instrumentation granularity and sums them
up at source line granularity (by using the debug info of the program).
This is dumped out after profiling into a trace file "cachegrind.out".

The postprocessing script vg_annotate sums the event counts up again
to get function granularity. You get the "self" cost of each function
for functions with debug info annotated source with costs per source line.

The call tree patch, called Cachegrind-CT in this README,
adds logging of the calls happening in your program.
For each call happening, it logs from/to instruction address, the number
of calls happening and the amount of events passing by while running a call.
The call instruction addresses are translated to source positions and
the call tree data is dumped to the trace file, too.

Note that the cost of recursive calls has to be ignored when summing
up call costs of a function. Recursive calls are distinguished from
normal ones, and we log costs happening at first recursion level.
Note that these cost are NOT really useful.

This enables postprocessing tools, e.g. vg_annoate (patched for that)
or KCachegrind, to give you cumulative costs of all functions, i.e.
how much cost was spent in a function inclusive all functions called.
Also, you get a list of all functions called from another function,
together with a call count and cost spent inside of each call.



2. Usage and additional options of Cachegrind-CT
---------------------------------------------------------------------

You start profiling as normal with

  cachegrind <executable>

The produced trace file is called "cachegrind.out.<pid>" by default
where <pid> is the Process ID of the profile run. This way, for processes
forking childs, you get a trace file for each child.

Additional, you can let Cachegrind-CT dump a trace file while the profiling is
running. The generated trace files are named "cachegrind.out.<pid>.<partno>".
Here, <partno> is a number starting from 1 and being incremented for each
dump. The dump at program termination is named as above without ".<partno>".

To complete trace file naming, there is an option to dump separate trace
files for each thread in a multi-threaded program. To the trace file name,
a "-<tid>" is added. <tid> is the Tread ID starting at 1.
So the trace file name for the first thread of a dump forced while running
Cachegrind-CT is "cachegrind.<pid>.1-1". Note that in fact, leading zero
digits are added to the part and thread number for correct lexicographical
ordering.

Note that vg_annotate only can load one trace file at once. To get summed
values for more trace parts, concatenate the trace files into one file
and load this one.
Note that KCachegrind does automatic loading of all trace parts of one
program run when giving the base name "cachegrind.out.<pid>".

Additional options of the call-tree patch:

 --call-tree=no|yes [default: yes]
   
   You can switch off the call tree functionality with "no".
   This way, no additional instrumentation of the code for the
   simulated CPU is done, and the added logging doesn't happen.
   Note however that this does not disable the other additions of the
   call tree patch like extended trace file naming, trace file
   compression and the possibility to create separated trace per thread.

   As most additional code of Cachegrind-CT is avoided when disabling
   call tree logging, profiling the original cachegrind way is
   still possible if call tree logging should happen to be buggy
   for you.

 --dump-threads=no|yes [default: no]

   If switched on, Cachegrind-CT produces separate traces per thread
   when running a multi-threaded program. The naming of trace files
   is explained above.

 --compress-strings=no|yes [default: yes]

   The strings to appear in the trace file can be very long
   (e.g. a source file name with absolute path, or demangled C++ symbols).
   With the call tree patch, the same string can appear multiple times
   in the trace file. The compression gives each string a unique ID and
   writes the string only the first time, using the ID for further
   reference. To allow humans to read trace files, this compression
   mechanism can be turned off.
   Note that original Cachegrind wrote out a line for each instruction
   of your program. The patch automatically adds events for the same
   source line and writes these sums. This behaviour can't be switched
   off . But together with string compression, trace files produced by
   Cachegrind-CT are a lot smaller even with call tree information than
   the trace files of original Cachegrind.

 --dumps=<count> [default: 0 = never]

   Cachegrind-CT can dump traces while running. Using this option, there
   will happen a dump after each execution of <count> basic blocks of
   your program. A basic block is a run of non-branching, non-jumping
   instructions.
   Note that Cachegrind typically runs 100 000 basic blocks without
   checking for a needed dump. Thus, <count> should be more than this.
   Trace file naming for dumps while running is explained above.

 --dumpat=<function> [default: never]

   You can also give Cachegrind-CT a function name prefix. Each time
   when entering a function having a symbol starting with <function>,
   a dump is made before. The prefix way is choosen because of the
   long C++ symbols which include argument types.

There also is an interactive way of forcing a trace dump while running
the profile: In the current working directory of the running profile,
create the file "cachegrind.cmd".
If the profiled program is awake, it regularly checks for existance if
this file and triggers a dump. After dumping, Cachegrind-CT deletes
the file "cachegrind.cmd". This way you can see when the dump is finished.

Note: In future versions, "cachegrind.cmd" will be used to control a
running profile run even further, e.g. for interactive adding / deleting
dump-breakpoints.

If you wonder: The way of using a command file "cachegrind.cmd" is the
most portable way to communicate with Cachegrind-CT, as it does not
need an opened file descriptor like other ways (pipe/socket/...).



3. Trace format and extensions
---------------------------------------------------------------------

The header has an arbitrary number of lines of the format
"<key>: <value>". Afterwards, position specifications
"<spec>=<position>" and cost lines starting with a source line
number and space separated cost numbers can appear.
Empty lines are always allowed.

Possible <key> values for the header:

 "version:" [Cachegrind-CT]

   This is used to distinuish future trace file formats.
   It's optional; if not appearing, original Cachegrind 1.0.x format
   as supposed. Otherwise, this has to be the first header line.

 "trigger:" [Cachegrind-CT]

   The <value> states the reason of why this trace was generated.
   E.g. program termination or forced interactive dump. At most once.

 "timeframe (BB):" [Cachegrind-CT]

   This roughly states the execution time this trace covers, in terms
   of executed basic blocks. At most once.

 "desc:" [original Cachegrind]

   Descriptions of some architecural properties of the target machine.
   Several lines with arbitrary string values are allowed.
   This is e.g. used for simulated cache sizes.

 "cmd:" [original Cachegrind]

   The name of the profiled program with arguments. Exactly once.

 "events:" [original Cachegrind]

   A list of short names of the event types logged in this file.
   The order is the same as in cost lines. The first event type
   is the second number in a cost line, as the first is the source line.
   Cachegrind-CT does not add additional cost types. Exactly once.
   Cost types from Cachegrind 1.0.x are
    Ir   Instruction read access
    I1mr Instruction Level 1 read cache miss
    I2mr Instruction Level 2 read cache miss
    ...

 "summary:" [Cachegrind-CT]
 "totals:"  [original Cachegrind]

   The <value> or the total number of events covered by this trace file.
   Both keys have the same meaning, but the "totals:" line happens
   to be at the end of the file, while "summary:" appears in the header.
   This was added to allow postprocessing tools to know in advance to total
   cost. The two lines always give the same cost counts. 


The value for position specifications are arbitrary strings.
When starting with "(" and a digit, it's a string in compressed format.
Otherwise it's the real position string. This allows for file and
symbol names as position strings, as these never start with "(" + <digit>.
The compressed format is either "(" <number> ")" <space> <position>
or only "(" <number> ")". The first relates <position> to <number> in
the context of the given format specification from this line to the end
of the file; it makes the (<number>) an alias for <position>.
Compressed format is always optional.
Position specifications allowed:

 "ob=" [Cachegrind-CT]

   The ELF object where the cost of next cost lines happens.

 "fl=" [original Cachegrind]
 "fi=" [original Cachegrind]
 "fe=" [original Cachegrind]

   The source file including the code which is responsible for
   the cost of next cost lines. "fi="/"fe=" is used when the source
   file changes inside of a function, i.e. for inlined code.

 "fn=" [original Cachegrind]

   The name of the function where the cost of next cost lines happens.

 "cob=" [Cachegrind-CT]

   The ELF object of the target of the next call cost lines.
   
 "cfl=" [Cachegrind-CT]

   The source file including the code of the target of the
   next call cost lines.
   
 "cfn=" [Cachegrind-CT]

   The name of the target function of the next call cost lines.

 "calls=" [Cachegrind-CT]

   The number of nonrecursive calls which are responsible for the cost
   specified by the next call cost line. This is the cost spent inside
   of the called function.

 "rcalls=" [Cachegrind-CT]

   The number of recursive calls which are responsible for the cost
   specified by the next call cost line. This is the cost spent inside
   of the called function. The cost comes from the first recursive call
   of the source position in the cost line only.
  
After "calls=" and "rcalls" there MUST be a cost line. This is the cost
spent in the called function. The first number is the source line from
where the call happened.




4. Change Log
---------------------------------------------------------------------

14.9.02
0.2a for Valgrind 1.0.2

  * Improved multi-thread support. There's much less slowdown for single
    threaded programs while allowing multi-threading.
  * Option "--dump-threads=no|yes" added.
    Allows separate trace file generation per thread in multi-threaded
    programs. Default is one trace file for costs of all threads.
  * Added documentation in README.calltree:
    All about usage, additional options, trace format extension,
    some benchmark results and technical details on the patch.

11.9.02
0.2 for Valgrind 1.0.2

  Version 0.2 supports multi-threaded programs now.
  Unfortunately there's some overhead (10%) even for single-threaded
  programs at the moment, and the version is possible not very stable.
  So use 0.1e if you don't need it. For thread traces, the filename has
  appended "-tid" for costs in thread tid. 

10.9.02
0.1e for Valgrind 1.0.2

  * Bugfix for Segfault with indirect jumps in client code 
  * Bugfix for correct dumping of inlined functions

9.9.02
0.1d for Valgrind 1.0.2

  * Option --calltree=no to disable call-tracing.
    Needed to disable call-tree tracing for multithreaded programs,
    as that's not working at the moment. You get the original cachegrind
    behaviour (aside from compressed output).
  * Option --compress-strings=no to disable string compression in trace
    dumps. This produces more human readable trace output. 
  * Atomic generation of trace part files. This is done by dumping to
    ".file" and renaming to "file" afterwards. 

6.9.02
0.1c for Valgrind 1.0.1

  * Failed assertions fixed (unmapping/CC type check) 
  * vg_annotate can now load the traces 

4.9.02
0.1b for Valgrind 1.0.1

  * Hopefully no malformed patch... 
  * Option --cachedumps= renamed to --dumps= 
  * Option --dumpat=function added to dump at function entry 
  * Immediate dump forcable with "touch cachegrind.cmd" in cwd of
    a running cachegrind (the program must be running, not sleep!) 
  * Creates traces with names 'cachegrind.out.pid.part' 
  * Writes compressed traces (70% smaller than original cachegrind) 

28.8.02
0.1 for Valgrind 1.0.1

  * Initial publication.



5. Benchmarks
---------------------------------------------------------------------

This gives you a feeling of the overhead of Cachegrind-CT.
The runs are done on a Athlon 1.3 GHz and only reproducable on the
authors machine with KDE 3.1 beta 1 at the time of this writing :-).

Legend:
 Instr - Instruction Accesses
 Calls - Non-recursive calls
 BBCCs - Number of allocated BBCCs = number of instrumented BBs
 TS    - Size of generated trace data file in MB
 Time  - User time in seconds (RT = real time)

           Instr/Calls/BBCCs  TS (1.0.2/CT)  Time (RT/1.0.2/CT 0.1e/0.2/0.2a)

xclock     6.7M / 96K  / 14K   0.89 / 0.25   0.01 / 1.56 / 1.67 / 1.81 / 1.73
qtconfig   274M / 6.9M / 59K   4.9  / 1.7    0.49 / 33.0 / 40.5 / 49.6 / 43.5
konqueror  462M / 9.2M /108K   8.8  / 3.4    1.20 / 62.7 / 76.0 / 106  / 83.3
designer   459M /10.1M / 84K   5.6  / 2.0    0.90 / 52.5 / 63.5 / 81.5 / 68.9

The additional overhead from CT 0.1x to 0.2x comes because of
the multi-thread support (separation of CallEntry/Alias hashes, additional
helper call at beginning of each BB -- see below). You can compile
V 0.2a without thread support by changing SUPPORT_THREADS to 0 at
start of vg_cachesim.c: The time then is 42.6s for qtconfig. Still higher
than V 0.1e (40.5s) because of mentioned hash separation... :-(




6. Technical details
---------------------------------------------------------------------

If you don't know the internals of Valgrind and Cachegrind, you will
NOT understand the information written here. Please read the
technical details section in the documentation of Valgrind first!

- Instrumentation and added helpers

  Code for a CALL and RET instructions gets a call to the log_call/log_ret
  helpers added. The cost center of CALL instructions is extended to allow
  for a pointer to a JCC (Jump Cost Center). This points to the linked
  list of JCCs for calls from this instruction.  

  In log_call, for every target address of the call, a JCC struct is
  allocated. It holds call counts and cumulative costs for non-recursive
  and recursive calls. There exists a counter array for all events.
  The original cache log helpers are modified to not only update the
  instruction cost centers, but also this counter array.
  On call, a snapshot is made of this array, on return, the difference
  of the current array to the old snapshot is added as cost the the call.
  
- Recursion detection

  We keep our own call stack as a resizable array of JCC pointers.
  It's kept in sync with real stack by using the value of ESP.
  This way additional RET instructions or other strange stack
  modifications not concerning function calls can be handled.

  For each call to a function, a CallEntry is allocated, holding a
  recursion counter. CallEntries are kept in a hash table, keyed by the
  call target address, to allow for fast lookup when a call happens.
  Then the recursion counter is incremented and we can detect recursions.
  On return, the recursion counter is decremented again.

- Symbol resolution trapping and function aliases

  Calls to functions in shared libraries are in reality calls to stubs
  in the own ELF object. This stub first does an indirect call to the
  symbol resolution function in the runtime linker.
  After resolution, the jump address of the stub is corrected.  
  It's observed behaviour of glibc/binutils on Linux that the jump from
  the symbol resolution to the real function is done by a PUSH/RET
  construct. This can be trapped as our log_ret helper is called on the
  RET instruction, but we detect that there was no fitting CALL before.

  The stub address is made an alias for the real function. This way,
  at the next call to the stub, we know that it's in reality a call
  to the library function and can find its CallEntry using the alias
  record. Thus, recursion detection for calls to lib functions,
  called from different ELF objects (and thus, calling different stubs)
  is possible.
  For the trace, a call to symbol resolution with jump to the real
  function is emulated as being 2 calls, one the the resolution, the
  other to the function. That's needed for correct trace info,
  as we have no meaning of logging jumps in the trace.

- Relating cost centers to (function names/source file/ELF object)

  Before first execution of a basic block its instrumentation happens.
  A BBCC struct (basic block cost center) is allocated for each BB.
  It holds an array of simple cost centers for each instruction in the
  basic block.
  The BBCC must be accessable at dump time to write out the costs.
  As in the trace the function name and source position should appear
  if possible, there exists a access path to each BBCC:
  For each BB, we look up debug info and use this to construct a
  hierarchy of hash tables: The 1st keyed by ELF object name,
  pointing to obj_node structs. These are in fact hash tables keyed
  by source file name, to file_node structs. Again, these are hash
  tables keyed by function names to fn_node structs. And these are
  hash tables keyed by BB start address to the BBCCs.
  When there is no debug info, we look at our call stack and put
  the BBCC to the fn_node of the BB target of the last call, i.e.
  the first BB of the actual function. If there is none, we
  construct a name from the address "0x<hexaddress>".
  On dump time, we iterate through the hash tables: We get automatically
  grouping of all costs of same ELF object, and so on, which holds
  trace file size low.
  For other purposes (e.g. BB discarding on library unloading), all
  BBCCs are in a huge resizable hash table keyed by start address only.
  It's important to understand that be can "move" BBs to other source
  positions by putting BBCCs from one fn_node to another.
  This is used in Symbol resolution trapping: The BBs of the stub are
  moved to the BBs of the real function. Or its used when detecting that
  the first BBs of a function have no debug info but the later.


- Multi-threading support

  We have to distinguish 2 modes for multi-threading. Dumping separate
  per thread (S) or not. All call information has to be kept per thread:
  This is stored in our call stack, in the CallEntry's + hash, the JCCs
  and the event counter array.
  When (S) is activated, we also need per thread
  version of the cost centers (BBCCs) and the hash table hierarchy holding
  the BBCCs to allow for easy dumping by gooing the the per thread hash
  table hierarchies.
  Alway globally used is the alias hash (only one thread does resolution,
  and others need to know about the alias) and the huge BBCC hash table
  keyed by BB address (and also keyed by TID in the (S) case, as we have
  per thread BBCCs).

  All per thread data structures are accessed using global pointers.
  On a thread switch, these pointers are changed (We don't need to
  change to whole code because of multi-thread support).
  The per-thread BBCCs is more difficult, as the instrumentation to
  the cache log funtions insert absolute addresses to the instruction
  cost centers. For each BB, the per-thread BBCCs are in fact the same
  aside from event counters (size, offsets). Only the BBCC start address
  changes. Therefore, in the (S) case, we add a call to a new setup helper
  at the beginning of each BB, giving the start address of the BBCC
  created at instrumenation time. This BBCC gets the TID at this time.
  The helper checks if the current TID is the same as the one in the
  BBCC is points to. If yes, nothing has to be done (we set a diff variable
  to 0). If no, the helper looks up if there already exists a BBCC for this
  BB and current TID. If not, it clones the BBCC by copying it but setting
  event counters to 0 and current TID. It then sets the diff variable to
  be the address difference of the original BBCC to the needed one.
  And the first thing all cache log helpers do is adding this diff to their
  cost center pointer, and the have to correct cost center address!
  


  
