Log every call and exit in embedded system

Log every call and exit in embedded system

[John Zoidberg]

Hi,

I am studying a FOSS embedded OS and would like to understand its
callgraph (especially assembly calls during OS initialization).
Since this is an embedded OS it means I have no access to profiling or
coverage features from GCC.
I've also looked into GDB manual for tracing and logging, but didn't
found anything that can solve my problem in a direct way. I tried
backtrace but couldn't get any usefull information.
The idea is to understand its callgraph, so it's a one time operation.
I'm not looking for profiling or statistics (of course that being able
to do this would be great).

ATM, my idea is to create a script that:
(1) parses objdump output to get symbols and
(2) create a GDB command file that sets a breakpoint in every symbol.
I'll then read the commands file, run the target and manually take
note of the function name and source code filename (because there are
symbol name collisions) everytime a breakpoint occurs.

Problems with this approach:
(1) unable to tell when a function returns, so it's impossible to tell
what is the level at which functions are being called. This is
especially true in assembly files (i.e., was it a JMP or was it a
RET?)
(2) unable to track macros and inline code :(
(3) can GBD handle thousands of breakpoints?
(4) it's a slow manual process because when a breakpoint fires I'll
have to take note of the symbol:filename and issue a continue



Is this the only way? Can anyone give me any suggestions or hints?




OFFTOPIC: how can I define string variables for GDB command files? I
tried "set" but it doesn't accept strings. What I would like to do is
this:
export SOURCE_ROOT=/path/to/source/code/with/lots/of/dirs/
dir $SOURCE_ROOT
dir $SOURCE_ROOT/core
dir $SOURCE_ROOT/util
dir $SOURCE_ROOT/drivers
dir $SOURCE_ROOT/drivers/ethernet


Thanks in advance!

Re: Log every call and exit in embedded system

[Daniel Jacobowitz]

On Sat, Mar 24, 2007 at 08:05:11PM +0000, John Zoidberg wrote:
> Hi,

> I am studying a FOSS embedded OS and would like to understand its
> callgraph (especially assembly calls during OS initialization).
> Since this is an embedded OS it means I have no access to profiling or
> coverage features from GCC.

Actually, it doesn't mean that at all.  It means you have to go to a
little more work to recover the profile data, though.

GDB won't be able to help you much with this; a simulator or hardware
debug interface may be able to do much better.

> (3) can GBD handle thousands of breakpoints?

Not really.  It will get very slow.

> Is this the only way? Can anyone give me any suggestions or hints?

If you're not too interested in recursive calls, and you're not
talking about too large an instruction trace, you could record the
output of stepi and then analyze it looking for jumps and calls.
It may be simpler if the data collection time is small enough for your
needs.

> OFFTOPIC: how can I define string variables for GDB command files?

You can't.  This is one of the reasons I've been talking about Python
integration; it's not a small problem to solve, because of the way we
define our variables.


-- 
Daniel Jacobowitz
CodeSourcery

Re: Log every call and exit in embedded system

[Andrew STUBBS]

John Zoidberg wrote:
> Is this the only way? Can anyone give me any suggestions or hints?

The way profiling works is that the compiler inserts a call to a 
function (mcount?) at each function call (*). I'm not sure on the 
precise rules for this, or whether it varies between target types, but 
these are details that you can certainly dig up from somewhere.

If you provide your own implementation for this function then it can do 
anything you like. Printing a call graph at run time should not be too 
hard (though it may be tricky if your print mechanisms are also 
instrumented).

* It typically also adds some kind of interrupt to count to time spent 
in various parts of the program, but that is probably not interesting here.

Hope that helps,

Andrew

Re: Log every call and exit in embedded system

[mathieu lacage]

On Mon, 2007-03-26 at 11:03 +0100, Andrew STUBBS wrote:
> John Zoidberg wrote:
> > Is this the only way? Can anyone give me any suggestions or hints?
> 
> The way profiling works is that the compiler inserts a call to a 
> function (mcount?) at each function call (*). I'm not sure on the 
> precise rules for this, or whether it varies between target types, but 
> these are details that you can certainly dig up from somewhere.

with gcc, -finstrument-functions

generates calls to:

         void __cyg_profile_func_enter (void *this_fn,
                                         void *call_site);
          void __cyg_profile_func_exit  (void *this_fn,
                                         void *call_site);

> If you provide your own implementation for this function then it can do 
> anything you like. Printing a call graph at run time should not be too 
> hard (though it may be tricky if your print mechanisms are also 
> instrumented).

I actually wrote a tool to do this: http://cutebugs.net/bozo-profiler/

Mathieu

Re: Log every call and exit in embedded system

[Michael Snyder]

On Sat, 2007-03-24 at 20:05 +0000, John Zoidberg wrote:
> Hi,
> 
> I am studying a FOSS embedded OS and would like to understand its
> callgraph (especially assembly calls during OS initialization).
> Since this is an embedded OS it means I have no access to profiling or
> coverage features from GCC.

That actually depends.  Don't dismiss the possibility too lightly.

> I've also looked into GDB manual for tracing and logging, but didn't
> found anything that can solve my problem in a direct way. I tried
> backtrace but couldn't get any usefull information.

Not sure what you mean by that, but you may be misunderstanding
what "backtrace" does.  It prints the current call stack at any
given time.  You would want at least some of this info if you 
need to construct a callgraph, but it's not sufficient.

> The idea is to understand its callgraph, so it's a one time operation.
> I'm not looking for profiling or statistics (of course that being able
> to do this would be great).

