GCC Function Instrumentation

Original Post : http://codingrelic.geekhold.com/2010/09/gcc-function-instrumentation.html

One of gcc’s more obscure features is -finstrument-functions. It was implemented by Cygnus Solutions, presumably as part of a contract for sombody-or-other to deliver something-or-other. When enabled, the compiler will emit calls to __cyg_profile_func_enter() and __cyg_profile_func_exit() at the top and bottom of every function.

Let’s examine a simple example which prints the function addresses at entry and exit.

#include 

void __cyg_profile_func_enter(void *this_fn, void *call_site)
                              __attribute__((no_instrument_function));
void __cyg_profile_func_enter(void *this_fn, void *call_site) {
  printf("ENTER: %p, from %p\n", this_fn, call_site);
} /* __cyg_profile_func_enter */

void __cyg_profile_func_exit(void *this_fn, void *call_site)
                             __attribute__((no_instrument_function));
void __cyg_profile_func_exit(void *this_fn, void *call_site) {
  printf("EXIT:  %p, from %p\n", this_fn, call_site);
} /* __cyg_profile_func_enter */

int foo() {
  return 2;
}

int bar() {
  return 1;
}

int main(int argc, char** argv) {
  printf("foo=%d bar=%d\n", foo(), bar());
}

The __cyg_profile_func_enter and exit functions are passed two parameters: the address of the function being entered/exited, and the address from which it was called. Note the use of the no_instrument_function attribute. If not present, then __cyg_profile_func_enter would be instrumented like any other function. Every call would result in calling the instrumentation again, which results in another call, etc etc until it blows the stack. Previously I’ve used -finstrument-functions to construct a profiler for a CPU whose interrupt structure was not suitable for a sample-based profiler. All of the routines implementing the profiler were labelled no_instrument_function.

Next we’ll examine the output, with just enough of the disassembled binary to make sense of it.

$ cc t.c -finstrument-functions
$ ./a.out
ENTER: 0x4005d0 @ 0x2b59e0d471c4 (calling main)
ENTER: 0x40059d @ 0x40060c       (calling foo)
EXIT:  0x40059d @ 0x40060c       (returning from foo)
ENTER: 0x40056a @ 0x400618       (calling bar)
EXIT:  0x40056a @ 0x400618       (returning from bar)
foo=2 bar=1
EXIT:  0x4005d0 @ 0x2b59e0d471c4 (returning from main)

000000000040056a :
  40056a: push   %rbp
  ...

000000000040059d :
  40059d: push   %rbp
  ...

00000000004005d0 :
  4005d0: push   %rbp
  ...
  400607: callq  40059d 
  40060c: mov    %eax,%ebx
  ...
  400613: callq  40056a 
  400618: mov    %eax,%esi
  ...

There are a few interesting things to note in the output.

Though main calls printf, we don’t see a call to printf in the output. Function instrumentation is implemented during compilation, and we didn’t compile printf we linked to an existing library. We’ll only see the instrumentation for functions compiled with -finstrument-functions.
The call_site is the instruction after the one which vectors over to run the function.
The call_site which called main() looks strange. It is not in the TEXT segment, it is way up at some weird address. This is address space layout randomization in action, every run of this binary has a different address calling main. I don’t know exactly what that routine is, but presumably it is part of the trampoline when the kernel begins executing a new process.

This instrumentation facility is not often used. The aforementioned call graph profiler is the only time I’ve used it. Nonetheless I hope you find it interesting.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s