Debugging Without The Debugger

by Dave Harms

Published 1999-03-29    Printer-friendly version

I have a guilty secret: I almost never use the Clarion debugger. It's certainly not that my code is so amazingly clean that I never have to debug my programs. It's just that I've always found the debugger awkward to use, in part because the debugger doesn't work together with the source editor. For instance, I think I should be able to set a breakpoint in a source embed and run to that point. I should be able to add watch variables from within the Application Generator. These and other features would make the debugger much more useful to me.

On the other hand, even if Clarion had a terrific debugger I probably wouldn't use it much. A tool that lets me single step through my code has limited usefulness, mainly because of my lousy short-term memory. I simply can't remember more than a few steps back in my code, and I quickly become confused as to what exactly happened to get me to wherever I currently am.

What I really find useful is a log that shows me what procedures or methods were called, and what the contents of particular variables were at certain points in the code. Ideally this log will also indent the procedure/method calls, can be displayed on-screen, or can be saved to disk.

I've written a pair of classes called cciDebugClass and cciProfilerClass to handle these kinds of basic debugging/tracing tasks, and they are available as part of the Clarion Open Source Project.

In this article I'll explain some of the underlying concepts and design ideas behind these classes. You may wish to download the class (the zip includes cciProfilerClass and a global extension template) so you can see the full source as you read. Click here for installation and usage instructions.

You may also want to refer to the article The ABCs of OOP - Part 1 which uses as its example a stripped-down version of cciDebugClass.

NOTE: This article discusses version 1 of cciDebugClass and cciProfilerClass. The most significant changes from version .9 to version 1 are the use of manual constructors instead of automatic constructors to avoid GPFs in handcoded projects, and the addition of a global extension template to handle the creation, initialization, and cleanup of the debugging/profiling object. For version 0.9 documentation click here.

The Debugging Class

The core functionality of cciDebugClass is the ability to trace messages in an internal queue and display these messages on screen upon request, or write them to a file. The queue which stores these messages is TraceQ.

TraceQ &cciTraceQueue,PROTECTED

TraceQ is of type cciTraceQueue, which is declared as follows:

cciTraceQueue              QUEUE,TYPE
IndentLevel                   SHORT
Text                          STRING(1000)
                           END

The IndentLevel variable in the queue is there to help with formatting text for display, particularly when showing procedure call trees as seen in Figure 1. Although the text field in the queue is much larger than will usually be necessary this doesn't result in excessive memory usage since queue field entries are run-length compressed.

Figure 1. Displaying a procedure call tree.

Initializing The Debug Class

TraceQ is a reference rather than an actual queue because queues cannot be declared statically inside a class. Instead, cciDebugClass uses a reference and creates the queue on the fly with the NEW operator. Listing 1 shows the Init() method source.

Listing 1. The cciDebugClass initialization code

cciDebugClass.Init                          procedure
   code
   SELF.TraceQ &= NEW(cciTraceQueue)
   SELF.ThreadQ &= NEW(cciThreadIndentQueue)
   SELF.ThreadQ.Thread = 1
   SELF.ThreadQ.IndentLevel = 1
   ADD(SELF.ThreadQ)
   SELF.NextLineToWrite = 1
   SELF.CacheSize = 50
   SELF.Disable = False
   CREATE(TraceLog)
   SELF.CollapseQ &= NEW(cciSimpleQueue)
   SELF.EventNameQ &= NEW(cciEventNameQueue)
   SELF.AddEvent('EVENT:Accepted      ',01H)
   ! Multiple calls to AddEvent omitted for brevity

As Listing 1 shows, TraceQ isn't the only queue in this class. ThreadQ is used to track the last indent level reached in any given thread when the program switches to a different thread. This way the class can resume logging messages at the appropriate level when the thread is resumed. The Init() method creates one record in the ThreadQ for the main program thread, and starts the indent level at 1.

