|
The trace facility, which is mostly implemented in the system macro files TDbg.s
and TDbg.sh, allows your macro to send debugging information to any of three
locations as it runs. The design lets you control exactly which trace statements generate debugging output
via two methods: by creating named trace areas in your code, and by setting one of five debugging levels for
each statement. You usually do this as a permanent part of your code (to see a system module that implements
traces very thoroughly and consistently, look at CSup.s). Then, at run time, you can
set the debugging level for each area; when a macro with trace statements runs, any trace statement whose
level is set equal to or higher than the current level for the area it belongs to will generate debug output.
Using Multi-Edit 9.10’s Trace Facility
Since you’ve shown yourself a hardy soul, unafraid to parse programmer-written prose, I make no apologies for any programmer
humor that may ensue. It might not be amiss, though, to refer any who may feel themselves ill-used in spite of my Virgillian
warning to Tom Lehrer’s remarks on Mathematicians, and How They Got That Way.
As mentioned earlier, the trace mechanism can send its output to any of three locations: the standard
Windows debug print function OutputDebugString(); the GExperts debugger (http://www.gexperts.org); and directly to a named edit window in Multi-Edit. You
specify the output target by setting the Log Number in the TDBG settings dialog (Macro | Debug
Settings… from the main menu). Log 0 sends to the first of these, Log 1 to the second, and Logs 2 through 255 to edit windows
in Multi-Edit, which will be named MSG-#.LOG, where # is
the Log Number. As a side-note, they also end up in temporary CMac global variables named ~MSGLOG-#, in case you care to write your own macro code to do something different with certain debug
output.
If you use Log 0, as most of our developers do, you need a
means of intercepting and viewing the debug output. There are a number of programs capable of
this. My personal favorite, which is both solidly written and free, is DebugView
from SysInternals(http://www.sysinternals.com). I’ll assume that’s what you’re using from here on. Just unpack it into a
directory and create a shortcut to install it. It’s a good idea to capture the
description page from SysInternals’ web site when you download it, as well, as it has a good
general description and some screen shots.Note that if you’re running on a non-NT version of Windows you’ll have to also grab the WinSock2 Update from
Microsoft, and you may need Admin privileges under Windows NT\2K\XP, as some
debug privileges aren’t granted to non-Admin users by default. The program documentation
is short, so read it before running.
There’s also a macro available for download at the Multi-Edit web site (http://www.multieditsoftware.com)
that displays a floating menu to start and stop DebugView. It also redirects the information
DebugView captures into a Pane in Multi-Edit. You may or may not prefer to use this; it still requires that DebugView be
running, although it can start and stop it itself. My personal preference is to simply Alt+Tab between
Multi-Edit and DebugView.
The Trace Statements
With those preliminaries out of the way, we’ll move on to the
fundamentals of adding traces into your code. There are four statements that actually generate code:
1) TTRACE(area
, debug_level, format_string
, [optional_args])
is the most basic, as it can occur anywhere in your code. The format string and
optional parameters work exactly like those in a C-language printf()
statement, save that the parameters it can support are the same ones CMac’s
SPrintF() macro in the SPrintF.s file supports, since it uses
that macro to format its output. The format string can include any fixed text you want, as well as the SPrintF() placeholders, which will be replaced at run-time by the then-current values of the optional
arguments that follow. Obviously, for each such placeholder in the string, there must be
a matching argument in the comma-delimited optional argument list.
TTRACE_ENTER(area, debug_level
, format_string, [optional_args
]) works exactly like TTRACE, save that it also marks the beginning of a
section of code that the trace facility tracks and formats differently. Effectively, this statement pushes an indent level
onto an internal trace stack, adding the string “==>” to the output line, and indenting all following output more deeply
than the preceding lines. Each TTRACE_ENTER statement must be paired with a TTRACE_LEAVE
statement eventually.
TTRACE_LEAVE(format_string,
[optional_args]) ends a section begun by TTRACE_ENTER,
adding the string “<==” to its output, and popping the internal trace stack, so that following lines are indented one level less.
It doesn’t require the area and debug_level arguments, as it assumes the
values of its corresponding TTRACE_ENTER
statement.
4) TDUMP_EX(area, level
, message, address
, length) dumps length bytes
of the computer’s memory to the debug output, starting at address, and preceded by
message, which can be any text. While this is a very basic and powerful command, you have to take
care that the memory locations are actually valid, or you may crash your machine. Since this statement can also output quite
a lot of data, you shouldn’t overuse it; dumping too much data can fill your disk, crash the machine or process, slow
execution to a dead crawl, or, more subtly, interfere with debugging
time-critical processes.
There are two other statements you should use consistently:
1)TDBG_DEFINE_AREA(), which indicates the start of a named trace area in the file; and
TDBG_DECLARE_AREA(), which declares an externally-defined object as a trace-debugging area; its main
use at present is to declare imported DLL functions as belonging to specific trace areas, so their debugging output can be
enabled, disabled, and captured by the trace functionality. You probably won’t find yourself using this one much; it’s there to
support features like TipWin, and would require some knowledge of program internals we haven’t made
public, as they’re in a state of flux at present.
Note that while in some sense the TDBG_DEFINE_AREA() statement defines a debugging scope, it has no
corresponding closure statement; either the end of the current file or another TDBG_DEFINE_AREA()
statement naming a different area ends the current area, although you’re free to define the same area more than once in the
same file, or in different files. Doing so effectively includes all source code within the defined area, no matter where it
physically occurs, in the same debugging scope. This is obviously useful, since the statements that create debugging output are
associated with single areas; in conjunction with carefully-crafted statement debug levels and current area debug levels, it
allows you to fine-tune the subset of statements that actually produce output during any specific debug run. It should be
obvious from the foregoing that you cannot nest trace areas.
You need only make minor modifications to the way you currently write your CMac code to
incorporate trace debugging. First, you must include TDbg.sh at the top of your source file, usually as
the first include file, followed immediately by a TDBG_DEFINE_AREA() statement; what name you choose
for the area is up to you, although it should be meaningful in the context of the module or section.
The only other thing you need do is include whichever of the four output statements described above are appropriate for your
purposes. There are a couple of caveats you should note: first, all of these trace statements are preprocessor equates; always
use the preprocessor form instead of directly invoking the functions they wrap. Second, each of these statements must occupy exactly one line, with no line breaks, or it will fail to compile.
Depending on your margin settings, it can be easy to accidentally break a trace statement across lines without noticing it by
any of several means, from simply creating long lines that auto-wrap, to manually reformatting sections containing trace
statements, to invoking Polystyle on a file. Should this happen, just rejoin the broken line,
save, and recompile.
If you just want to generate a text note in the debug output, or record the value of one or more variables at one or more
points during execution, use the TTRACE statement. If you’re
only outputting text, and not variable values, the formatting string becomes the text, and the optional argument names go
missing; if you’re outputting variable values, include one of the percent metacommands in the format string for each variable,
and a comma-delimited list of variables following the format string. For a list of the
metacommands you can use, look at the SPrintF() macro in SPrintF.s.
If you want to know what the flow of macro execution is, use the TTRACE_ENTER() and TTRACE_LEAVE() statements, which generate debugging messages when control flow enters and leaves a macro. You
always use these in pairs, with the TTRACE_ENTER() statement as the first
statement after the macro’s opening curly-brace, and the TTRACE_LEAVE() statement as the last statement
before the macro returns control to its caller. Their syntax is the same as that of the TTRACE()
statement, save that TTRACE_LEAVE() doesn’t require an area as an explicit argument, since it assumes
the same area as its matching TTRACE_ENTER(). Most commonly you’ll have them generate messages giving
the contents of passed macro arguments on entry, and return values, if any, on exit, although they can pass any information
you’d like. As noted earlier, they define a block, within which all debug output is indented one extra level.
There are a couple of gotchas you should always keep in mind when writing trace blocks with these statements. First, while
you can nest blocks (after all, if you call a macro that uses them from another that also does, you’ve
implicitly done so), you can’t overlap them—even if you try. Since TTRACE_LEAVE() statements assume that they terminate the trace block for the area specified in the last
preceding TTRACE_ENTER(), a TTRACE_LEAVE() will automatically terminate the
inner nested block. Second, never exit a block without terminating it, as this will disrupt the
nesting levels, leading to some pretty confusing output. The most common and insidious ways to accidentally exit a trace block
without properly closing it are via goto, ret, and return statements. Thus, yet another reason not to use goto statements without very
good cause. You can write trick code involving almost any control construct that can break a trace block, but unless you’re
planning on entering an obfuscated code contest, there’s never a good reason to do so.
The best way to guarantee you always get it right is to automate it. Every macro you write should have at minimum the
entry/exit trace block defined, as it’s much easier to create them as you write than to try and put them in lots of existing
macros when a problem crops up. There are two ways, one obvious, the other not so much so. The obvious method is to write a
template to do the job. The most recent version of the CMac.tpt
template file goes a bit in this direction, and will go further in forthcoming updates. One of the files appended to this
article for you to download, CMac Trace Templates.txt, contains a pair of templates of my own devise,
which you can mine for ideas, use as-is, or consign to the spode bin. The second one generates a macro skeleton and comment
header specifically for macros that return string values. To flesh out the concept, you could, as I do, either create extra
templates more specific to other return types, or get fancier and parameterize on return type, perhaps with a dialog
interface—if you’re one of those “self-starters” the job postings always seem to be asking for. You’ll notice that my template
uses some undocumented macros from TDbg.s to help automate things; you could figure them out on your
own, but I think the example template shows how to use them well enough. However, when in doubt, the code itself is the Court
of Last Recourse (or perhaps, “Last Recurse”). Sorry for that one, but allow me to remind you of the “Abandon All Hope, etc.”
sign back at the entrance (directions to the rare and endangered Egress will be found near the end of the disquisition).
There’s one other macro, though, that isn’t as immediately obvious which I could have used in my template: TDbgCreateTraceBlock(). This macro automates quite a bit of the
scut-work of generating blocks. You can use it in templates, or you can use it to automatically add trace blocks to an existing
macro. For instance, to do the latter, just put the cursor pretty much anywhere in the macro, press Shift+F10 to display the dialog, enter Tdbg^TdbgCreateTraceblock /EL=1/LP=CMAC, press the button, and watch the fun.
It isn’t guaranteed to get everything right all the time, so be sure to check things over with the trusty Mk.I eyeball, but it
does try. For instance, it looks for a “best fit” trace area; if it finds more than one possible area, it selects the first,
but back-ticks it for easy selection via the Ctrl+U and Ctrl+I keys, should you
want to change it. The code is well worth the read, as is the entire module.
I’m going to somewhat slight the TDUMP_EX() statement on the grounds that on the one hand, its
operation and usage should be fairly transparent at this point, and on the other, most of you won’t use it much. For the few
who find themselves with a problem it can help solve, the fact will become fairly obvious at that point, and so long as you
keep the already-mentioned caveats in mind, you shouldn’t have any trouble in using it.
By this time you’re likely wondering what the Deuce those “debug levels” that keep cropping up in trace statements are. Fair
question, as I’ve been glossing right over them while dealing with more basic issues. At this point you have a pretty fair
working knowledge of how traces do their thing, so the answer will make more sense than it would have earlier. There are five
possible settings, which roughly correspond to decreasing levels of importance.
TDBG_ERROR Use this level to indicate a true error that would cause Multi-Edit
or Windows API calls to fail. Since such situations are catastrophic, it will always generate
debug output (when you’ve compiled for debugging, of course).
TDBG_WARNING Use this for unexpected behavior that the program can recover from gracefully. Under
default area debug level settings (see below) this will generate output, so don’t overuse it.
TDBG_DEBUG Use this for main macro calls and other important things, but don’t use it for anything
that doesn’t need to be reported too frequently.
TDBG_TRACE Use this for lesser macro invocations and other informational dumps you don’t often
need to see, especially things that generate a lot of output.
TDBG_LOUD Use this for debug statements you only want to invoke very infrequently, such as very
localized traces or ones that generate large amounts of data. If you find yourself using TDUMP_EX(),
you’ll probably want to assign it this
debug level.
You needn’t use the levels for exactly these purposes, but they were designed with that usage in mind, and it’s a good
layout, so unless you have a very good reason for doing things differently, stick with this scheme. These levels are,
obviously, hard-coded into your trace statements, so be careful when you decide which levels to use, or you may find yourself
overwhelmed with data when you actually have to debug. Now, you’re probably wondering how Multi-Edit
knows when to display any particular one of these levels; the answer to that is just a short way down the pike, and I’d like to
go through things linearly, just as you would when you do it yourself, so bear with me for just a bit longer.
 One nice property of the trace mechanism in Multi-Edit 9.10 is that when you do a “release” or “production” compile of code containing trace statements,
