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

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 2

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 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 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 5

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 6

Use a debugger to set breakpoints with associated actions. For example, in gdb you could set a breakpoint at the beginning and end of each of the functions you want to trace. You can give each of those breakpoints a command to execute, such as:

printf("Enter func100(p1001=%d, p1002=%d)", p1001, p1002)

Then, when you run the program (in the debugger) it'll print the text from each of your commands along with the associated parameters.

Take a look at the relevant documentation for gdb.

Answer 7

I would recommend to try uftrace, which can trace function call graph and also can show the value in arguments. It works with both static instrumentation (gcc -pg) or dynamic instrumentation, a very nice tool.

https://github.com/namhyung/uftrace

Answer 8

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

Answer 9

If you use dynamic modules you can get this info with the command ltrace. You can even specify the watched library with the -l flag

Answer 10

Here is a perfect answer, I was looking for a similar tool and I found one by John Panzer made in 1998 called CallMonitor.. here is the output of the tool. Yes it's made for Visual C++ 6.0 but it works in Visual Studio 2019 with no edits at all.

(Aside from missing the parameters which ehh I could live without.)

Works on Windows!!!

I put the code on my personal github for historical backups. (It also contains a compiled Debug built I built myself so you can test it right away just run Test.exe in a command prompt to see the results).

https://github.com/fatrolls/CallMonitor

Here is the test.cpp code

// Test driver for CallMon

#include <windows.h>
#include <iostream>

using namespace std;

void child2(bool doThrow)
{
    Sleep(5);
    if (doThrow) throw "random exception";
}

void child1(bool doThrow)
{
    child2(false);
    child2(doThrow);
}

// Waits a bit, then calls a child function
// that might throw an exception
DWORD WINAPI threadFunc(LPVOID param)
{
    Sleep(1);
    try {
        child1(param ? true : false);
    } catch (char *) {
        child1(false);
    }
    return 0;
}

// Starts argv[1] threads running, of which argv[2] throw
// exceptions.
void main(int argc,char *argv[])
{
    if (argc!=3)
    {
        cout << "Usage: " << argv[0] << " <number of threads, or 0> <number of exceptions>" << endl;
        cout << "  Pass 0 for number of threads for simple nonthreaded test" << endl;
        cout << "  Pass the number of threads which should throw exceptions as the second arg" << endl;
        cout << "  Note: The test output for the multithreaded case gives " << endl;
        cout << "        nearly unreadable output." << endl;
        return;
    }
    const int MAX_THREADS=MAXIMUM_WAIT_OBJECTS;
    DWORD id;
    HANDLE th[MAX_THREADS];
    int numThreads = atol(argv[1]);
    int numExc = atol(argv[2]);
    if (numThreads == 0)
    {
        threadFunc((void*)(numExc));
    }
    else
    {
        int i;
        for(i=0;i<numThreads;i++)
        {
            void * param= (void*)(i < numExc ? 1 : 0);
            th[i] = CreateThread(NULL,0,threadFunc,param,0,&id);
        }
        WaitForMultipleObjects(numThreads,th,TRUE,50000);
        for(i=0;i<numThreads;i++)
        {
            CloseHandle(th[i]);
        }
    }
}

Here is output of Test.exe 0 20

C:\Users\User\Desktop\callmonitor\Debug>Test 0 20
Test!main (002B2160)
        Test!threadFunc (002B20A0)
                Test!child1 (002B1F70)
                        Test!child2 (002B1FB0)
                        exit 002B1FB0, elapsed time=4 ms (13738100 ticks)
                        Test!child2 (002B1FB0)
                                Test!child1 (002B1F70)
                                        Test!child2 (002B1FB0)
                                        exit 002B1FB0, elapsed time=4 ms (123855
75 ticks)
                                        Test!child2 (002B1FB0)
                                        exit 002B1FB0, elapsed time=5 ms (150199
75 ticks)
                                exit 002B1F70, elapsed time=27 ms (82797408 tick
s)
                        exception exit 002B1FB0, elapsed time=40 ms (122291193 t
icks)
                exception exit 002B1F70, elapsed time=56 ms (170411060 ticks)
        exit 002B20A0, elapsed time=61 ms (184553835 ticks)
exit 002B2160, elapsed time=74 ms (222897953 ticks)

C:\Users\User\Desktop\callmonitor\Debug>

Here is the output of Test.exe

Test!main (01132160)
        Test!std::operator<<<std::char_traits<char> > (01131740)
                Test!<unknown symbol> (01132070)
                exit 01132070, elapsed time=0 ms (1960 ticks)
                Test!<unknown symbol> (01131CB0)
                        Test!<unknown symbol> (01131C40)
                        exit 01131C40, elapsed time=0 ms (3123 ticks)
                exit 01131CB0, elapsed time=2 ms (7502464 ticks)
                Test!<unknown symbol> (01131F00)
                exit 01131F00, elapsed time=0 ms (378 ticks)
Usage:          Test!<unknown symbol> (01131E60)
                        Test!<unknown symbol> (01131DC0)
                        exit 01131DC0, elapsed time=0 ms (1740 ticks)
                exit 01131E60, elapsed time=2 ms (6846975 ticks)
        exit 01131740, elapsed time=15 ms (47014729 ticks)
        Test!std::operator<<<std::char_traits<char> > (01131740)
                Test!<unknown symbol> (01132070)
                exit 01132070, elapsed time=0 ms (1485 ticks)
                Test!<unknown symbol> (01131CB0)
                        Test!<unknown symbol> (01131C40)
                        exit 01131C40, elapsed time=0 ms (2268 ticks)
                exit 01131CB0, elapsed time=2 ms (8479308 ticks)
                Test!<unknown symbol> (01131F00)
                exit 01131F00, elapsed time=0 ms (285 ticks)