Next the Init() method sets some caching properties. Although the class does create a log file, it doesn't write every trace message out immediately on receipt. That would waste a lot of I/O and greatly slow any program being debugged. Instead it caches as many messages as specified by the CacheSize property. The NextLineToWrite variable keeps track of the first unwritten line.

The call to CREATE(TraceLog) effectively empties any existing log by creating a new file called trace.log. The file itself is declared outside the class definition but inside the class source file. Files cannot be declared inside a class structure, although they can be declared inside a method. Another option here would be to have a reference to a file (and the single field of the file) and initialize it accordingly, but as there is only one method that writes records to the file it's probably easier just to derive a class and override that method if you want to change the way the log is written.

After the trace log is created several additional queues are created. CollapseQ has to do with the class's ability to display a trace in tree view, as shown in Figure 1. That trace was created by cciProfilerClass which is derived from cciDebugClass, and shows all of the ABC method calls. For many procedures, particularly browses, there are some methods which are called numerous times and which seldom have any embedded code. All messages which are added to TraceQ are first checked against the strings stored in CollapseQ, and if there's a match the indent level is given a negative sign which causes the tree to contract at that level.

CollapseQ was added to reduce the clutter of logs created by the derived cciProfilerClass. Ordinarily something added solely for a derived class would go in the derived class, not the parent class, but it seemed plausible that someone might want to have this capability even when not using cciProfilerClass.

The final queue created by the Init() method is EventNameQ. This queue is used to store a list of event numbers and their corresponding names. You can translate an event number using the GetEventName() method. If you wanted to see what events are being generated in a procedure, put the following code at the top of the accept loop (assuming you have a debug object called dbg).

