Tracing Function Calls in C with -finstrument-functions
Some time ago, I wrote a blog post about mutex guards in the Linux kernel [1]. It uses a cool feature in GCC which allows you to cleanup resources when they go out of scope. I have a few of such GCC features that I use every now and then, which often show itself handy in the most unexpected way. -finstrument-functions is one of those.
So, what is -finstrument-functions?
When you compile an application with -finstrument-functions, GCC automatically inserts calls to special functions at the entry and exit of every function in that source file. This simply allows you to trace the flow of function calls without modifying your source code.
E.g.
1gcc -finstrument-functions main.c -o mainGCC inserts calls to two special functions; __cyg_profile_func_enter() and __cyg_profile_func_exit(), which are called at the start and end of every function, respectively. By overriding those, you can implement your own tracing logic such as logging function calls, measure execution time and much more.
Just remember that this is pretty intrusive, especially if you put a lot of logic here.
(Ftrace in the Linux kernel)
Just a parantheses:
Does this sounds familiar? It’s similar to how function tracing works in the Linux kernel with ftrace, even if ftrace is not implemented with -finstrument-functions but rather with profiling information (-pg). Together with live patching it overrides the mcount() [2], [3] (or __fentry__()) on newer systems), which is the function that gets called on every function entry when you compile with -pg.
Pretty cool hue? Also, when ftrace is disabled, the call mcount is replaced with NOP instructions to minimize the overhead.
A minimal tracer
Lets start with a simple example:
1#include <stdio.h>
2
3void attribute((no_instrument_function))
4__cyg_profile_func_enter(void *func, void *caller)
5{
6 printf("ENTER: %p from %p\n", func, caller);
7}
8
9void attribute((no_instrument_function))
10__cyg_profile_func_exit(void *func, void *caller)
11{
12 printf("EXIT : %p to %p\n", func, caller);
13}
14
15void foo(void)
16{
17 printf("Inside foo()\n");
18}
19
20void bar(void)
21{
22 printf("Inside bar()\n");
23 foo();
24}
25
26int main(void)
27{
28 bar();
29 return 0;
30}Compile:
1gcc -finstrument-functions -o trace trace.cand run:
1./trace
2ENTER: unknown (0x55ca2cc14356) called from unknown (0x7f5d943896c1)
3Inside main()
4ENTER: unknown (0x55ca2cc14309) called from unknown (0x55ca2cc1438c)
5Inside bar()
6ENTER: unknown (0x55ca2cc142c1) called from unknown (0x55ca2cc1433a)
7Inside foo()
8EXIT : unknown (0x55ca2cc142c1) returning to unknown (0x55ca2cc1433a)
9EXIT : unknown (0x55ca2cc14309) returning to unknown (0x55ca2cc1438c)
10EXIT : unknown (0x55ca2cc14356) returning to unknown (0x7f5d943896c1)Now you'll see where the function entries and exits are, but the function names are not resolved. You may use addr2line to resolve the names by yourself, but that is not very convenient.
It is important to always use no_instrument_function on the hooks functions, otherwise they instrument themselves and you will end up in an infinite recursion. That is not what you want.
Making it readable with dladdr()
To resolve function addresses into symbol names, we can use dladdr().
Here’s an improved version:
1#define _GNU_SOURCE
2#include <stdio.h>
3#include <dlfcn.h>
4
5static void __attribute__((no_instrument_function))
6print_symbol(void *addr)
7{
8 Dl_info info;
9
10 if (dladdr(addr, &info) && info.dli_sname) {
11 printf("%s (%p)", info.dli_sname, addr);
12 } else {
13 printf("unknown (%p)", addr);
14 }
15
16}
17
18void __attribute__((no_instrument_function))
19__cyg_profile_func_enter(void *func, void *caller)
20{
21 printf("ENTER: ");
22 print_symbol(func);
23 printf(" called from ");
24 print_symbol(caller);
25 printf("\n");
26}
27
28void __attribute__((no_instrument_function))
29__cyg_profile_func_exit(void *func, void *caller)
30{
31 printf("EXIT : ");
32 print_symbol(func);
33 printf(" returning to ");
34 print_symbol(caller);
35 printf("\n");
36}
37
38void foo(void)
39{
40 printf("Inside foo()\n");
41}
42
43void bar(void)
44{
45 printf("Inside bar()\n");
46 foo();
47}
48
49int main(void)
50{
51 bar();
52 return 0;
53}To compile this we need a few more flags:
1gcc -finstrument-functions -rdynamic -o trace trace.c -ldl- finstrument-functions enabled the instrumentation as we saw before
- rdynamic exports symbols so that dladdr() can resolve names
- -ldl links against the dynamic linking library for dladdr()
And now the output becomes much more prettier:
1$ ./trace
2ENTER: main (0x55eb5682d356) called from unknown (0x7fbf637876c1)
3ENTER: bar (0x55eb5682d309) called from main (0x55eb5682d37d)
4Inside bar()
5ENTER: foo (0x55eb5682d2c1) called from bar (0x55eb5682d33a)
6Inside foo()
7EXIT : foo (0x55eb5682d2c1) returning to bar (0x55eb5682d33a)
8EXIT : bar (0x55eb5682d309) returning to main (0x55eb5682d37d)
9EXIT : main (0x55eb5682d356) returning to unknown (0x7fbf637876c1)What's next?
It's up to you! My most common use case for this is to measure execution time of functions. Then you will need some kind of filtering because you don't want to log every single function.
Also, you don't have to compile all files with -finstrument-functions, you can just compile the files you want to trace with that flag and link it together with the rest of the code.