C/C++ need a clever way to track function calls

Question

I am looking for a clever way to track function calls and returns. I know I can use the debugger, but I would like a way to just have it print something out to the terminal when calling a function vs having to step through code.
I am thinking that I might be able to use the preprocessor, but I am not sure what would be the best way to go about this.
Or is there a way to use gdb to print out the information that would be useful, while not having to step through the code.

Answer 1

Most compilers allow you to inject an instrumentation function before and after the function call.

In MSVC they are _penter and _pexit. A nice article: http://www.drdobbs.com/184403601.

In GCC you would use the -finstrument-functions option, see the docs.

You can use debug libaries or map files to get more info.

Answer 2

A quite intrussive solution is using RAII to control the scope of the function. This will have a great impact in performance, but will be quite explicit in the logs without requiring the user to add instrumentation in all possible code paths that may leave the function:

class ScopeLogger {
public:
   ScopeLogger( std::string const & msg ) : msg(msg)
   {   std::cout << "Enter: " << msg << std::endl; }
   ~ScopeLogger()
   {   std::cout << "Exit:  " << msg << std::endl; }
   std::string msg;
};
#if DEBUG
#define FUNCTION(x) ScopeLogger l_##x##_scope(x);
#endif

void foo( int value ) {
   FUNCTION( __FUNCTION__ );
   if ( value > 10 ) throw std::exception;
   std::cout << "." << std::endl;
}

int main() {
   foo(0);    // Enter: foo\n.\nExit:  foo
   foo(100);  // Enter: foo\nExit:  foo
}

If the code is single threaded, you might even want to add a static variable with some indentation level to ScopedLogger without adding too much to the already heavy performance impact:

class ScopeLogger {
public:
   ScopeLogger( std::string const & msg ) : msg(msg)
   {   std::cout << std::string(indent++,' ') << "Enter: " << msg << std::endl; }
   ~ScopeLogger()
   {   std::cout << std::string(--indent,' ') << "Exit:  " << msg << std::endl; }
   std::string msg;
   static int indent;
};
int ScopeLogger::indent = 0;

Answer 3

Since you are using GCC, you can also use linker function wrapping.

Link-Time Replacement / Wrapping
– GCC option: -Wl,--wrap,function_name

Basically, you can take a function called "function_name()" and wrap it with a function called "__wrap_function_name()". You can access the original function by calling "__real_function_name()".

Answer 4

#define BEGIN_FUNC(X) printf("Function %s Entered",X)
#define END_FUNC(X)  printf("Function %s End",X)

foo()
{
BEGIN_FUNC(__func__);

//Your code here


END_FUNC(__func__);


}

I think if you write a macro like above and use it for every function as described then you can get the logs on the terminal.

Answer 5

You may want to look at Valgrind's Callgrind which can track function calls into a pretty graph. It will show function calls, but not the parameter or return values.

Answer 6

Or is there a way to use gdb to print out the information that would be useful, while not having to step through the code

Yes. Set a breakpoint only at the functions that you actually care about. Use "continue" until you get to those functions or until your program crashes. Then use "backtrace" (or "bt") to get a stack trace.

Answer 7

If you need to automate it, you might take a look at TARGET_ASM_FUNCTION_END_PROLOGUE and TARGET_ASM_FUNCTION_BEGIN_EPILOGUE. These are compiler hooks that will let you specify pieces of assembly to be emitted along with the normal function prologue/epilogue -- in your case, you'd use them to emit a little assembly to log the entry/exit from the function in question. You could also look at FUNCTION_PROFILE and/or PROFILE_HOOK (e.g., at: http://gcc.gnu.org/onlinedocs/gccint/Function-Entry.html).

Answer 8

Below is an example illustrating the GCC side of the answer by Jonathan Fischoff.

Here we call external tool addr2line to print the location as functionName at /path/to/file.cpp:line instead of simply the address. I've tried using dladdr for this (as suggested in a comment to the answer linked above), but it returned only null pointers in dli_sname for me.

This approach of resolving the addresses has some drawbacks:

• It's slow due to fork/execve/file read.
• It needs exact file path to the binary containing the address, so the simple code below can't print symbols in shared libraries.

// Instrumentation
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>

static void __attribute__((no_instrument_function))
    log_func(const void* funcAddr, const char* action, const void* callSite)
{
    char cmd[50];
    snprintf(cmd, sizeof cmd, "addr2line -Cpfe /proc/%d/exe %p", getpid(), funcAddr);
    fprintf(stderr, "%p %s %p ", callSite, action, funcAddr);
    system(cmd);
}

extern "C" void __attribute__((no_instrument_function))
    __cyg_profile_func_enter(void* this_fn, void* call_site)
{
    log_func(this_fn, "->", call_site);
}

extern "C" void __attribute__((no_instrument_function))
    __cyg_profile_func_exit(void* this_fn, void* call_site)
{
    log_func(this_fn, "<-", call_site);
}

// Actual code we're tracing
#include <iostream>

struct Test
{
    Test() { std::cout << "Hi, I'm Test constructor\n"; }
    void method() const { std::cout << "And I'm Test method\n"; }
};

int main()
{
    std::cout << "Hello, my name is main\n";
    Test test;
    test.method();
}

Compilation and running:

$ g++ test.cpp -o test -g -finstrument-functions && time ./test
0x8048b0b -> 0x804899b _GLOBAL__sub_I___cyg_profile_func_enter at /tmp/test.cpp:41
0x80489c4 -> 0x804890b __static_initialization_and_destruction_0(int, int) at /tmp/test.cpp:41
0x80489c4 <- 0x804890b __static_initialization_and_destruction_0(int, int) at /tmp/test.cpp:41
0x8048b0b <- 0x804899b _GLOBAL__sub_I___cyg_profile_func_enter at /tmp/test.cpp:41
0xf7a0de71 -> 0x804886a main at /tmp/test.cpp:37
Hello, my name is main
0x80488b1 -> 0x80489de Test::Test() at /tmp/test.cpp:32
Hi, I'm Test constructor
0x80488b1 <- 0x80489de Test::Test() at /tmp/test.cpp:32
0x80488c0 -> 0x8048a4a Test::method() const at /tmp/test.cpp:33
And I'm Test method
0x80488c0 <- 0x8048a4a Test::method() const at /tmp/test.cpp:33
0xf7a0de71 <- 0x804886a main at /tmp/test.cpp:37

real    0m0.062s
user    0m0.054s
sys     0m0.008s

Answer 9

There is a __FUNCTION__ (Reference) macro used to determine what method (in the format Class::Method) you're in, but this is more of a manual process.

However, when I needed the same 'trace' information recently, I could not find a automatic method.