DbgProfiler - Example:


The code for the following example can be found in "./tests/linux/example.cpp" or "./tests/win32/example.cpp"
void foo(int i)
{
dummy();
bar(i)
}

void bar(int i)
{
if(i<1) {
dummy();
return;
}
bar(i-1);
}

void dummy()
{
usleep(1000*100);
}

int main()
{
for(int i=0; i<10; ++i)
foo(2);

    bar(5);
dummy();

return 1;
}

1. Step:

Add PROFILE_BEGIN and PROFILE_END macros around the code blocks you want to measure. The name in brackets must be a valid and unique C/C++ identifier otherwise you will get compile errors. Moreover, make sure that each PROFILE_BEGIN has its corresponding PROFILE_END call. In the below example an additional PROFILE_END(bar) had to be added to the if-statement block to make sure, that the PROFILE_BEGIN(bar) has its counterpart in any case of the control flow.
void foo(int i)
{
PROFILE_BEGIN(foo);
dummy();
bar(i)
PROFILE_END(foo);
}

void bar(int i)
{
PROFILE_BEGIN(bar);
if(i<1) {
dummy();
PROFILE_END(bar);
return;
}
bar(i-1);
PROFILE_END(bar);
}

void dummy()
{
PROFILE_BEGIN(dummy);
usleep(1000*100);
PROFILE_END(dummy);
}

int main()
{
PROFILE_BEGIN(main)
for(int i=0; i<10; ++i)
foo(2);

    bar(5);
dummy();
PROFILE_END(main);
  
dbgProfiler.writeReport("./Example");
return 1;
}

2. Step

Call  dbgProfiler.writeReport() just before your application is about to terminate. In the parameter you must specify the directory where to write the report with the profiling results. The directory must exist already.

3. Step

Add the DbgProfiler.cpp source file to your project, compile and link with all compiler flags and optimizations you desire and run your application just as normal.

4. Step

Analyze the profiling report which is written to the specified directory after your application has terminated.

HERE you can find the report for the example above. Below it will be revised in detail.

The profiling report:

For each PROFILE_BEGIN - PROFILE_END block a separate HTML file is generated. Each file consists of three sections: statistics, callees and callers.  If you have the Graphviz dot tool installed the call graph is shown at the top of each HTML file. The following output was generated for the block foo of the above example.

Call graph:



Statistics for: 'foo'

number of
calls
average time
per call (ms)
total time (ms)
 foo
10203.62036.4

Here you can see that the block foo was called 10 times. Overall 2,036 seconds where spend in this block. Hence the average time per call is 203 milliseconds.

Callees:

number of
calls
average time
per call (ms)
total time (ms)
 dummy
 50.2%
10102.11021.3
 bar
 49.8%
10101.51015.1
 dummy
 30.5%
11101.51116.9
 bar
 69.5%
25101.62539.5

foo has called dummy and bar. The block dummy was called 10 times from foo and with 1021.3 milliseconds 50.2% of foos execution time was spend there. bar also was called 10 times and with 1015.1 milliseconds 49.8% of foos time was spend in this block. The block bar itself has called the blocks dummy and bar recursively, ...

Callers:

The following Callers-table was generated for the block dummy:

number of
calls
average time
per call (ms)
total time (ms)
 foo
 45.6%
10102.11021.3
 bar
 49.9%
11101.51116.9
 main
 4.5%
1101.9101.9

The block dummy was called by foo, bar and main. From foo it was called 10 times and 45.6% of dummys total execution time was caused by these calls.



Last modified: 02 Dez. 2006 (Copyright 2006 by Erik Einhorn)