Function Logging
Volume Number: 8
Issue Number: 7
Column Tag: C Workshop
Function Logging in Think C 
For debugging, optimizing, and better understanding a program’s
execution path
By Eric Shapiro, Ann Arbor, Michigan
About the author
Eric Shapiro’s works include Business Simulator®, EzTape®, and two new
QuickTime™ programs: Spectator™, a screen recorder from Baseline Publishing and
VideoBeep™, a silly Control Panel from Sound Source Unlimited.
Eric has taught Mac programming seminars for Apple and developed the course
materials for Apple’s Macintosh Device Driver seminar. He is best known, however, as
the author of everyones favorite singing trash can, The Grouch.
This article presents a simple way to log all function calls into a text file using
Think C 5.0. The technique presented here is useful for debugging, optimizing, and
obtaining a better understanding of a program’s execution path.
In the old days before source level debugging, function logging was an important
way to debug Mac programs. On one of my first Mac projects, I remember sending
function names out the serial port to a machine running a terminal program in order to
figure out where the program was crashing. At MacHack this year, Marshall Clow from
Hewlett Packard showed how to log function calls to MacsBug in MPW. Preferring Think
C to MPW, I decided that I’d do a similar project for Think C. This article presents the
results.
To Use the Logger
If all you want to do is use the function logger, here’s what you need to do:
• Add the file LogToFile.c to your Think C project.
• Add the file ANSI or ANSI-Small to your project (for some string utilities).
• Turn both the profiling and stack frame options on for the project.
• Call LogInit during program initialization (with appropriate parameters).
• Call LogDInit during program de-initialization.
• Recompile your code.
That’s all there is to it! You can control logging more precisely as follows:
• The following line of code turns profiling on for an entire file (if it appears
outside of all functions) or for a single routine (if it appears within a function):
/* 1 */
#pragma options( profile, force_frame )
• Likewise, the following line of code turns profiling off:
/* 2 */
#pragma options( !profile, !force_frame )
• You can determine if logging is active at compile-time using:
/* 3 */
#if _option( profile )
• Call SetLogState( true ) or SetLogState( false ) to turn logging on or off during
program execution. You can do this via a menu selection, for example.
• Call SetLogFlush( true ) or SetLogFlush( false ) to turn flushing on or off during
program execution. Performance suffers considerably when flushing is active,
but it can help find the location where a crash occurs.
Note: Writing to disk when debugging a program can be a dangerous activity. Be
sure you have adequate backups before trying any new debugging technique.
Note: By default, the function logger handles calling depths up to 100 levels. This
should be sufficient for all but the most recursive programs. You can change the
constant kMaxLogDepth to control the maximum depth.
How The Logger Works
When profiling is active, Think C generates a call to the function _profile_ at the
beginning of every function call. Actually, only functions that generate stack frames
call _profile_, which is why we turn on the stack frame option as well (stack frames
are described below). The _profile_ function has the following form:
/* 4 */
void _profile_( void *functionNamePString )
The first version of _profile_ I wrote simply logged the function name to a file.
While this is adequate for some uses, I really wanted to create an indented list of
function calls so a programmer can tell exactly who called each function. To do this,
our code needs to be notified when a function exits as well as when it is entered. Here’s
where life gets a bit complicated.
Unfortunately, Think C’s profiler doesn’t generate a function call whenever a
function exits. I looked at Think C’s profiler source code and used a similar technique
for my logger. The technique involves replacing return addresses on the stack with the
address of our own routine. When a function exits via an rts instruction, it will
unknowingly call our exit handler. Our exit handler will decrement a depth counter,
write some text to the log file, and jump to the original return address. To understand
how we trace back the stack to find return addresses, we need to know exactly how
Think C handles stack frames.
Stack Frames
Before and during function execution, space must be allocated for the following
items:
• The function’s parameters
• The caller’s return address
• The function’s local variables
• Additional information, such as register contents, that the function may want to
store
The first two items, the parameters and return address, are placed on the
program stack by the calling code. Space for the the local variables and register storage
is also allocated on the stack, but by the function itself. For convenience, the compiler
uses register A6 to reference local variables while the stack pointer itself can be
lowered and raised during function execution. The previous value of A6 is also placed
on the stack so the compiler can easily clean up the stack when a function exits.
If FuncA calls FuncB, and FuncB calls FuncC, the stack looks like that shown in
Figure 1.
As you can see, register A6 always points to the start of a linked list of previous
A6 values. This is how debuggers such as MacsBug can back-trace function calls (using
the SC command). In the _profile_ routine, we need to find the return address of the
function that called the function that called us. The assembly language code finds this
value on the stack at 4 + the previous A6 value. We save the old return address in a
global array before modifying the stack so we know where to return to when our exit
handler is called.
Note: If Think C’s force stack frame option is not active, the compiler doesn’t
generate a stack frame for functions that have no local variables or parameters. Our
_profile_ code is not called for these functions.
Sample Output
The code shown below produces the very simple log file also shown below. Note
that the recursion in Func1 works properly. The braces in the output allow you to
select an entire function using Think C’s Balance command.
/* 5 */
void DoSomething( void )
{
Func1();
Func2( 10 );
}
void Func1( void )
{
static short x = 0;
if ( ++x < 2 )
Func1();
}
short Func2( short x )
{
return( 2 * x );
}
Here is the sample output from the code:
/* 6 */
DoSomething
{
Func1
{
Func1 {}
}
Func2 {}
}
A simple object-oriented example produces the following output. Note how easy
it is to follow the calling sequence of the constructors and destructors for both a base
class and a child class.
/* 7 */
DoSomeOopStuff
{