TweetFollow Us on Twitter

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.

Overview

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.

History

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
{
 BaseClass::BaseClass {}
 ChildClass::ChildClass {}
 ChildClass::MiscFunc
 {
 BaseClass::MiscFunc {}
 }
 ChildClass::~ChildClass {}
 BaseClass::~BaseClass {}
}

Summary

A fairly simple technique was given to log function names to a text file for any Think C project, including object-oriented ones. The technique can be used to debug and optimize programs as well as to investigate a program’s runtime activity.

Possible future additions include:

• Put more information into the log file, such as the stack and register contents.

• Make the output look better, perhaps by drawing a graph of the program’s runtime activity.

• Do some validity checking on the heap and file id to make sure that the system is in a reasonably safe state for writing.

• Optionally log information to MacsBug using DebugStr() instead of to the log file.

• Support for interrupt-driven code and trap patches

This would involve setting some semaphores, restoring the global variable context, and changing the I/O calls to be asynchronous. I don’t think it would be very difficult, but as most Mac programmers know, nothing is difficult until you have to implement it.

Good luck, and let me know if you find any bugs.

Listing LogToFile.c
/*
 LogToFile.c
 © 1992 Rock Ridge Enterprises. All Rights Reserved.

 Requires Think C 5.0x

 To use this file:
 1a) Turn on the profiling and stack frame options for your    
 entire project from the Edit/Options/Debugging dialog.
 
 1b) Or, if you prefer, add the following line to your files:
 #pragma options( profile, force_frame )
 Place it within a function to profile just that function,
 within a file for just that file, or in a header file.

 2)Call LogInit at program initialization. For example:
 LogInit( NULL, true, false, true );
 
 3)Call LogDInit at program de-initialization. For example:
 LogDInit();

 4)You can call SetLogState( true ) or SetLogState( false )
 to turn logging on and off dynamically.
*/

#include <string.h>
#include <files.h>
#include <errors.h>
#include <memory.h>
#include <pascal.h>

#include “LogToFile.h”

#define kMaxLogDepth 100  // maximum 100 calls deep

 // create Think C text files as output
#define kThinkCreatorID   ‘KAHL’
#define kTextFileType‘TEXT’

 // strings written to output file
#define kTabString ((void*) “\t” )
#define kReturnString((void*) “\r” )
#define kOpenBraceString  ((void*) “{“)
#define kCloseBraceString ((void*) “}”)
// exiting a function that called nobody
#define kSimpleExitString “ {}”  

 // write this string the top of every log file
#define kStringForNewFile ((void*) “” )

 // write this string between program runs when appending to
 // the log file
#define kStringForReusedFile((void*)
 “\r\r*****************************\r”)

 // the largest buffer we’ll need (+ a little extra)
#define kMaxStringLength  ( kMaxLogDepth + 100 )

 // the default output file is on the root of the boot disk
#define kBootVol -1
#define kRootDir 2L
#define kDefaultPName“\PLog File.txt”

 // don’t profile our profile handler
#pragma options( !profile )

/*
 Permanent storage for this file
*/
static short   gLogFileID = 0;
// vRefNum of log file’s disk
static shortgLogFileVol = -1; 
// true = call FlushVol after every write
static Boolean   gAlwaysFlush = false; 
// true = logging is active
static Boolean   gLogActive = false; 
static FSSpec  gDefaultFileLoc = { kBootVol, kRootDir,
 kDefaultPName };

/*
 Info on the calling chain
*/
// how many calls deep are we?
static long gDepth = 0;   
// the return addresses
static void *gStack[ kMaxLogDepth ]; 
// are braces needed for this function?
static Boolean   gNeedBraces[ kMaxLogDepth ];

/*
 Internal routine prototypes
*/
void    _profile_( void *pFuncName );
void    StringPtoC( void *source, void *target );
OSErr   WriteOpenBrace( short howDeep );
OSErr   WriteFunctionEntry( void *pString );
OSErr   WriteFunctionExit( void );
OSErr   WriteOpenBrace( short howDeep );