they compile to nothing, and so, insert no extra overhead in your code. The converse of this is, of course, that you have to
compile a module in debug mode to cause the compiler to generate trace code. The easiest way to do this is to press F9 to display the compiler list dialog, then select “Compile macro for debugging,” as the figure to the left
shows.
Debugging
How Debug Levels in Areas Work
You’ve already seen that the debug levels embedded in your CMac trace statements control when those
statements actually generate debug output, but you haven’t yet seen how. The answer to that one actually wraps up a couple of
loose ends. Haven’t you been wondering what the point of the debug areas really is? If so, it probably won’t come as any
surprise to discover that debug areas are the other part of the puzzle.
It’s actually quite simple (to use; the machinery beneath the stage is something else again): areas, just like the trace
statements themselves, have debug levels associated with them. The same five levels, in fact. You might have missed this, as
every area has a default debug level: TDBG_WARNING (which is why I suggested being parsimonious with
that level in my first mention of it). The interaction between the two is simple: only trace statements with debug levels at
least as high as the current debug level of the area they belong to (also hard-coded, as you’ll recall) will generate debug
output—and if they don’t, then you can be pretty sure the execution point never passed through them. So if you have an area’s
debug level set to the default, TDBG_WARNING, any trace statement with that level or TDBG_ERROR will generate debugging output when executed; any others will not. Were you to set the area to
TDBG_LOUD, every executed trace statement would generate output. For obvious reasons, you’ll likely
want to use that one cautiously.
So how do you change the debug level for an area? Well, you could go in and change globals directly, but we’d really not
recommend that. Besides, there’s a macro (didn’t you just suspect as much?) to do it for you, TdbgSettingsDialog(). You needn’t even call that directly, though, as we’ve added it into the menu for you,
under Macro | Debug Settings…, which displays the TDBG settings dialog you see
below.
As a bit of examination shows, this is also where you can change the destination of your trace output, by changing the Log
number it’s routed to; note that this destination applies to all output, not just that from the
currently-selected item in the area list. To change an area’s debug level, just select it in the list and click the Change button. That will display the Area TipWin dialog you see overlapping the
TDBG settings dialog above. Its usage should be obvious, as the illustration pretty well says it
all.
Note that you’ll have to debug-compile a module containing a TDBG_DEFINE_AREA() statement referring
to a particular area before that area will appear in the list. A point of minor
interest: you’ll note that the third column in the list only shows DLLs. That’s because
every area in the illustration above is associated with a DLL (take a close look at the area names), and the third column is
there to show which DLL goes with which area. Your own CMac areas will show nothing in that column.
Debugging, in Fee Simple
The hardest thing about Multi-Edit 9.10’s trace facility is getting your mind around the basic
concepts, and we’ve covered those. To actually use it, all you have to do is add the trace header, define at least one trace
area, and insert trace statements where you think there might be a problem (again, we consider it a “best practice” to build
enter/leave trace blocks into all your non-trivial macros at the time you write them, so you can follow execution flow). Then
compile the module or modules in debug mode, start an external application like DebugView (assuming
you’ve left all areas set to Log 0, the default), and run your macro. When it’s done (or when it crashes Multi-Edit or sends it into a loop you can’t break out of), just shift over to DebugView and have a look at your debug output. If you have enough screen real-estate, you can run Multi-Edit and DebugView side-by-side and watch the debug output as it’s generated.
Either your output will show you what’s going on, or you’ll iterate, changing and adding trace code, recompiling, and
rerunning. It doesn’t usually take too much of this to find all save the most refractory bugs, though. Once you’ve got it
running to your satisfaction, you can either remove the trace code or just recompile in non-debug mode. If you perform any kind
of unit tests, regression tests, or the like, it’s a good idea to leave them in place, just as you would assert() statements in C.
If you do use DebugView as your viewer, you can pull some extra stunts. I won’t describe all of
them here; SysInternals’ documentation is short, pithy, and quite readable, and you should certainly
read it. One thing it can do that I will mention is save whatever it captures to a disk file you specify. This is a
particularly useful capability for those instances where your problem manages to kill one or both programs, or even hang the
machine, because it’s highly likely that the debug output will still be there, intact up to the point of the crash when you
restart things. For other useful capabilities, like color-coding or filtering the captured output, RTFM.
Okay, enough jabber from me; let’s see how to apply all this theory to a real-world example. And while I’m at it, I’d like
to thank Mark Russinovich of SysInternals for letting us use screen shots
of DebugView in this article.
A Real-World Example
The Problem Code
This is a portion of one of my own macros. As you might infer from the comments on the local subroutines, it finds all
occurrences in the current file of any keywords in the four keyword lists for the file’s associated language, and forces them
to the same capitalization as the keyword lists, unless they’re located in either a comment or a string.
It worked fine, but ran really slowly on a target file of any size, so I started to implement little experimental speedups
one at a time, testing to see whether they improved things or not; eventually, this piece of code ended up looking quite
different than what you see here, but I’ve reverted it to its form right after I made the first change to keep the example
manageable. The change was a simple one, but it put the program into an infinite loop every time when run on many, but not all,
target files. The only change was on line 0718 in the screen capture above; originally, instead of moving to Block_Col2 it merely moved one character right. It seemed a simple enough change. Yes, well…
Here’s an example of some code it failed on:
Obviously, this is a CMac macro itself (and you’ll note that it uses the enter/leave trace
instructions, as we recommend). However, instead of executing it, the problem macro simply uses it as text input.
The Problem Code with Traces Added
Here’s what the buggy macro looked like after adding a few trace statements beyond the enter/leave pair it already had
(off-screen in this capture). You’ll note that there are two statements to report the current keyword being searched for, as
well as a trace statement on each possible execution path within the FixCase: subroutine. The TTRACE() within the second while() statement wasn’t strictly necessary, as execution would
have to proceed down one of the two forks of the if/else statement within that loop. However, since I
had an infinite loop situation (which I knew from observing CPU utilization in Task Manager), I wanted
to be sure execution flow was even making it past the top-of-loop conditional test.
Note also the debug levels I assigned to the various trace statements. I’ll come back to that in a moment.
Captured Debug Output
With the debug level for the area, which, as you can see from the trace statements, is called “RShared,” set to TDBG_DEBUG, the default, DebugView captured
the following output:
Hmmmn. Not all that useful. This output might lead one to think the execution point was entering the
while() loop, but somehow skipping its contents. A moment’s thought will tell
you what’s going on, though. Even if that were the case, why didn’t the trace statements placed to report the current value of
sCurrentWord do anything? A quick skim back through some of the earlier
discussion of debug levels is worth the effort before going on. What, no daring sense of adventure for the bold experiment
ahead? Okay, okay. Remember that the area debug level defaults to TDBG_DEBUG if you don’t set it to
something else. If you re-examine the problem code with that in mind, you’ll see that there’s only one trace statement with
that high a debug level, and it’s exactly the one that generated all the output in the illustration above. So, let’s boost the
area a notch, to TDBG_TRACE.
Aha! These results are a bit more interesting. We’re now getting output from the two statements in the if/else fork, and that’s what we need to solve the problem. We’re still not getting output from the two outer
trace statements; that’s because we’d have to set the area to TDBG_LOUD to activate them. But in this
instance, that won’t be necessary, as the statements that are active are generating everything we need to solve the current
problem. It’s no accident that I had those statements report the value of Block_Col2, since that was
the change that broke the code. With a bit more foresight, I might have also had them report the current line number, but while
it would have been nice, it wasn’t necessary here.
If you compare the possible execution with the contents of the target file and the debug output, three things are
immediately obvious: first, the keyword “int” is correctly
replaced five times (there are five integer definitions at the top of the file); second, every pass through the inner loop
after that results in “)int(“ being found and skipped because it’s in a string (okay, poorly-phrased
error message); and third, Block_Col2 is always zero, which means that the next statement keeps moving
the cursor back to the start of the same line. It’s that zero value that’s the problem;
I’d made a false assumption about the contents of Block_Col2 after a regex
search. That analysis is confirmed by the second observation above, as there just aren’t
as many occurrences of “int” in the file as were appearing in the debug output (which continued on for
some little time; note the location and size of the thumb in the vertical scroll bar in the DebugView
screen capture below).
Problem Solved
Changing the source code to this:
gives the correct behavior, as the corresponding trace capture shows. That the macro finished instead of looping to infinity
and beyond is extra confirmation.
Search_End_Col assumes the values I’d falsely assumed Block_Col2 would.
Wrong, because unless you specify it, found text won’t be marked as a block.
“But why didn’t you just set the area to TDBG_LOUD and see all the output, Master?” I hear you cry.
Ah, Weedwhacker, had I done that, I’d have spent the next ten minutes futilely trying to Ctrl+Break out of a very long stream of debug output, because my CMac Reserved Word
lists contain around 3,000 words—and you perhaps begin to see why I was interested in speeding this macro up to begin with.
Wrap-up
You should now have no trouble using traces in your CMac development. Of course, the best way to
really understand how it all works is to look at the source modules, TDbg.s and TDbg.sh. At the least, you should read the comments in those files, as they explain some things in more
detail than a how-to article like this. And now folks, this way to the Egress…
|
|
Subscribe to the Multi-Edit Newsletter:
Click here
Please review our MESI Privacy Policy: