Instrumenting for a different profiling algorithm

[Michael Veksler <mveksler at tx dot technion dot ac dot il>]

Hello all,

[Sorry for the excessively long mail. It contains introduction, problem 
explanation, solution and a set of how-to questions].

== Introduction ==
Because gprof is completely useless in some cases (see below), I had to 
develop
(1999) a new profiling algorithm. Unfortunately, my implementation 
requires manual
instrumentation of all "interesting" functions with RAII objects (C++ 
only).
Aside form the manual instrumentation, the new profiler works perfectly, 
with
remarkable accuracy and low overhead (a bit faster than gcc -O2 -pg -g).

Instead of doing this manually, I would like to tell GCC instrument the 
code such that:

  1. Create a static variable per profiled function (could be void*).
  2. Call a profiling-function upon entry (and pass this pointer, and
     __FUNCTION__ - or whatever its name is in c99/c++0x).
  3. Call a conclude-function upon exit from the profiled function.

== Problem description ==

gcc -pg and gprof can't accumulate time of function's children. Instead, 
gprof
would interpolate based on call count. For example, look at the attached 
file.
In practice 'fast' takes less than a millisecond, and slow takes around 
a second,
yet gprof manages to reverse their order (when compiling gcc -pg -g t.c,
and running gprof a.out):

|                0.00    0.00       1/1001        slow [4]
               1.05    0.00    1000/1001        fast [3]
[1]    100.0    1.06    0.00    1001         f [1]
-----------------------------------------------
[2]    100.0    0.00    1.06                 main [2]
               0.00    1.05    1000/1000        fast [3]
               0.00    0.00       1/1           slow [4]
|The only correct  information is on the time that the leaf "f" takes.

Measuring the time manually (see t.c) give (contradicting gprof):

   |Slow took 1.15 seconds
   Sum of fast took 0.00 seconds
   |

(You can tune t.c to make the result as inaccurate as you like)

=== Solution ===

Record approximate time of entry and exit of each function (volatile tick
counter is updated by a SIGPROF handler). Accumulate time for each:

  1. Time for a function (unlike -pg this will be function+sibling time).
  2. Time for a pair of caller-callee functions. (The time that the
     callee  contributes to the caller's total)

In my experience, this scheme works much better than the current 
-pg+gprof (the latter is totally useless for my needs, I'd better flip a 
coin to decide which function I guess to be expensive).

To do:
I would like to add the instrumentation (as explained above). To avoid 
billing the overhead of the profiling on instrumented functions, I need 
to maintain
volatile unsigned in_profiler;
and avoid counting time when in_profiler!=0. in_profiler is updated as 
follows:

  1. in_profiler=1 right before parameters are passed to the call of
     start_profile_function(&state, __FUNCTION__); and
     finalize_profile_function(&state);
  2. in_profiler=0 immediately  after *_profile_function() cleans up
     the remains of the call (depending on the ABI, it is possible that
     no such clean up occurs).

== How to: ==

I would like to find how to force gcc (and its optimizers):

  1. Not to move stuff across in_profiler=*  assignments, for all
     optimizers. This was measured to skew profiling by 10-20% on x86
     Linux, and more than x2 on tiny functions on PPC-AIX (adding an
     __asm__ register+memory barrier lowered this to 1-4% on x86, but
     not for PPC-AIX's ABI)
  2. Instrument start_profile_function as early as possible in the
     profiled function (if possible before most of the preamble).
  3. Instrument finalize _profile_function as late as possible in the
     profiled function (if possible after most of the preamble).
  4. Take exceptions into account
  5. Extract the __FUNCTION__ information from inside
     start_profile_function() instead of passing it explicitly (debug
     info?)
        1. If __FUNCTION__ can be extracted from stack then maybe ditch
           in_profiler=* altogether (this way the profiler will be
           billed correctly for its time, without such variables).
        2. Use specialized ABI to call *_profile_function, saving up
           the need for register save/restore for profiler's function
           calls.

It took me about a week to implement it in C++ using STL (using RAII and 
manual instrumentation). I hope that it would take me no more than two 
weeks doing this for C. Anything more than will shift my benefit/cost 
ration to finding a weaker solution.

I would be happy to get any comments or suggestions (especially "don't 
waste your time, it is not needed because...").

Note that I am not 100% if I am allowed to assign copyright to FSF. I am 
doing this with my student hat (need it for accurate profiling of my 
research code), but my IBM researcher hat may (or may not) interfere, 
and I'll need advice from our legal department.

Thanks
 Michael

--
Michael Veksler
http:///tx.technion.ac.il/~mveksler

#include <stdio.h>
#include <time.h>
volatile long long total_count=0;
void f(unsigned repeat_count)
{
	unsigned i;
	for (i=0; i < repeat_count ; ++i)
		++total_count;
}
void fast()
{
	f(1);
}
void slow()
{
	f(300*1000*1000);
}
int main()
{
	unsigned i=0;
	clock_t start;
	start=clock();
	slow();
	printf("Slow took %.2f seconds \n",
		 (clock()-start)*1.0/CLOCKS_PER_SEC);
	start=clock();
	for (i=0 ; i < 1000 ; ++i)
		fast();
	printf("Sum of fast took %.2f seconds \n",
		 (clock()-start)*1.0/CLOCKS_PER_SEC);
	return 0;
}