Logging code execution in C++

Question

Having used gprof and callgrind many times, I have reached the (obvious) conclusion that I cannot use them efficiently when dealing with large (as in a CAD program that loads a whole car) programs. I was thinking that maybe, I could use some C/C++ MACRO magic and somehow build a simple (but nice) logging mechanism. For example, one can call a function using the following macro:

#define CALL_FUN(fun_name, ...) \
    fun_name (__VA_ARGS__);

We could add some clocking/timing stuff before and after the function call, so that every function called with CALL_FUN gets timed, e.g

#define CALL_FUN(fun_name, ...) \
   time_t(&t0);                 \
   fun_name (__VA_ARGS__);      \
   time_t(&t1);

The variables t0, t1 could be found in a global logging object. That logging object can also hold the calling graph for each function called through CALL_FUN. Afterwards, that object can be written in a (specifically formatted) file, and be parsed from some other program.

So here comes my (first) question: Do you find this approach tractable ? If yes, how can it be enhanced, and if not, can you propose a better way to measure time and log callgraphs ?

A collegue proposed another approach to deal with this problem, which is annotating with a specific comment each function (that we care to log). Then, during the make process, a special preprocessor must be run, parse each source file, add logging logic for each function we care to log, create a new source file with the newly added (parsing) code, and build that code instead. I guess that reading CALL_FUN... macros (my proposal) all over the place is not the best approach, and his approach would solve this problem. So what is your opinion about this approach?

PS: I am not well versed in the pitfalls of C/C++ MACROs, so if this can be developed using another approach, please say it so.

Thank you.

Answer 1

I am bit late, but here is what I am doing for this:

On Windows there is a /Gh compiler switch which makes the compiler to insert a hidden _penter function at the start of each function. There is also a switch for getting a _pexit call at the end of each function.

You can utilizes this to get callbacks on each function call. Here is an article with more details and sample source code:

http://www.johnpanzer.com/aci_cuj/index.html

I am using this approach in my custom logging system for storing the last few thousand function calls in a ring buffer. This turned out to be useful for crash debugging (in combination with MiniDumps).

Some notes on this:

• The performance impact very much depends on your callback code. You need to keep it as simple as possible.
• You just need to store the function address and module base address in the log file. You can then later use the Debug Interface Access SDK to get the function name from the address (via the PDB file).

All this works suprisingly well for me.

Answer 2

Well you could do some C++ magic to embed a logging object. something like

class CDebug 
{
CDebug() { ... log somehow ... }
~CDebug() { ... log somehow ... }

};

in your functions then you simply write

void foo()
{
   CDebug dbg;
    ...

   you could add some debug info


   dbg.heythishappened()

   ...
}  // not dtor is called or if function is interrupted called from elsewhere.

Answer 3

Let me assume the reason you are doing this is you want to locate any performance problems (bottlenecks) so you can fix them to get higher performance.

As opposed to measuring speed or getting coverage info.

It seems you're thinking the way to do this is to log the history of function calls and measure how long each call takes.

There's a different approach. It's based on the idea that mainly the program walks a big call tree. If time is being wasted it is because the call tree is more bushy than necessary, and during the time that's being wasted, the code that's doing the wasting is visible on the stack. It can be terminal instructions, but more likely function calls, at almost any level of the stack. Simply pausing the program under a debugger a few times will eventually display it. Anything you see it doing, on more than one stack sample, if you can improve it, will speed up the program. It works whether or not the time is being spent in CPU, I/O or anything else that consumes wall clock time. What it doesn't show you is tons of stuff you don't need to know. The only way it can not show you bottlenecks is if they are very small, in which case the code is pretty near optimal.

Here's more of an explanation.

Answer 4

Many nice industrial libraries have functions' declarations and definitions wrapped into void macros, just in case. If your code is already like that -- go ahead and debug your performance problems with some simple asynchronous trace logger. If no -- post-insertion of such macros can be an unacceptably time-consuming.

I can understand the pain of running an 1Mx1M matrix solver under valgrind, so I would suggest starting with so called "Monte Carlo profiling method" -- start the process and in parallel run pstack repeatedly, say each second. As a result you will have N stack dumps (N can be quite significant). Then, the mathematical approach would be to count relative frequencies of each stack and make a conclusion about the ones most frequent. In practice you either immediately see the bottleneck or, if no, you switch to bisection, gprof, and finally to valgrind's toolset.

Answer 5

Although I think it will be hard to do anything better than gprof, you can create a special class LOG for instance and instantiate it in the beginning of each function you want to log.

class LOG {
    LOG(const char* ...) {
        // log time_t of the beginning of the call
    }
    ~LOG(const char* ...) {
        // calculate the total time spent,
        //by difference between current time and that saved in the constructor
    }
};

void somefunction() {
    LOG log(__FUNCTION__, __FILE__, ...);
    .. do other things
}

Now you can integrate this approach with the preprocessing one you mentioned. Just add something like this in the beginning of each function you want to log:

// ### LOG

and then you replace the string automatically in debug builds (shoudn't be hard).

Answer 6

May be you should use a profiler. AQTime is a relatively good one for Visual Studio. (If you have VS2010 Ultimate, you already have a profiler.)