Getting call stack tracing out of navit (or any C application)

This evening I’ve been working on something I’d been thinking about for a little while. As part of my trying to get involved in navit I discovered that I understand fairly little able C and very little about how navit works. Before I could be any real use I needed to be able to get more understanding on both counts.
Initially I turned to looking through the source trying to understand bits and pieces. But it can be quite difficult to follow what code is going to do without a good grasp of what gets called when. So I turned to the runtime debug that can be enabled in the config file.

This debug is a good start, but what I found was the output is flat, it’s impossible to tell which calls are even from the same method let alone at what level they are being called. Having mused outlound on the active and friendly IRC channel #navit, Gerrit picked up on my talk of instrumenting the code and wrote a blog post about what he found.

Basically a built in capability of GCC allows you to instrument start and end of function calls. It is used in the example to generate a cool image that represents the logic flow of the application.

However this just show what calls what and how often. It still doesn’t really show me what I was after… which brings me to this evening. I figured out how to use the technique to do a couple of useful things. Firstly I wanted to just output Entry:> function pointer and Exit > function pointer,  inline with Navit’s debug. Fortunately for me this defaults to stderr. And being lazy I could just write to stderr also and get the information inlined.

The second thing I wanted to achieve was to indent the debug as it went into methods, and unindent (?) when exiting. So I patched the debug.c source file to have an indent value. Whenever it writes a log statement it checks if this value is other than 0 (the default) if it is then it first prints that number of ‘-‘s before outputting  the debug line.

Similarly the Function entry and function exit output is also indented. This means that instead of this:

      navit:attr_new_from_text:enter name='name' value='timestamps'
     navit:attr_new_from_text:enter name='level' value='1'
     navit:convert_to_attrs:ret=0x500f0
     navit:attr_search:enter attrs=0x500f0
     navit:attr_search:*attrs=0x4fe48
     navit:attr_search:enter attrs=0x500f0
     navit:attr_search:*attrs=0x4fe48
     navit:attr_search:*attrs=0x50dc8
     19:29:05.884|navit:attr_new_from_text:enter name='center' value='4808 N 1134 E'
     19:29:05.884|navit:coord_parse:enter('4808 N 1134 E',1,0xbee102e0)

You get something like this:

-Entering E0x1110c
--Entering E0x334e8
---Entering E0x1ca68
--Exiting X0x1ca68
-Exiting X0x334e8
--Entering E0x11874
-Exiting X0x11874
--Entering E0x14b24
---Entering E0x36cec
--Exiting X0x36cec
---Entering E0x139fc
--Exiting X0x139fc
---Entering E0x14950
--Exiting X0x14950
---Entering E0x11d4c
--Exiting X0x11d4c
--navit:main_init:Warning: LC_ALL is set, this might lead to problems
-Exiting X0x14b24

That’s starting to look pretty good, but pointers aren’t much good to people in understanding what’s going on. This is were the clever/hacky bit comes it.

There is a tool called addr2line which uses a map file that can be gereated at compile/link time to take in a function pointer and tell you which file,function and line it comes from

After considerable messing about I came up with a long and hacky command that would find all the function pointers in my log file, perform an addr2line on them to generate a long sed script

which is then run to substitute those values in the log.

the result of which is something that looks like this:

-Entering Emain start.c:72
--Entering Eevent_glib_init event_glib.c:194
---Entering Eplugin_register_event_type plugin_def.h:31
--Exiting Xplugin_register_event_type plugin_def.h:31
-Exiting Xevent_glib_init event_glib.c:194
--Entering Eatom_init atom.c:25
-Exiting Xatom_init atom.c:25
--Entering Emain_init main.c:218
---Entering Ecallback_list_new callback.c:40
--Exiting Xcallback_list_new callback.c:40
---Entering Efile_exists file.c:236
--Exiting Xfile_exists file.c:236
---Entering Emain_setup_environment main.c:189
--Exiting Xmain_setup_environment main.c:189
---Entering Edebug_level_get debug.c:119
--Exiting Xdebug_level_get debug.c:119
--navit:main_init:Warning: LC_ALL is set, this might lead to problems
-Exiting Xmain_init main.c:218
--Entering Emain_init_nls main.c:289
-Exiting Xmain_init_nls main.c:289