Now -- there are static tools that will construct a callgraph
simply by analyzing the source code.  If this isn't what you
want, what is it that you need in addition to a static callgraph?

Some sort of frequency counts?  You say you're not looking for
statistics...

> ATM, my idea is to create a script that:
> (1) parses objdump output to get symbols and
> (2) create a GDB command file that sets a breakpoint in every symbol.
> I'll then read the commands file, run the target and manually take
> note of the function name and source code filename (because there are
> symbol name collisions) everytime a breakpoint occurs.

Not sure what you mean by "manually".  GDB will print that info 
automatically each time a breakpoint is hit.  You can just pipe
the output to a file.

You can attach a command script to each breakpoint to tell gdb
to continue, so that you don't have to do that manually either.

> Problems with this approach:
> (1) unable to tell when a function returns, so it's impossible to tell
> what is the level at which functions are being called. This is
> especially true in assembly files (i.e., was it a JMP or was it a
> RET?)

Presumably your breakpoints will be at the function entry point.
You won't get any events on RET.  You'll only get call events, 
or potentially JMP events in assembly code.

> (2) unable to track macros and inline code :(

GDB has some mechanisms for both -- look in the manual.

> (3) can GBD handle thousands of breakpoints?

No problem -- but it has to set and unset them at every stop event, 
and that requires a message cycle between host and target.  The time
it takes to start and stop will increase linearly with the number
of breakpoints.

> (4) it's a slow manual process because when a breakpoint fires I'll
> have to take note of the symbol:filename and issue a continue

See above, there is no reason why that needs to be done manually.


> 
> OFFTOPIC: how can I define string variables for GDB command files? I
> tried "set" but it doesn't accept strings. What I would like to do is
> this:
> export SOURCE_ROOT=/path/to/source/code/with/lots/of/dirs/
> dir $SOURCE_ROOT
> dir $SOURCE_ROOT/core
> dir $SOURCE_ROOT/util
> dir $SOURCE_ROOT/drivers
> dir $SOURCE_ROOT/drivers/ethernet

You may want to use some scripting system to drive this.
Shell script, makefile, expect, tcl, python...

Re: Log every call and exit in embedded system

[John Zoidberg]

On 3/26/07, Michael Snyder <Michael.Snyder@palmsource.com> wrote:
> On Sat, 2007-03-24 at 20:05 +0000, John Zoidberg wrote:
> > Hi,
> >
> > I am studying a FOSS embedded OS and would like to understand its
> > callgraph (especially assembly calls during OS initialization).
> > Since this is an embedded OS it means I have no access to profiling or
> > coverage features from GCC.
>
> That actually depends.  Don't dismiss the possibility too lightly.
>
> > I've also looked into GDB manual for tracing and logging, but didn't
> > found anything that can solve my problem in a direct way. I tried
> > backtrace but couldn't get any usefull information.
>
> Not sure what you mean by that, but you may be misunderstanding
> what "backtrace" does.  It prints the current call stack at any
> given time.  You would want at least some of this info if you
> need to construct a callgraph, but it's not sufficient.

What I mean is that due to the nesting level of calls I'm unable to
get a useful call stack. I can see the call stack at a certain level,
but I can't see what happened in deeper levels (and a lot happens
there).

> > The idea is to understand its callgraph, so it's a one time operation.
> > I'm not looking for profiling or statistics (of course that being able
> > to do this would be great).
>
> Now -- there are static tools that will construct a callgraph
> simply by analyzing the source code.  If this isn't what you
> want, what is it that you need in addition to a static callgraph?

I suspect those tools won't support assembly modules and will have
problems with branching (i.e. I'll have to debug to know where
execution flows). But if those tools are capable of handling hundreds
of files across multiple directories they will still be useful. Since
I've not tested any, which ones would you recommend?

> Some sort of frequency counts?  You say you're not looking for
> statistics...
>
> > ATM, my idea is to create a script that:
> > (1) parses objdump output to get symbols and
> > (2) create a GDB command file that sets a breakpoint in every symbol.
> > I'll then read the commands file, run the target and manually take
> > note of the function name and source code filename (because there are
> > symbol name collisions) everytime a breakpoint occurs.
>
> Not sure what you mean by "manually".  GDB will print that info
> automatically each time a breakpoint is hit.  You can just pipe
> the output to a file.

Using "set logging"

> You can attach a command script to each breakpoint to tell gdb
> to continue, so that you don't have to do that manually either.

Using "commands"