dbg.Trace('Event ' & GetEventName(EVENT())

The global extension template that accompanies the debugging/profiling classes can add this code to all of your procedures automatically, if you wish, thereby giving you a complete log of all program events.

You might wonder why GetEventName() does a lookup in a queue instead of using a large case or execute statement. Although the standard Clarion event numbers are fixed, you can create and post your own events (using numbers from EVENT:User on up). The AddEvent() method provides a standard means of informing the class of the events it needs to track, and it also allows you to override the standard naming of the Clarion event codes without having to recompile the class.

Other Properties

Some class properties are given default values in the declaration rather than in the Init() method. AutoCollapse is a flag that indicates whether a check should be made against entries in CollapseQ. A false value will improve performance slightly. CurrThread simply tracks the current thread number. This value is checked against the value returned by the THREAD() function on each call to Trace() if the ThreadAware property is true. IndentLevel keeps track of the current indenting, and IndentSpacing specifies how many spaces to use per indent level. IndentSpacing comes into play if you choose a non-tree display of the trace log, and when the log is written to disk.

LevelsToShow specifies how many levels of indent should be shown expanded. This does not override level collapsing via CollapseQ. StayOnLastLine applies only to the toolbox view (see ShowTraceToolbox(), below) and if true forces the list box cursor to the bottom of the list whenever a new message is logged. Warning: this can have the unwanted side effect of always forcing the focus to the toolbox's list control!

TreeView is a flag that indicates if the trace toolbox displays records in tree view or in an non-tree view with space-indented lines.

Methods

I've alluded to some of the methods, but here's a complete listing.

AddEvent PROCEDURE(STRING EventName,long EventNo)

Ordinarily only used during initialization to load the standard Clarion event numbers and their corresponding names.

AddCollapseString PROCEDURE(STRING Collapse)

Not used in initialization of this class, but there for the use of cciProfilerClass which is a derived class. Specifies strings which are to be automatically collapsed when the trace is displayed in tree view.

FindEvent PROCEDURE(LONG EventNo),BYTE,PRIVATE

Used internally to retrieve the EventNameQ record for a given event number.

FormatQueue PROCEDURE(BYTE TreeView=False)

Switches the display queue between tree view and space-indented view. The trace log is always written in space-indented form, which includes a three digit indent number on the left side of each line. Note the use of the omittable TreeView parameter with a default value of False.

FormatText PROCEDURE(STRING Text,BYTE TreeView=False),string

Formats a single line of text for either tree view or space-indented view.

GetEventName PROCEDURE(LONG EventNo),STRING

Returns the name of the specified event.

GetThread PROCEDURE(LONG Thread)

If the ThreadAware property is true, this method detects thread changes and records the change in the trace. It also creates new ThreadQ records as needed and maintains indent levels on a thread-by-thread basis.

HideTraceToolbox PROCEDURE

Hides the trace toolbox window (see ShowTraceToolbox()).

Init PROCEDURE

Initializes the class. In earlier versions this was an automatic construct method.

Kill PROCEDURE

Cleans up data created by the class. In earlier versions this was an automatic destruct method.

SetIndentLevel PROCEDURE(SHORT IndentLevel)

Specifies the current indent level. This is provided only so that user can override indent levels if desired.

ShowTraceToolbox PROCEDURE

One of two ways to display trace logs on-screen, the other being ViewTrace(). ShowTraceToolbox() starts a display procedure on a separate thread. This isn't quite as easy as you might think. You can't simply START() a method because the first parameter of every method is in fact the class itself. (A side effect of this is that with methods you must always account for the hidden class parameter when using OMITTED() to check for missing parameters.) The way around this is to define a normal non-class procedure and call it. See TraceToolbox() for more.

Trace PROCEDURE(STRING Text)

This is the workhorse method which adds a message to the trace queue. It also calls the WriteTrace() method whenever the cache is full.

TraceIn PROCEDURE(STRING Text)

Increments the indent level and calls Trace(). Should be called when entering a procedure. cciProfilerClass can do this automatically for you.

TraceOut PROCEDURE(STRING Text)

Decrements the indent level and calls Trace(). Should be called when leaving a procedure. cciProfilerClass can do this automatically for you.

ViewTrace PROCEDURE

Displays an application modal window with the contents of the trace queue.

WriteTrace PROCEDURE,VIRTUAL

Writes cached messages to the trace log. As this is a virtual method you need only to override it to change how the log file is written.

TraceToolbox PROCEDURE(STRING Addr)

This procedure isn't part of the class, but is prototyped in the local map at the top of the class source file. The whole idea of a trace toolbox is to be able to see messages on screen as they are added, and since you can't start a class method you have to use a regular procedure.

Of course it isn't quite that simple. The procedure still needs to have some knowledge of the class, or it won't be able to display the queue which is inside the class. Furthermore, the procedure is an actual code entity that will be run. The class isn't. It has a TYPE attribute which means that no memory is allocated to it. You have to create an instance of the class to use it, but you have no way of knowing what that instance will be. The instance of cciDebugClass is going to have to provide that information to TraceToolbox() at runtime.

The solution is to create a reference of type cciDebugClass inside the TraceToolbox() procedure:

dbg &cciDebugClass

The ShowTraceToolbox() method passes its own address (which is determined at runtime) as a parameter to START():

SELF.ToolboxThread = START(TraceToolbox,25000,ADDRESS(SELF))

START() only accepts string parameters (up to three), so the address, which is a long, is going to be cast to a string. TraceToolbox() contains a LONG which receives the address. Clarion's automatic type conversion handles the cast.

DebugObjAddress = Addr

One last step assigns the LONG address to the reference:

dbg &= (DebugObjAddress)

Note the use of parentheses to evaluate the LONG variable. Without these you'll get an illegal reference assignment, since &= expects either a function return value or an appropriate data type.

From this point on TraceToolbox() simply references its own dbg reference whenever it needs to work with something from the debug object. The code

?list{PROP:From} = dbg.TraceQ

sets the list box's FROM property to the object's trace queue.

The Profiling Class

When I wrote my first non-OOP trace library I wanted the log to show when I entered and left procedures. I did that by embedding code at the start and end of each procedure, and it was a tedious business at best. Happily Topspeed provided a means of automatically generating procedure calls in Clarion version 4, though that probably wasn't their intention.

Since version 4 Clarion has shipped with a file called profile.clw, which you can find in your libsrc directory. This file contains a very bare-bones example of how you can intercept the start and end of each procedure (and routine). From this source you can see that the intent is to allow you to profile how much time is used by each of your methods. This capability is in the works for cciProfilerClass, but at the moment it simply provides a way of logging method calls which cciProfilerClass exploits.

To generate automatic method call logs, choose Project|Edit from the main menu, click on the Properties button for the entire application, and enable full debugging. On the Defines tab enter

profile=>on

To turn on profiling for the entire application. You'll also need to turn off profiling for the debugging and profiling classes – this is explained in more detail in the usage instructions.

When debugging and profiling are both turned on, your application at runtime will look for the following two procedures:

EnterProc(UNSIGNED Line,*CSTRING Proc,*CSTRING File),NAME('Profile:EnterProc') LeaveProc(),NAME('Profile:LeaveProc')

If these procedures have been linked in, they'll be called each time your application enters or leaves a procedure or routine. cciProfilerClass uses these profiling hooks to log corresponding messages to the trace queue via the ProcStart and ProcEnd methods.

ProcStart and ProcEnd

ProcStart does a bit of massaging of method names to change them from the format

method(class,param1,param2)

to the more familiar

class.method(param1,param2)

ProcStart() also does a bit of fiddling with routine calls. It's unfortunately the case that when you return from a routine, you get a ProcEnd() on the procedure but not on the routine. Since cciDebugClass keeps a stack of indent levels, this can result in mismatches in the log. It gets worse if there have been a succession of routine calls (each with a ProcStart()) before the return. ProcStart() gets around this by using a hard coded list of the problem ABC routines.

ProcEnd() simply decrements the indent level, and that's about all there is to say about the methods except that Init() also makes a few calls to CollapseString() to avoid cluttering up the trace with repetitive calls (although the disk log will contain all the trace messages).

Exploring ABC with cciProfilerClass

You can use cciProfilerClass to get a window on how your ABC (or legacy) application functions. Following the usage instructions set up your application for profiling, and call the ShowTraceToolbox() method from a suitable menu option or embed point. With the trace toolbox active you can see the method calls onscreen as they happen, along with any trace statements you've inserted. If you're using the global extension template, go to the Options tab and check Record All Events. This will add messages recording all windows events to the log so you can see how ABC responds to user actions.

Tracking GPFs

You can use the profiling class to quickly track down GPFs. Set up your application to do procedure as described above, and on startup set the CacheSize property to 1. That will force each message to be written out to trace.log immediately. Let the program run to GPF, and then examine trace.log to find out the last procedure/method call which succeeded. From this point you can use the debugger or additional trace statements to uncover the problem.

Possibilities

There are a number of enhancements I'd like to see added to these classes. As I've mentioned, the original intent of the EnterProc() and LeaveProc() procedures is to enable procedure profiling which can provide detailed information about how much time is spent on individual methods on a per-call and total calls basis, and on how many times a given method is called. This is invaluable when you have performance issues to address. cciProf.clw already contains prototypes for 16 and 32 bit API functions used to get system clock times with a much finer increment than the 1/16 of a second afforded by the CLOCK() function.

cciDebugClass could also be enhanced with watch variables by means of a queue of ANY variables with the value displayed on the trace toolbox, or reported along with each trace message, or on a specific method call, or only when it changed.

You're free to modify these classes and distribute the modified versions, but keep in mind that these classes are (as of version 1) covered by the Developers' Open Source License, and all changes you make are automatically covered by that license.

---

David Harms is an independent software developer and the editor and publisher of Clarion Magazine. He is also co-author with Ross Santos of Developing Clarion for Windows Applications, published by SAMS (1995), and has written or co-written several Java books. David is a member of the American Society of Journalists and Authors (ASJA).

Printer-friendly version

Copyright © 1999-2008 by CoveComm Inc. All Rights Reserved. Reproduction in any form without the express written consent of CoveComm Inc., except as described in the subscription agreement, is prohibited.

Clarion Magazine ISSN 1718-9942