Now we’re talking, now it looks something like serious trace.

So how do you do it?

first you need to apply my patch to debug.c and debug.h (who knows sometime it might even get checked into the normal version)

Then you need to run configure with something like the following:

./configure CFLAGS=”-g -finstrument-functions” –disable-samplemap LDFLAGS=”-Wl,-Map=navit.map”

Then make as normal

this compiles the code with instrumentation in place. It also creates lots of navit.map files in the source tree that are required to do the mapping to function names etc.

With this verison of navit configure the xml file to turn on the level of debug you want, I like to set timestamps=1 to give me some idea of elapsed time between debug statements.

Then execute navit like:

navit 2> debug.log

Navit will run slower with debug output runnig obviously.

Do what ever you’re trying to do, then when you close navit you have a debug.log file tha tlooks like my second example above.

Now you need to take this log file back to your source tree. (if you’re pulling it back from a device like I do from my n810 I’d advice gzip’ing it before transmitting text compresses nicely)

once back in your source tree in the same folder as the navit executable got built, you now need my hacky script UpdateLog.sh

Make it executable and run:

./UpdateLog debug.log

This will take a while to run, at the end it will of spat out a couple of files you can ignore (sedscr and sedscr2)

and it will of produced newTrace.log which should be complete with switched out function names and line numbers.

Of course the same technique applies to any C application.

If you look in the DebugPatch the code added is pretty standalone :-

/* Output trace file pointer */
static FILE *fp;  /*used in the constructor methods*/
int debugptr = &debug_timestamp;  /*used to identify pointer to static method debug_timestamp so we can exclude it from entry/exit logging*/

void main_constructor( void )
{

  fp =stderr;    /*At the moment we put all instrumented output to stderr */
    indent=0; /*set indent to 0*/
  if (fp == NULL) exit(-1); /*If we had any trouble getting a pointer to stderr then FAIL*/
}
/*Close file handle after main is finished*/
void main_destructor( void )
{
  fclose( fp );
}
/*instrumentation function that gets called on entry into any function if you compile with -finstrument-functions*/
void __cyg_profile_func_enter( void *this, void *callsite )
{
  /* Function Entry Address */
  int i=0;  /*define iterator int for use in for loop*/
 if ((int *) this == (int *) debugptr){  /*check if this function is debug_timestamp since that's a sub function within the debug statement
                                the output gets werid if you trace it's entry/exit*/
    /*don't do entry/exit for timestamp function*/
 }else{     
        indent++;     /*we've entered a function so increment the indent*/
    if (indent > 0){ /*if indent is more than 0*/
        for (i=0; i<indent; i++){
            fprintf(fp,"-");    /*prefix out output with one - for each indent level*/
        }
    }   
  fprintf(fp, "Entering E%p\n", (int *)this);  /*output a log statement showing Entering EfunctionPointer*/
 }   
}

/*instrumentation function that gets called on exit from any function if you compile with -finstrument-functions*/
void __cyg_profile_func_exit( void *this, void *callsite )
{
  /* Function Exit Address */
  /*dbg_decrement_indent();*/
     int i=0;  /*define iterator int for use in for loop*/
    if ((int *) this == (int *) debugptr){/*check if this function is debug_timestamp since that's a sub function within the debug statement
                                the output gets werid if you trace it's entry/exit*/
    /*don't do entry/exit for timestamp function*/
 }else{   
 indent--;    /*we've entered a function so increment the indent*/
    if (indent > 0){  /*if indent is more than 0*/
        for (i=0; i<indent; i++){
            fprintf(fp,"-");  /*prefix out output with one - for each indent level*/
        }
    }   
  fprintf(fp, "Exiting X%p\n", (int *)this);  /*output a log statement showing Exiting XfunctionPointer*/
}
}

The only other code I added was to make the navit projects debug output methods pay heed to the indent level in the same way as these entry/exit trace points.
the beuty of this is that you can simply compile without -finstrument-functions and it all goes away! unlike actually adding real debug statements to entry/exit of every single method