> > Problems with this approach:
> > (1) unable to tell when a function returns, so it's impossible to tell
> > what is the level at which functions are being called. This is
> > especially true in assembly files (i.e., was it a JMP or was it a
> > RET?)
>
> Presumably your breakpoints will be at the function entry point.
> You won't get any events on RET.  You'll only get call events,
> or potentially JMP events in assembly code.

I've re-checked GDB's behavior for assembly and it (1) breaks on the
first instruction of an assembly symbol (on the jmp scenario) and (2)
I can know if it was a call by checking the backtrace.

> > (2) unable to track macros and inline code :(
>
> GDB has some mechanisms for both -- look in the manual.

I've checked the manual, made a simple test and confirmed what I
suspected: I'm unable to set breakpoints in macros/inline.

> > (3) can GBD handle thousands of breakpoints?
>
> No problem -- but it has to set and unset them at every stop event,
> and that requires a message cycle between host and target.  The time
> it takes to start and stop will increase linearly with the number
> of breakpoints.
>
> > (4) it's a slow manual process because when a breakpoint fires I'll
> > have to take note of the symbol:filename and issue a continue
>
> See above, there is no reason why that needs to be done manually.
>
>
> >
> > OFFTOPIC: how can I define string variables for GDB command files? I
> > tried "set" but it doesn't accept strings. What I would like to do is
> > this:
> > export SOURCE_ROOT=/path/to/source/code/with/lots/of/dirs/
> > dir $SOURCE_ROOT
> > dir $SOURCE_ROOT/core
> > dir $SOURCE_ROOT/util
> > dir $SOURCE_ROOT/drivers
> > dir $SOURCE_ROOT/drivers/ethernet
>
> You may want to use some scripting system to drive this.
> Shell script, makefile, expect, tcl, python...
>

Thanks for your help!

Re: Log every call and exit in embedded system

[John Zoidberg]

On 3/26/07, mathieu lacage <Mathieu.Lacage@sophia.inria.fr> wrote:
> On Mon, 2007-03-26 at 11:03 +0100, Andrew STUBBS wrote:
> > John Zoidberg wrote:
> > > Is this the only way? Can anyone give me any suggestions or hints?
> >
> > The way profiling works is that the compiler inserts a call to a
> > function (mcount?) at each function call (*). I'm not sure on the
> > precise rules for this, or whether it varies between target types, but
> > these are details that you can certainly dig up from somewhere.
>
> with gcc, -finstrument-functions
>
> generates calls to:
>
>          void __cyg_profile_func_enter (void *this_fn,
>                                          void *call_site);
>           void __cyg_profile_func_exit  (void *this_fn,
>                                          void *call_site);

I'll investigate this further.
With embedded systems there are always issues... but I think I can use
these functions to log to a buffer the address of the called functions
(and then look them up).

> > If you provide your own implementation for this function then it can do
> > anything you like. Printing a call graph at run time should not be too
> > hard (though it may be tricky if your print mechanisms are also
> > instrumented).
>
> I actually wrote a tool to do this: http://cutebugs.net/bozo-profiler/
>
> Mathieu

Your tool seems very interesting, it's unfortunate it's not ready for
embedded systems.
On the documentation you mention malloc, but some embedded systems
don't have the code for malloc. Moreover, no embedded system uses
glibc, it uses newlib, uclib, and others... this means that the code
that is linked may not have the support for it (i.e. there are missing
functions).
There is the issue of the target code (the part that is linked to the
application) must be compiled with the corresponding GCC (for the
target system).
And besides all this, there is the issue of where to log the
information or how to send it.


Thanks!

Re: Log every call and exit in embedded system

[Mathieu Lacage]

On Tue, 2007-03-27 at 12:07 +0100, John Zoidberg wrote:

> Your tool seems very interesting, it's unfortunate it's not ready for
> embedded systems.
> On the documentation you mention malloc, but some embedded systems
> don't have the code for malloc. Moreover, no embedded system uses
> glibc, it uses newlib, uclib, and others... this means that the code
> that is linked may not have the support for it (i.e. there are missing
> functions).
> There is the issue of the target code (the part that is linked to the
> application) must be compiled with the corresponding GCC (for the
> target system).
> And besides all this, there is the issue of where to log the
> information or how to send it.

The way I have implemented this is that I store in a circular buffer
(one per user thread) the address of the function. Then, I have another
thread (the manager thread) which reads data from every circular buffer
and writes it in a global log file. It also stores in this global log
file the memory map of your program whenever it changes because of a
dlopen. The thread stuff is really an optimization to avoid as much as
possible locking from the user program if I can avoid it: you could
write into the log file directly from the __cyg_* functions.

And then, there is a post-processing tool which reads the binary log and
generates a human-readable output based on the program memory map, the
symbol addresses and the debugging information found in the binaries.

There is some platform-specific code to make sure that I am notified
upon every memory map change (I place an int3 breakpoint in the r_debug
data structure to get link map changes through a unix signal). You could
avoid this problem by simply scanning the link map all the time whenever
you write a new symbol in the log file.


Mathieu
--