/**********************************
 LogInit - Call at program start
 fileLoc- set to NULL or a valid FSSpec for the                
 output file
 deleteOld- true => truncate old log file
 alwaysFlush- true => call FlushVol a lot (better log          
  file if you crash)
 startLogging  - true => turn logging on, false => don’t       
  log yet
**********************************/
OSErr LogInit( FSSpec *fileLoc, Boolean deleteOld,
 Boolean alwaysFlush, Boolean startLogging )
{
 OSErr  err = noErr;
 BooleancreatedFile = false;
 
 if ( !fileLoc )
 // use default if user doesn’t specify one
 fileLoc = &gDefaultFileLoc;

 // in case user calls init twice
 if ( !gLogFileID )
 {
 /*
 Create the file & open the data fork for writing.
 */
 err = FSpCreate( fileLoc, kThinkCreatorID,
 kTextFileType, 0 );
 if ( !err )
 createdFile = true;
 
 err = FSpOpenDF( fileLoc, fsRdWrPerm, &gLogFileID );
 if ( err ) goto DONE;
 }

 /*
 Clear out the file if the user requests it.
 */
 if ( deleteOld )
 {
 err = SetEOF( gLogFileID, 0L );
 if ( err ) goto DONE;
 }

 /*
 Append to the file
 */
 err = SetFPos( gLogFileID, fsFromLEOF, 0 );
 if ( err ) goto DONE;

 /*
 Setup the globals and write ‘****’ to the file.
 */
 gAlwaysFlush = alwaysFlush;
 gLogActive = startLogging;
 gLogFileVol = fileLoc->vRefNum;
 
 // write a header to the file
 if ( deleteOld || createdFile )
 err = WriteLogString( kStringForNewFile );
 else
 err = WriteLogString( kStringForReusedFile );
 
 DONE:
 if ( err )
 LogDInit();

 return( err );
}

/**********************************
 LogDInit - Call at program exit
**********************************/
OSErr LogDInit( void )
{
 OSErr  err;

 if ( !gLogFileID )
 return( openErr );
 
 /*
 Close the file and flush the data to the disk.
 */
 err = FSClose( gLogFileID );
 if ( !err )
 err = FlushVol( NULL, gLogFileVol );
 
 /*
 Clear out the globals so we know we’re not active.
 */
 gLogFileID = 0;
 gLogActive = false;

 return( err );
}

/**********************************
 SetLogState - Call to start or restart logging. 
 Returns previous state.
**********************************/
Boolean SetLogState( Boolean startLogging )
{
 Booleanresult;
 
 result = gLogActive;
 gLogActive = startLogging;

 return( result );
}

/**********************************
 SetLogFlush - Call to start or restart flushing. 
 Returns previous state.
**********************************/
Boolean SetLogFlush( Boolean startFlushing )
{
 Booleanresult;
 
 result = gAlwaysFlush;
 gAlwaysFlush = startFlushing;

 return( result );
}

/**********************************
 ClearLogFile - Call to zero out the log file
**********************************/
OSErr ClearLogFile( void )
{
 OSErr  err = noErr;
 OSErr  err2;
 
 if ( !gLogFileID )
 return( openErr );
 
 err = SetEOF( gLogFileID, 0L );

 if ( gAlwaysFlush )
 {
 err2 = FlushVol( NULL, gLogFileVol );
 if ( !err )
 err = err2;// return the first error to occur
 }

 return( err );
}

/**********************************
 WriteLogString - Write a C string to the log file
**********************************/
OSErr WriteLogString( void *cString )
{
 OSErr  err = noErr;
 OSErr  err2;
 long   numBytes;
 
 if ( !gLogFileID )
 return( openErr );

 /*
 Write the data to the file
 */
 numBytes = strlen( cString );
 err = FSWrite( gLogFileID, &numBytes, cString );
 
 /*
 Flush the volume if we always flush
 */
 if ( gAlwaysFlush )
 {
 err2 = FlushVol( NULL, gLogFileVol );
 if ( !err )
 err = err2;
 }

 return( err );
}

