Software debugging is a complex task. There is always the need to collect all available information, in order to detect and understand the problem fast and to think of a proper solution. Sometimes it’s more convenient to debug step-by-step, sometimes it’s better to make the program run completely, and then trace the execution flow “offline”.
Another important step in software development is profiling. GNU offers “gprof” as a tool to analyze the execution time of functions. The working principle of gprof is that it polls the program state with a small sampling interval and notes the function that is executing. In this case small functions could also not appear in the profiling data because their execution time is smaller than an interval.
I recently tried to use a feature of GNU GCC that can be of some help both for tracing and for profiling. It’s the following option (from its GNU GCC Manual section):
-finstrument-functions- Generate instrumentation calls for entry and exit to functions. Just after function entry and just before function exit, the following profiling functions will be called with the address of the current function and its call site. [...]
void __cyg_profile_func_enter (void *this_fn, void *call_site); void __cyg_profile_func_exit (void *this_fn, void *call_site);[...]
The execution flow can be traced implementing these monitoring points, for example writing on file some useful information.
Suppose you have to analyze the following code:
#include <stdio.h>
void foo() {
printf("foo\n");
}
int main() {
foo();
return 0;
}
Create a file called “trace.c” with the following content:
#include <stdio.h>
#include <time.h>
static FILE *fp_trace;
void
__attribute__ ((constructor))
trace_begin (void)
{
fp_trace = fopen("trace.out", "w");
}
void
__attribute__ ((destructor))
trace_end (void)
{
if(fp_trace != NULL) {
fclose(fp_trace);
}
}
void
__cyg_profile_func_enter (void *func, void *caller)
{
if(fp_trace != NULL) {
fprintf(fp_trace, "e %p %p %lu\n", func, caller, time(NULL) );
}
}
void
__cyg_profile_func_exit (void *func, void *caller)
{
if(fp_trace != NULL) {
fprintf(fp_trace, "x %p %p %lu\n", func, caller, time(NULL));
}
}
The idea is to write into a log (in our case “trace.out“) the function addresses, the address of the call and the execution time. To do so, a file needs to be open at the beginning of execution. The GCC-specific attribute “constructor” helps in defining a function that is executed before “main”. In the same way the attribute “destructor” specifies that a function must be executed when the program is going to exit.
To compile and execute the program, the command-line is:
$ gcc -finstrument-functions -g -c -o main.o main.c $ gcc -c -o trace.o trace.c $ gcc main.o trace.o -o main $ ./main foo $ cat trace.out e 0x400679 0x394281c40b 1286372153 e 0x400648 0x40069a 1286372153 x 0x400648 0x40069a 1286372153 x 0x400679 0x394281c40b 1286372153
To understand the addresses, the “addr2line” tool can be used: it’s a tool included in “binutils” package that, given an executable with debug information, maps an execution address to a source code file and line. I put together an executable shell script (“readtracelog.sh“) that uses addr2line to print the trace log into a readable format:
#!/bin/sh
if test ! -f "$1"
then
echo "Error: executable $1 does not exist."
exit 1
fi
if test ! -f "$2"
then
echo "Error: trace log $2 does not exist."
exit 1
fi
EXECUTABLE="$1"
TRACELOG="$2"
while read LINETYPE FADDR CADDR CTIME; do
FNAME="$(addr2line -f -e ${EXECUTABLE} ${FADDR}|head -1)"
CDATE="$(date -Iseconds -d @${CTIME})"
if test "${LINETYPE}" = "e"
then
CNAME="$(addr2line -f -e ${EXECUTABLE} ${CADDR}|head -1)"
CLINE="$(addr2line -s -e ${EXECUTABLE} ${CADDR})"
echo "Enter ${FNAME} at ${CDATE}, called from ${CNAME} (${CLINE})"
fi
if test "${LINETYPE}" = "x"
then
echo "Exit ${FNAME} at ${CDATE}"
fi
done < "${TRACELOG}"
Testing the script with the previous output, the result is:
$ ./readtracelog.sh main trace.out Enter main at 2010-10-06T15:35:53+0200, called from ?? (??:0) Enter foo at 2010-10-06T15:35:53+0200, called from main (main.c:9) Exit foo at 2010-10-06T15:35:53+0200 Exit main at 2010-10-06T15:35:53+0200
The “??” symbol indicates that addr2line has no debug information on that address: in fact it should belong to C runtime libraries that initialize the program and call the main function. In this case the execution time was very small (less than a second) but in more complex scenarios the execution time can be useful to detect where the application spends the most time. It is also a good idea to use the most precise timer on the system, such as gettimeofday in Linux that returns also fractions of a second.
Some thoughts for embedded platforms:
- It is possible to have fine-grain timing information if the platform contains an internal hardware timer, counting even single clock cycles. It will become then important to reduce the overhead of the entry and exit functions to measure the real function execution time.
- The trace information can be sent to the serial port (for example in binary form), and then interpreted by a program running on PC.
- The entry and exit functions can be used to monitor also the state of other hardware peripherals, such as a temperature sensor.
See also:
Entries
Sylvain
2010/10/19
This is a great article !
It shows a way to trace and also profile in a manner that fits perfectly the embedded world constraints. I imagine coupling this to OCD. I was initially looking after a way to use the profiling info (-pg gcc option) and redirect it to OCD or USART stream, do you know if it is feasible ?
Balau
2010/10/19
If you have an operating system running on your target, then -pg is OK. Otherwise -pg can’t work, for example because it needs a filesystem to write “gmon.out” during execution. The toolchain must also support it.
With the method I explained, it is quite trivial to send data to your USART instead of writing to file, it just needs to remove the fprintf calls and add functions to write data on the correct serial port registers. I don’t know about OCD but I suppose it is more complex because it involves having a JTAG adapter and a way to send your custom debug info with it.
Kaiwan
2011/03/22
Hi,
If I may, I have a kind of unrelated question to this post:
how exactly did you get the ‘syntax highlighter’ plugin (i assume that’s the one you’re using above) to work with this wordpress blog?
It’s really cool!
Am sure others would like to know as well!
TIA!
Balau
2011/03/22
I didn’t have to do anything, the syntax highlighter is already enabled in wordpress.com blogs: see Posting Source Code.
For wordpress.org blog installations, there’s a plugin available.
Kaiwan
2011/03/23
Hey, thanks again! it works. indeed
Silly of me…
Mahmoud Eltahawy
2012/04/26
Hi ,
Can I use the addr2line with shared library as input instead of executable??
Balau
2012/04/26
Yes you can, but you need to give addr2line the address as an offset from the load address of the shared library. The absolute address that you get run-time won’t work. You can find the load address of the shared library run-time with the dladdr function.
Sumi Dodger
2012/08/28
i added this trace.c in my project and compiled in Gxlinux and got this why this so some one help me………..
my project also consists of main.c
GxLinux- A complete embedded Linux development platform
[root@GxLinux src]# gcc -finstrument -functions -g -c -o main.o main.c
cc1: error: unrecognized command line option “-finstrument”
cc1: error: unrecognized command line option “-functions”
Balau
2012/08/28
You should write “
-finstrument-functions” without the space, you currently have “-finstrument -functions“Sumi Dodger
2012/09/05
I want that all the files of my project get traced using this function
I have added a file(trace.c) in my code containing these functions
but problem is that i have to run these commands for a particular file like main.c here
gcc -finstrument-functions -g -c -o main.o main.c
gcc -finstrument-functions -g -c -o main.o main.c
$ gcc -c -o trace.o trace.c
$ gcc main.o trace.o -o main
$ ./main
foo
$ cat trace.out
Is there any possible way to trace all the files (near about 70) at a time so that i come to know, what was the particular path or flow of functions was.
or better way will be that if a function can be created for running these commands.
Sumi Dodger
2012/09/06
someone plz give a solution………….
Balau
2012/09/06
I don’t know if I understand your problem.
It seems that what you need is a build system.
I suggest using GNU make.
I am giving you a quick example:
Create a file called “Makefile” where you have your C source files. Suppose your C source files are “main.c”, “foo.c” and “trace.c” The makefile contains:
main: main.o foo.o trace.oCFLAGS = -g -finstrument-functionstrace.o: CFLAGS = -gThen in the same directory run "make". You should see:
$ makecc -g -finstrument-functions -c -o main.o main.c
cc -g -finstrument-functions -c -o foo.o foo.c
cc -g -c -o trace.o trace.c
cc main.o foo.o trace.o -o main
You can then fill the list of object files needed by "main" and let "make" compile them.
For everything you need to know on makefiles, see the GNU Make manual.
Joseph Hillery
2012/09/14
Very useful! One thing omitted from code sample was to exclude the trace routines from the instrumentation. Otherwise they will recursively fire until stack is exhausted and you get a SIGSEQV.
void __cyg_profile_func_enter(void *this_fn, void *call_site)
__attribute__((no_instrument_function));
void __cyg_profile_func_exit(void *this_fn, void *call_site)
__attribute__((no_instrument_function));
Balau
2012/09/14
Yeah, in the compilation commands that I indicated the “
trace.c” source file is not compiled with “-finstrument-functions” option, so the trace routines were not instrumented anyway, but it’s a good idea to enforce it also with an attribute.alfred
2013/01/26
To resolve the addresses at run time you could also use the dladdr() function:
ex:
#include <stdio.h>#define __USE_GNU
#include <dlfcn.h>
void __cyg_profile_func_enter (void *this_fn,
void *call_site)
{
Dl_info info;
if (dladdr(this_fn, &info) != 0) {
printf("%s", info.dli_sname);
}
}
Michael R. Hines
2013/01/28
I’ve improved on this tutorial here: http://michael.hinespot.com/tutorials/gcc_trace_functions
Now you can:
1. trace your program with fuzzy, human-readable function names
2. easily trace external libraries linked to by your program
3. blacklist/whitelist functions that you don’t care about
4. output trace results in human-readable format
Balau
2013/01/28
Thanks for improving my work! Glad to have inspired you.
Pierre Rasmussen
2013/04/22
Nice post!
Do you have any trick for handling static functions?
Balau
2013/04/22
What about them? My example works
in the same wayalmost the same even if function foo is static or inline.Correction: I tried some more, and it seems to have some problems detecting the caller when the callee is inlined.