Test            Test!<unknown symbol> (01131E60)
                        Test!<unknown symbol> (01131DC0)
                        exit 01131DC0, elapsed time=0 ms (2415 ticks)
                exit 01131E60, elapsed time=3 ms (10897188 ticks)
        exit 01131740, elapsed time=17 ms (52439945 ticks)
        Test!std::operator<<<std::char_traits<char> > (01131740)
                Test!<unknown symbol> (01132070)
                exit 01132070, elapsed time=0 ms (1443 ticks)
                Test!<unknown symbol> (01131CB0)
                        Test!<unknown symbol> (01131C40)
                        exit 01131C40, elapsed time=0 ms (2550 ticks)
                exit 01131CB0, elapsed time=2 ms (8731260 ticks)
                Test!<unknown symbol> (01131F00)
                exit 01131F00, elapsed time=0 ms (354 ticks)
 <number of threads, or 0> <number of exceptions>               Test!<unknown sy
mbol> (01131E60)
                        Test!<unknown symbol> (01131DC0)
                        exit 01131DC0, elapsed time=0 ms (2397 ticks)
                exit 01131E60, elapsed time=3 ms (10455030 ticks)
        exit 01131740, elapsed time=18 ms (54133983 ticks)
        Test!std::endl<char,std::char_traits<char> > (01131BE0)

        exit 01131BE0, elapsed time=0 ms (1256316 ticks)
        Test!std::operator<<<std::char_traits<char> > (01131740)
                Test!<unknown symbol> (01132070)
                exit 01132070, elapsed time=0 ms (1554 ticks)
                Test!<unknown symbol> (01131CB0)
                        Test!<unknown symbol> (01131C40)
                        exit 01131C40, elapsed time=0 ms (1983 ticks)
                exit 01131CB0, elapsed time=2 ms (8839671 ticks)
                Test!<unknown symbol> (01131F00)
                exit 01131F00, elapsed time=0 ms (2736 ticks)
  Pass 0 for number of threads for simple nonthreaded test              Test!<un
known symbol> (01131E60)
                        Test!<unknown symbol> (01131DC0)
                        exit 01131DC0, elapsed time=0 ms (1605 ticks)
                exit 01131E60, elapsed time=2 ms (8375898 ticks)
        exit 01131740, elapsed time=20 ms (61957080 ticks)
        Test!std::endl<char,std::char_traits<char> > (01131BE0)

        exit 01131BE0, elapsed time=0 ms (1303008 ticks)
        Test!std::operator<<<std::char_traits<char> > (01131740)
                Test!<unknown symbol> (01132070)
                exit 01132070, elapsed time=0 ms (1245 ticks)
                Test!<unknown symbol> (01131CB0)
                        Test!<unknown symbol> (01131C40)
                        exit 01131C40, elapsed time=0 ms (1548 ticks)
                exit 01131CB0, elapsed time=2 ms (8249352 ticks)
                Test!<unknown symbol> (01131F00)
                exit 01131F00, elapsed time=0 ms (408 ticks)
  Pass the number of threads which should throw exceptions as the second arg
        Test!<unknown symbol> (01131E60)
                        Test!<unknown symbol> (01131DC0)
                        exit 01131DC0, elapsed time=0 ms (1503 ticks)
                exit 01131E60, elapsed time=2 ms (8074389 ticks)
        exit 01131740, elapsed time=17 ms (52143870 ticks)
        Test!std::endl<char,std::char_traits<char> > (01131BE0)

        exit 01131BE0, elapsed time=0 ms (1312485 ticks)
        Test!std::operator<<<std::char_traits<char> > (01131740)
                Test!<unknown symbol> (01132070)
                exit 01132070, elapsed time=0 ms (1392 ticks)
                Test!<unknown symbol> (01131CB0)
                        Test!<unknown symbol> (01131C40)
                        exit 01131C40, elapsed time=0 ms (2043 ticks)
                exit 01131CB0, elapsed time=2 ms (8364006 ticks)
                Test!<unknown symbol> (01131F00)
                exit 01131F00, elapsed time=0 ms (357 ticks)
  Note: The test output for the multithreaded case gives                Test!<un
known symbol> (01131E60)
                        Test!<unknown symbol> (01131DC0)
                        exit 01131DC0, elapsed time=0 ms (1557 ticks)
                exit 01131E60, elapsed time=2 ms (8433210 ticks)
        exit 01131740, elapsed time=17 ms (51733404 ticks)
        Test!std::endl<char,std::char_traits<char> > (01131BE0)

        exit 01131BE0, elapsed time=0 ms (1323972 ticks)
        Test!std::operator<<<std::char_traits<char> > (01131740)
                Test!<unknown symbol> (01132070)
                exit 01132070, elapsed time=0 ms (1257 ticks)
                Test!<unknown symbol> (01131CB0)
                        Test!<unknown symbol> (01131C40)
                        exit 01131C40, elapsed time=0 ms (1668 ticks)
                exit 01131CB0, elapsed time=2 ms (7994649 ticks)
                Test!<unknown symbol> (01131F00)
                exit 01131F00, elapsed time=0 ms (393 ticks)
        nearly unreadable output.               Test!<unknown symbol> (01131E60)

                        Test!<unknown symbol> (01131DC0)
                        exit 01131DC0, elapsed time=0 ms (1572 ticks)
                exit 01131E60, elapsed time=2 ms (8090115 ticks)
        exit 01131740, elapsed time=17 ms (52094652 ticks)
        Test!std::endl<char,std::char_traits<char> > (01131BE0)

        exit 01131BE0, elapsed time=0 ms (1355601 ticks)
exit 01132160, elapsed time=162 ms (486552183 ticks)