/**********************************
 StringPtoC - Convert a pascal string to a c string
**********************************/
static void StringPtoC( void *source, void *target )
{
 BlockMove( source, target, 1 + *( (unsigned char*)source ));
 PtoCstr( target );
}

/**********************************
 WriteFunctionEntry - called by _profile_ whenever a function  is entered

 The following string is written to the output:
 <CR> + <TABS> + FunctionName
 Where <CR> is a carriage return and <TABS> indicates 1        
 tab per depth.
**********************************/
static OSErr WriteFunctionEntry( void *pString )
{
 Str255 cString;
 unsigned char   theString[ kMaxStringLength ];
 long   count;
 OSErr  err;

 // convert func name to c string
 StringPtoC( pString, cString );   

 // start with a carriage return
 strcpy( (void*)theString, kReturnString );  
 
 // 1 tab for each level
 for ( count=0; count<gDepth; count++ )
 strcat( (void*)theString, kTabString );
 
 // the function name
 strcat( (void*)theString, (void*)cString );

 // write the string
 err = WriteLogString( theString );
 return( err );
}

/**********************************
 WriteFunctionExit - called whenever a function is exited
 by our exit handler

 If this function called another function, write the
 following string:
 <CR> + <TABS> + }
 Otherwise, write:
 {}
 Where <CR> is a carriage return and <TABS> indicates 1
 tab per depth.
**********************************/
static OSErr WriteFunctionExit( void )
{
 OSErr  err = noErr;
 long   count;
 unsigned char   theString[ kMaxStringLength ];
 
 if ( gNeedBraces[ gDepth ] )
 {
 // start with a carriage return
 strcpy( (void*)theString, kReturnString );
 // indent 1 tab for each level
 for ( count=0; count<gDepth; count++ )
 strcat( (void*)theString, kTabString );
 // then a close-brace
 strcat( (void*)theString, kCloseBraceString );
 }
 else
 {
 // just write “exit”
 strcpy( (void*)theString, kSimpleExitString );
 }

// write the string
 err = WriteLogString( theString );
 return( err );
}

/**********************************
 WriteOpenBrace - adds some tabs and an open brace to the
 output

 The following string is written to the output:
 <CR> + <TABS> + {
 Where <CR> is a carriage return and <TABS> indicates 1
 tab per depth.
**********************************/
static OSErr WriteOpenBrace( short howDeep )
{
 OSErr  err;
 unsigned char   theString[ kMaxStringLength ];
 
 // start with a return
 strcpy( (void*)theString, kReturnString );  
 // 1 tab per level deep
 while( howDeep- > 0 )
 strcat( (void*)theString, kTabString );
 // add an open-brace
 strcat( (void*)theString, kOpenBraceString );

 err = WriteLogString( theString );
 return( err );
}

