y-graphs

is a performance analysis tool, based on trivial macros. It reports wall-clock time spent in functions and arbitrary sections of code defined by “checkpoints”.

Performance analysis with y-graphs

Generally, analysis with ygraphs goes somehow like this:

1. Add appropriate macros to interesting parts of your code
2. Run your macroized program, collecting output from macros
3. Use logs to generate suitable output (graphs or text)

Details follow.

Macros

There are 3 main macros defined in apperf.h header:

• ENTER - should be placed at the beginning of functions you want to monitor
• LEAVE - should be placed before each return from those functions (inc. implicit return from void functions)
• CP - “checkpoint”, place this macro in interesting points within the function

And here comes example:

double Entry::updateIsKnown()
{
        int i;
        int ct = 0;
        for (i=responses.size()-1; i > responses.size()-3 && i >= 0; i--) {
                if (responses.at(i) > 0) {
                        ct += 1;
                } else {
                        return 0;
                }
        }
        return ct/2.0;
}

Should be rewritten as:

double Entry::updateIsKnown()
{ENTER 
        int i;
        int ct = 0;
        for (i=responses.size()-1; i > responses.size()-3 && i >= 0; i--) {
                if (responses.at(i) > 0) {
                        ct += 1;
                } else {
                        LEAVE return 0;
                }
        }
        LEAVE return ct/2.0; //this is not exactly right, but who cares :)
}

Running your program

You just need to catch stderr of your program to some file. Stderr output of you program does not need to be clean (with timestamps only) - you can also print out your own debug messages to strerr. Ygraphs will find correct timestamps in your output.

If you can’t redirect the stderr when you start your program, place an INIT macro as first instruction in your “main” function. It will redirect your stderr to /tmp/clm.PID.log file.

Analysis

Your logs can be used by 4 different tools:

• print_events.rb - will show you (in textual format) what happened in your program. When it entered some function, when it reached some checkpoints, and so on. It will give you nice - readable - time differences between relevant events. (so you don’t have to subtract timestamps)

  cat your.logs | ruby print_events.rb

• print_paths.rb - will show you general statistics for all the paths taken by your program, and all macroized functions. It tells you about the total time spend on execution of each function (or path), number of times this function (or path) was executed, average time, and the worst time.

  cat your.logs | ruby print_paths.rb

• graph_cumulative.rb - shows the same thing as print_paths as a graph. More precisely, it generates input for graphviz tools (dot).

  cat your.logs | ruby graph_cumulative.rb | dot -Tpng -omy_cumulative_graph.png

• graph_timeline.rb - shows the same thing as print_events as a graph. These graphs look really cool. (check them out in examples section)

  cat yout.logs | ruby graph_timeline.rb -o my_timeline_graph.png

Example output

Some time ago I’ve written small Flash Cards program for Maemo platform. After adding some nice features it started to act very slowly. I’ve made an analysis with y-graphs. Then optimized the code. Then analyzed again. Below you can see 2 graphs generated before and after optimization. For example, take a look at clickedOk function. Before optimization it took 73ms per call, and after optimization only 46ms.