how to trace function call in C?

Question

Without modifying the source code, how can i trace which functions are called and with what parameters, when some function(say func100 in the following example) is invoked. I would like the output to be as follows:

enter func100(p1001=xxx,p1002=xxx)
        enter func110(p1101=xxx,p1102=xxx)
        exit  func110(p1101=xxx,p1102=xxx)
        enter func120(p1201=xxx,p1202=xxx,p1203=xxx)
                enter func121(p1211=xxx)
                exit  func121(p1211=xxx)
        exit  func120(p1201=xxx,p1202=xxx,p1203=xxx)
exit  func100(p1001=xxx,p1002=xxx)

is this doable? or what's the solution with minimum modification of source code?

Answer 1

With the GNU C Library, you can use the backtrace module. Here is an example for that:

#include <stdio.h>
#include <execinfo.h>
#include <stdlib.h>


void handler(char *caller) {
  void *array[10];
  size_t size;
  printf("Stack Trace Start for %s\n",caller);
  size = backtrace(array, 10);
  backtrace_symbols_fd(array, size, 2);
  printf("Stack Trace End\n");
}

void car() {
    handler("car()");
    printf("Continue Execution");
}
void baz() {car(); }

void bar() { baz(); }
void foo() { bar(); }


int main(int argc, char **argv) {
  foo(); 
}

compile with -g -rdynamic compiler option to load the symbols

gcc -g -rdynamic Test1.c -o Test

You will see an output similar to

Stack Trace Start for car()
./Test(handler+0x2d)[0x80486f1]
./Test(car+0x12)[0x804872e]
./Test(baz+0xb)[0x8048747]
./Test(bar+0xb)[0x8048754]
./Test(foo+0xb)[0x8048761]
./Test(main+0xb)[0x804876e]
/lib/i386-linux-gnu/libc.so.6(__libc_start_main+0xe7)[0x126e37]
./Test[0x8048631]
Stack Trace End
Continue Execution in car

You can write this handler function and call from anywhere in your program at any number of time. Remember to increase the array size as required.

Answer 2

Sometimes I have to trace lots of function calls, even for external libraries I don't have any control, or I don't want to modify.

Sometime ago, I realized that you can combine gdb's regular expression breakpoints (regular ones are ok, too) and then just execute a set of commands to be run each time those breakpoints are triggered. See: http://www.ofb.net/gnu/gdb/gdb_35.html

For example, if you want to trace all the functions which start with "MPI_" prefix, you can do:

(gdb) rbreak MPI_
[...]
(gdb) command 1-XX
(gdb) silent
(gdb) bt 1
(gdb) echo \n\n
(gdb) continue
(gdb) end

Silent command is used to hide gdb messages when a breakpoint is found. I usually print a couple of empty lines, so that it is easier to read.

Then, you just run the program: (gdb) run

Once your program starts running, gdb will print the N topmost backtrace levels.

#0  0x000000000040dc60 in MPI_Initialized@plt ()


#0  PMPI_Initialized (flag=0x7fffffffba78) at ../../src/mpi/init/initialized.c:46


#0  0x000000000040d9b0 in MPI_Init_thread@plt ()


#0  PMPI_Init_thread (argc=0x7fffffffbe78, argv=0x7fffffffbde0, required=3, provided=0x7fffffffba74) at ../../src/mpi/init/initthread.c:946


#0  0x000000000040e390 in MPI_Comm_rank@plt ()


#0  PMPI_Comm_rank (comm=1140850688, rank=0x7fffffffba7c) at ../../src/mpi/comm/comm_rank.c:53


#0  0x000000000040e050 in MPI_Type_create_struct@plt ()


#0  PMPI_Type_create_struct (count=3, array_of_blocklengths=0x7fffffffba90, array_of_displacements=0x7fffffffbab0, array_of_types=0x7fffffffba80, newtype=0x69de20) at ../../src/mpi/datatype/type_create_struct.c:116


#0  0x000000000040e2a0 in MPI_Type_commit@plt ()


#0  PMPI_Type_commit (datatype=0x69de20) at ../../src/mpi/datatype/type_commit.c:75

If you want more detailed information, printing local variables of a given breakpoint is also possible, just insert more commands between command and end.

Bonus tip: add all of these to your .gdbinit file and pipe the execution into a file.

Answer 3

I also encountered this problem of having good function call traces. Therefore, I wrote a Python GDB script (https://gist.github.com/stettberger/e6f2fe61206471e22e9e6f1926668093) that sets a breakpoint on every interesting function (defined by the environment variable TRACE_FUNCTION). GDB then invokes the python function, which decodes the frame and all its arguments. If it encounters a pointer it tries to dereference it and so print a function call trace to TRACE_FILE (default: /tmp/log) with arguments. For the following program

#include <stdio.h>

struct foo {
    int a;
    struct foo * next;
};

int fib(int a, struct foo *b) {
    if (a <= 1) return 1;
    printf("%d\n", a);
    return fib(a-1, 0)+fib(a-2, 0);
}

int main() {
    struct foo b = {23, 0};
    return fib(5, &b);
}

I get a detailed trace, where every line is a python tuple that can be read with eval():

('call', None, 1, 'main', 'main', {})
('call', 1, 2, 'fib', 'fib', {'a': {'type': 'int', 'value': 5}, 'b': {'type': 'struct foo *', 'value': 140737488344320, 'deref': {'type': 'struct foo', 'value': {'a': {'type': 'int', 'value': 23}, 'next': {'type': 'struct foo *', 'value': 0, 'deref': None}}}}})
('call', 2, 3, 'fib', 'fib', {'a': {'type': 'int', 'value': 4}, 'b': {'type': 'struct foo *', 'value': 0, 'deref': None}})
....
('return', 'fib', 2, {'type': 'int', 'value': 8})
('exit', 8)

The gist contains more information on the log file format.

Answer 4

If you use gcc, you can use the -finstrument-functions compilation flag. It adds code that calls two functions, __cyg_profile_func_enter and __cyg_profile_func_exit, whenever a function enters/exits.

You'll need to implement these functions, to do what you want. Make sure to compile them either without the flag, or with attribute((no_instrument_function)), so they won't try to call themselves.

The functions' second parameter would be a pointer to the call site (i.e. the return address within the calling function). You can just print it with %p, but it will be somewhat hard to use. You can use nm to figure out the real function which contains this address.

You can't get the function parameters this way.

Answer 5

If you were on linux, callgrind might help. It basically collects statistics of what you're looking for, so, it might provide a way to access its raw data.

Answer 6

You can look into log4cxx, a project hosted by the apache foundation. I know that log4j, the java variant allowed you to set the sensitivity, and you could track every single thing that was done in the program. Maybe that the c++ variant is the same, but there are several alternatives-there's an aspect oriented c++ compiler, and you can define an aspect across all functions, and have it catch and print the variables. Another alternative is to use a debugger.

To summarize: debugger, log4cxx or AOP