/**********************************
 _profile_ - Called every time a function is entered
 
 This more complicated version does the following:
 1) Prints the function name to the file in
    an indented list
 2) Saves the return address of the caller’s
    caller into gStack[]
 3) Modifies the stack so that the caller returns
    to our code and not to its caller.
 4) Prints exit info when the function is exited and
    then jumps to the correct return address.
**********************************/
void _profile_( void *pFuncName )
{
 OSErr  err;

 if ( !gLogFileID ) return; // output file not opened
 if ( !gLogActive ) return; // logging is off
 if ( gDepth >= kMaxLogDepth ) return; // we’re too deep

 /*
 We have to put an open brace in the output if the parent      
 function hasn’t called any other functions until now.
 */
 if ( gDepth > 0 )
 if ( !gNeedBraces[gDepth-1] )
 {
 gNeedBraces[gDepth-1] = true;
 err = WriteOpenBrace( gDepth-1 );
 if ( err ) return;
 }

 // write the function name
 err = WriteFunctionEntry( pFuncName );
 if ( err ) return;

 gNeedBraces[ gDepth ] = false;
 

 /*
 Save the return address that the caller will return to.
 Modify the stack so that the caller will return to us         
 instead.
 */
 asm
 {
 ; gStack[ gDepth ] = return address where caller
 ; will return to

 ; A1 = &gStack[ gDepth ]
 lea.l  gStack, A1
 move.l gDepth, D0
 lsl.l  #2, D0
 adda.l D0, A1
 
 move.l (A6), A0 ; A0 = A6 from previous call
 move.l 4(A0), (A1); gStack[ gDepth ] = ret Addr
 
 ; Change the return address on the stack to
 ; point to our code
 lea    @FuncExit, A1
 move.l A1, 4(A0)

 addq.l #1, gDepth ; we’re one level deeper now
 
 ; return to caller
 unlk   A6
 rts
 }

 /*
 This code is executed when a profiled function exits
 */
 FuncExit:
 asm
 {
 move.l D0, -(SP); save return value onto stack
 subq.l #1, gDepth ; we’re one level more shallow

 ; write exit info to the file
 jsr    WriteFunctionExit

 ; get the real return address from our array
 ; and jump to it
 
 ; A0 = &gStack[ gDepth ]
 lea.l  gStack, A0
 move.l gDepth, D0
 lsl.l  #2, D0
 adda.l D0, A0
 
 move.l (SP)+, D0; restore return value
 move.l (A0), A0 ; A0=real return address
 jmp    (A0); jump to real return address
 }
}
 

Community Search:
MacTech Search:

Software Updates via MacUpdate

The beginner's guide to Warbits
Warbits is a turn-based strategy that's clearly inspired by Nintendo's Advance Wars series. Since turn-based strategy games can be kind of tricky to dive into, see below for a few tips to help you in the beginning. Positioning is crucial [Read... | Read more »
How to upgrade your character in Spellsp...
So you’ve mastered the basics of Spellspire. By which I mean you’ve realised it’s all about spelling things in a spire. What next? Well you’re going to need to figure out how to toughen up your character. It’s all well and good being able to spell... | Read more »
5 slither.io mash-ups we'd love to...
If there's one thing that slither.io has proved, it's that the addictive gameplay of Agar.io can be transplanted onto basically anything and it will still be good fun. It wouldn't be surprising if we saw other developers jumping on the bandwagon,... | Read more »
How to navigate the terrain in Sky Charm...
Sky Charms is a whimsical match-'em up adventure that uses creative level design to really ramp up the difficulty. [Read more] | Read more »
Victorious Knight (Games)
Victorious Knight 1.3 Device: iOS Universal Category: Games Price: $1.99, Version: 1.3 (iTunes) Description: New challenges awaits you! Experience fresh RPG experience with a unique combat mechanic, packed with high quality 3D... | Read more »
Agent Gumball - Roguelike Spy Game (Gam...
Agent Gumball - Roguelike Spy Game 1.0 Device: iOS Universal Category: Games Price: $2.99, Version: 1.0 (iTunes) Description: Someone’s been spying on Gumball. What the what?! Two can play at that game! GO UNDERCOVERSneak past enemy... | Read more »
Runaway Toad (Games)
Runaway Toad 1.0 Device: iOS Universal Category: Games Price: $2.99, Version: 1.0 (iTunes) Description: It ain’t easy bein’ green! Tap, hold, and swipe to help Toad hop to safety in this gorgeous new action game from the creators of... | Read more »
PsyCard (Games)
PsyCard 1.0 Device: iOS Universal Category: Games Price: $1.99, Version: 1.0 (iTunes) Description: From the makers och Card City Nights, Progress To 100 and Ittle Dew PSYCARD is a minesweeper-like game set in a cozy cyberpunk... | Read more »
Sago Mini Robot Party (Education)
Sago Mini Robot Party 1.0 Device: iOS Universal Category: Education Price: $2.99, Version: 1.0 (iTunes) Description: -- Children's Technology Review Editor's Choice -- | Read more »
Egz – The Origin of the Universe (Games...
Egz – The Origin of the Universe 1.0.2 Device: iOS Universal Category: Games Price: $3.99, Version: 1.0.2 (iTunes) Description: ►►► Special offer until 2nd may : get the game at 2.99€ instead of 3.99€ ! ◄◄◄ Egz is a mesmerizing mix... | Read more »

Price Scanner via MacPrices.net

Mac minis on sale for up to $100 off MSRP
B&H Photo has Mac minis on sale for up to $100 off MSRP including free shipping plus NY sales tax only: - 1.4GHz Mac mini: $449 $50 off MSRP - 2.6GHz Mac mini: $649 $50 off MSRP - 2.8GHz Mac mini... Read more
13-inch Retina MacBook Pros on sale for up to...
B&H Photo has 13″ Retina MacBook Pros on sale for $130-$200 off MSRP. Shipping is free, and B&H charges NY tax only: - 13″ 2.7GHz/128GB Retina MacBook Pro: $1169 $130 off MSRP - 13″ 2.7GHz/... Read more
Apple price trackers, updated continuously
Scan our Apple Price Trackers for the latest information on sales, bundles, and availability on systems from Apple’s authorized internet/catalog resellers. We update the trackers continuously: - 15″... Read more
SanDisk Half-Terabyte SSD Optimized for Every...
SanDisk Corporation has announced the SanDisk Z410 SSD, a cost-competitive, half-terabyte solid state drive (SSD) that enables manufacturers to design for a broad range of desktop PCs and laptops.... Read more
Churchill Downs Racetrack Selects VenueNext t...
Churchill Downs Racetrack has announced an agreement with VenueNext to implement its technology platform for the start of Churchill Downs 2016 Spring Meet, which includes the 142nd running of the... Read more
Record 700 Million Pounds of CE Recycled in 2...
The Consumer Technology Association (CTA) reports that a record-setting 700 million pounds of consumer electronics (CE) have been recycled under the eCycling Leadership Initiative (ELI). According to... Read more
Price drops on clearance 12-inch Retina MacBo...
B&H Photo has dropped prices on leftover 2015 12″ Retina MacBooks with models now available starting at $999. Shipping is free, and B&H charges NY tax only: - 12″ 1.1GHz Gray Retina MacBook... Read more
15-inch Retina MacBook Pros available for $20...
B&H Photo has 15″ Retina MacBook Pros on sale for up to $210 off MSRP. Shipping is free, and B&H charges NY tax only: - 15″ 2.2GHz Retina MacBook Pro: $1799 $200 off MSRP - 15″ 2.5GHz Retina... Read more
Target offers Apple Watch Sport for $50 off M...
Target has Apple Watch Sports on sale for $50 off MSRP for a limited time. Choose free shipping or free local store pickup (if available). Sale prices for online orders only, in-store prices may vary... Read more
Apple restocks Certified Refurbished Mac mini...
Apple has restocked Certified Refurbished 2014 Mac minis, with models available starting at $419. Apple’s one-year warranty is included with each mini, and shipping is free: - 1.4GHz Mac mini: $419 $... Read more

Jobs Board

*Apple* Retail - Multiple Positions - Apple,...
Job Description: Sales Specialist - Retail Customer Service and Sales Transform Apple Store visitors into loyal Apple customers. When customers enter the store, Read more
Restaurant Manager (Neighborhood Captain) - A...
…in every aspect of daily operation. WHY YOU'LL LIKE IT: You'll be the Big Apple . You'll solve problems. You'll get to show your ability to handle the stress and Read more
Restaurant Manager (Neighborhood Captain) - A...
…in every aspect of daily operation. WHY YOU'LL LIKE IT: You'll be the Big Apple . You'll solve problems. You'll get to show your ability to handle the stress and Read more
Simply Mac *Apple* Specialist- Service Repa...
Simply Mac is the largest premier retailer of Apple products in the nation. In order to support our growing customer base, we are currently looking for a driven Read more
*Apple* Retail - Multiple Positions - Apple,...
Sales Specialist - Retail Customer Service and Sales Transform Apple Store visitors into loyal Apple customers. When customers enter the store, you're also the Read more
All contents are Copyright 1984-2011 by Xplain Corporation. All rights reserved. Theme designed by Icreon.