June 1999

Code for this article: June99BugSlayer.exe (238KB)

John Robbins is a software engineer at NuMega Technologies Inc. who specializes in debuggers. He can be reached at www.jprobbins.com.

How many times have you heard the saying, "Too much of a good thing can kill you?" What does that really mean? In your projects, I am willing to bet you have or are suffering from an excess of a good bugslaying technique—to the point that it is no longer useful. In fact, it is probably downright annoying. You guessed it, too many trace statements. A plethora of trace statements completely lose their effectiveness very quickly. How many times have you sat there searching through two megabytes of trace statements looking for a single line to tell you what went wrong? Even worse is when you fall asleep waiting for the debugger to process the trace statements inside a loop that has 10,000 iterations. To ensure that everyone is on the same sheet of music, a trace statement (for the purposes of this column) is a way to view the internal state of your program. Generally, these resolve down to the Win32® OutputDebugString API or the Visual Basic® Debug.Print object method.     Too many trace statements are especially bad in real-world team development. Everyone sprinkles in a few and yours are lost in the morass as soon as you check your code in. Another problem with trace statements is that a call to OutputDebugString can get expensive processing-wise. OutputDebugString processing actually entails a process context switch on each call. If you look at the Win32 debug API, you will see that one of the DEBUG_EVENT unions returned from WaitForDebugEvent is OUTPUT_DEBUG_ STRING_INFO. That means your process stops and the debugger reads the information out of your address space. This can subtly change the timing on your multithreaded applications and lead to situations where it works under DEBUG builds (with OutputDebugString calls), and not under RELEASE builds. Even worse is when it runs in RELEASE builds, but not DEBUG builds.     What would be really nice is if you could use a ton of trace statements, but only see the ones that came out of the source files you are interested in—no matter which modules they came from. The good news is that I think I've solved this problem for both Visual C++® and compiled Visual Basic! After presenting my solution, I want to talk about some of the scrapes and bruises I earned implementing LIMODS (LIMit OutputDebugStrings). I think you will find that with LIMODS you will be able to wallow in trace statement excess with complete and unadulterated abandon. Possible Solutions     My initial thought was to recommend conditional compilation so that each source file had a define associated with it. To see the trace statements for a particular file or set of files, you would just need to set the define and compile. While it would work, I certainly did not want to recompile each and every time I wanted to change which source files had trace statements. From what I have seen, the conditional compilation approach is used quite a bit in the real world, but I wanted something more automatic than chugging through different compiles just for trace statements.     Another possible solution involved special tracing macros. In an effort to solve the too-many-traces on a very, very large development team, I tried this approach. Each team received a unique trace macro for their particular section of the project. The macro system worked out to something similar to what MFC uses with the internal tracing that is turned on with its TRACER.EXE program. MFC internal trace statements check an internal flag variable, and if the bit assigned to a subsystem is active, the trace statements appear in the debug window. For the most part, the special macro approach works.     However, there are a few obstacles. In my large team this approach started breaking down after a while because the MFC wizards themselves generate TRACE macros and developers would forget to use the special functions. I tried to combat this by redefining TRACE away to force developers to use the correct macros, but it was quite annoying to have to fix generated wizard and third-party code. The other problem is that this type of solution is not that extensible. You generally will have to spend a good bit of time up front porting the trace macros from project to project. It also became a pain to maintain when there were architectural changes and code would move from one subsystem to another. And this does not work at all for Visual Basic.     After realizing that starting from the source code side was not working, I tried to step back and think about the whole problem in a different light. I realized that, in essence, I needed a way to associate a call to a tracing function with the particular source file it came from. I also needed a way to decide if the tracing function call was to go through or not. Finally, I needed a way to toggle trace statement output from both source file and module. When I summarized the problem in this manner, I ran around the house screaming "Eureka!" (too loudly, of course). If you have been reading this column for the last couple of years, you know that each of these problems has been solved independently. To build a trace-limiting system, I just needed to tie the different individual solutions together. As you will see when I get to the implementation section, I was able to achieve nerd-vana and hit the Holy Grail of code reuse. LIMODS Requirements and Usage     When I started seeing the way to proceed, I laid out my requirements for LIMODS. LIMODS needs absolutely minimal source code changes. Ideally, I wanted LIMODS to require only a single-line change to your program. LIMODS keeps out of the way so that all the user needs to do is specify the source files they want to see trace statements from. After having suffered through the trace macro scheme mentioned earlier, I wanted to ensure that it was brain-dead-easy to use LIMODS. LIMODS has a simple user interface that lets you quickly and easily pick the source files you want to see trace statements from.     In the big scheme of life, these requirements might seem quite broad. Nevertheless, after the next few paragraphs on usage, I think you will agree that I hit them.     Before doing anything, you need to install LIMODS. In the \Bugslayer\SourceCode\Release directory in this month's source code are the compiled LIMODS files and the settings file, LIMODS.INI. First, copy LIMODS.INI to your %SYSTEMROOT% or Windows directory. By default, LIMODS will place its data files (.LOM) in the same directory as each module loaded while LIMODS is active. If you set the LOMDirectory in the [LIMODS] section of LIMODS.INI, all .LOM files are built into one directory. Personally, I prefer to have them go to one place instead of all over the disk. After taking care of the settings file, you need to place the binary files—LIMODSDLL.DLL, BugslayerUtil.DLL, GenLIMODS.EXE, and LIMODS.EXE—into a directory specified in your PATH environment variable.     If you want to use LIMODS with an application that uses either MFC42D.DLL or MFC42UD.DLL, you will need to do an extra step. Unfortunately, there are at least 700 different versions of those two very important DLLs out there. I will discuss this further in the implementation section, but LIMODS must know what ordinal export corresponds to AfxTrace from each of the MFC DLLs. While you'd think that they would always be the same ordinal, they are not. The distributed LIMODS.INI holds the information for MFC42(U)D.DLL that is in use with Visual C++ 6.0 without any service pack, Visual C++ 6.0 SP1, Visual C++ 6.0 SP2, and Visual C++ 5.0 without any service pack.     If you are using a different version of Visual C++ (including any subsequent service pack releases) you will need some extra steps for MFC42D.DLL and MFC42UD.DLL to ensure that LIMODS gets the right export out of the MFC debug DLLs. Get the version information from the %SYSTEMROOT%\System32\MFC42(U)D.DLL by right-clicking on it in Explorer and selecting Properties on the popup menu. Click on the Version tab; the first item, File Version, is the version. For example, the Visual C++ 6.0 SP1 version of MFC42D.DLL is 6.00.8267.0.     Next, change to the \MFC\SRC\Intel directory in your Visual C++ installation. There you'll find the .DEF files used to link MFC. Each .DEF file name corresponds to the binary name. For example, MFC42D.DEF is the matching .DEF for MFC42D.DLL. Open the appropriate .DEF, and for MFC42D.DLL search for the text, "?AfxTrace@@YAXPBDZZ". For MFC42UD.DLL, search for the text, "?AfxTrace@@YAXPBGZZ". The important line will look like the following:

?AfxTrace@@YAXPBDZZ @ 1179 NONAME

The number after the third @ symbol is the ordinal that exports the AfxTrace function. You will need that number.     Open up your copy of LIMODS.INI. For MFC42D.DLL, look for the section [MFC42D.DLL Hack-O-Rama]. For MFC42UD.DLL, the section to find is [MFC42UD.DLL Hack-O-Rama]. The section will look like the following:

[MFC42D.DLL Hack-O-Rama] VerCount=2 ; VC 6.0 SP1 and SP2. Ver0=6.00.8267.0,1179 ; VC 6.0 NO SERVICE PACKS Ver1=6.00.8168.0,1179

The Verx lines show the version and ordinal information. The first number is the MFC file version number, and the second number is the ordinal export.     Add your MFC file version as the next number in the list. For example, if you are working with Visual C++ 5.0 with no service packs, you would add a line to the above sample, which would be "Ver2=4.21.7022,1253" for MFC42D.DLL. You would also need to increment the right-hand side of the VerCount. For MFC42UD.DLL in Visual C++ 5.0 no service pack, the line would be "Ver2=4.21.7022,1256".     If you built your own private MFC42(U)D.DLL, which I would not recommend at all, you can do the ordinal checking the same way.     LIMODS looks at the MFC file versions as it comes into memory. If the corresponding file version is not found in LIMODS.INI, you will be warned with a message box. If you compile and run the LIMODS test program in the .\BugslayerUtil\SourceCode\TestLIMODS directory, you can quickly see if you got everything right.     After all of that, it is almost a letdown to tell you that for C/C++ programs, the following is the only line of code that you need to add to your program to get LIMODS working:

LoadLibrary ( "LIMODSDLL.DLL" ) ;

LIMODSDLL.DLL works all of its magic in its DllMain, so you do not need to call any other functions. I figure adding one line of code is not too much to ask for the benefit of LIMODS.     Developers using Visual Basic have to take a couple more steps, but not that many more. The first step is to copy LIMODS.cls out of the .\Bugslayer\SourceCode\VB directory and add it to your project. You will then need to create a global instance of the clsLIMODS class, shown in Figure 1. I would recommend something like Trace. There is only one method to clsLIMODS; it's called (surprise) Trace, and it takes the same input as the Debug.Print method. Since there is no way to intercept the internal Debug.Print object, you must compile your application for LIMODS to do its magic. When you run from the IDE, the clsLIMODS Trace method will resolve down to a Debug.Print, so you can still see trace statement output in the intermediate window.     Finally, you will need to define the conditional compilation option LIMODS=1 in your project so that you get the appropriate class functions when you compile. If the conditional compilation is not defined, you get the empty versions. By using the conditional compilation, you will not have to pay the overhead for LIMODS when you don't need it.     All of the .LOM files for modules compiled with debug symbols will be generated the first time you run with LIMODSDLL.DLL loaded, so there will be a slight pause in your application as they are being processed. LIMODS does the right thing and keeps the .LOM files up-to-date as your modules change, so you do not have to do anything manually. If you want, you could also generate the .LOM files as part of your normal build process by using GenLIMODS.EXE. Just run GenLIMODS.EXE without any command-line parameters to see what it takes.     After you have your .LOM files, simply run LIMODS.EXE and select which source files from which modules you want to view. Figure 2 shows LIMODS.EXE in action. Select the checkbox next to the source files you want to see trace statements from.

Figure 2 LIMODS.EXE

Now that you have an idea how to use LIMODS, I want to show you how it was implemented. Implementing LIMODS     Based on some of the things I mentioned and the history of this column, you can probably guess that I am using our old friend IMAGEHLP.DLL yet again. With the source and line functions in the IMAGEHLP.DLL symbol engine, I figured that I could find the first and last addresses (what I call the address range) that correspond to a particular source file. Armed with that information, I could hook OutputDebugString as I showed back in the February 1998 column, and look at the return address to see if it is in a source file the user wants to allow trace statements in. While correct in theory, I still had to go around my elbow to get the information the way I needed it.     While there is no specific API function to enumerate the source file address ranges, I thought that I could use the symbol enumeration function, SymEnumerateSymbols. In the middle of enumerating the symbols I move back to the start of the source file with SymGetLinePrev, then walk to the end with SymGetLineNext. This worked great on my simple test cases, but when I ran it against GenLIMODS.EXE itself, I noticed that the source ranges didn't jibe with what the disassembly showed. I seemed to be missing whole sections of the source file.     When I manually calculated the ranges, they came out looking like Figure 3. The issue was that the IMAGEHLP.DLL source enumeration functions only enumerate the contiguous ranges. As you can see in Figure 3, source files with inline functions occur between the first part of GenLIMODS.cpp and the second part. I quickly realized that this is not a bug, but exactly how it should operate. The misunderstanding was on my part; I was putting the emphasis on the source file when I really needed to be thinking about the ranges first.     The .LOM files generated by GenLIMODS.EXE are just .INI files (see Figure 4). The first section is where I keep the main module information. The interesting part is that I keep the date and time stamp for the module used to build the .LOM. When LIMODSDLL.DLL looks at the module in memory, it checks the one in memory against the .LOM file; if the one in memory is different, LIMODSDLL.DLL has GenLIMODS.EXE generate a new one. I also keep the base address of the module so that if the module is relocated, LIMODSDLL.DLL can recalculate the address ranges on the fly. LIMODSDLL.DLL will also let you know through a couple of OutputDebugString calls that a module has been relocated.     The format of the [Ranges] section defines the ranges for the source files and is primarily what LIMODSDLL.DLL uses to determine what trace statements to show and when to show them. In order, the fields are start address, end address, the show trace boolean, and the source file. LIMODS.EXE uses the [Sources] section to show the source files in its tree. I did the .INI file format originally to make initial testing easier and had it hidden by an accessor class in LOMFile.h and LOMFile.cpp. As I kept working on LIMODS as a whole, I found the performance acceptable, so I never changed it.     GenLIMODS.EXE offers an exclusion capability to limit the source files in the resulting .LOM file to the ones that really have trace statements in them. While it might be interesting to see that you have half the STL library in the generated code, there are no trace statements in those files, and they just cause LIMODSDLL.DLL to take up more memory and slow processing. GenLIMODS.EXE looks for two files that Visual C++ itself uses to keep the dependency checking under control: SYSINCL.DAT and the optional, user-supplied MSVCINCL.DAT. SYSINCL.DAT and MSVCINCL.DAT are just a list of the files that appear in your VC\Include and VC\MFC\Include directories. In addition to those files, GenLIMODS.EXE will also look for a LIMODSINCL.DAT for any extra files. For example, if you do not want to see the CRT files in your .LOM file, they can be included in LIMODSINCL.DAT. I included in the source code distribution a version of LIMODSINCL.DAT that will exclude the CRT source files.     LIMODSDLL.DLL is the other interesting part of the system. When LIMODSDLL.DLL starts up, it intercepts the key imported tracing functions in all process modules. Right now, those functions are OutputDebugStringA/W from KERNEL32.DLL, DiagOutputA/W from BugslayerUtil.DLL, _CrtDbgReport from MSVCRTD.DLL, and AfxTrace from MFC42(U)D.DLL. In addition, I hooked the LoadLibrary family of functions so that I could get notified when other modules come into the address space.     For LIMODS to work with Visual Basic, I also needed to hook GetProcAddress so I could return the appropriate hook function when MSVBVM60.DLL tries to get OutputDebugStringA. I have talked about hooking OutputDebugString in the past, but the interesting parts were hooking DiagOutputA/W and the AfxTrace functions. For one thing, they are __cdecl functions instead of the __stdcall functions, and the AfxTrace functions are exported by ordinal instead of by name. (The February and October 1998 Bugslayer columns discuss __stdcall export function hooking if you need a refresher. Both columns are on the current MSDN™ CD.)     __stdcall functions are easy to hook because the function itself cleans up the stack; __cdecl functions' stacks are cleaned up by the caller. The DiagOutputA/W and AfxTrace functions have variable-length parameters, so there is more of a twist. The actual act of hooking is the same, but the hooking function processing has to be different. In the LIMODSDLL.DLL case, I want the hooking function to grab the return address and determine whether it is in an address range that the user wants to see trace statements from. After checking the source, I will either let the function execute or return to the caller. In the __stdcall case, this is very simple. I can just call the hooked function directly and return right from my hooking function to the caller because I clean up the stack. In the __cdecl case, I have to get the stack back to the original state and jump to the real function if I need to execute it.     Figure 5 shows an expanded hooking function that takes care of DiagOutputA from BugslayerUtil.DLL. In LIMODSDLL.CPP, I used macros to hold the inline assembler so I could reuse it in other functions. Yes, I had to use inline assembler, but it is not anything weird and I encourage you to step through it in the debugger's disassembly window so you can watch it in action.     I have to be honest and say that I almost did not support hooking functions exported by ordinal because it is so error-prone, especially since MFC uses different ordinals for different builds with the same file name. However, when you get down to implementing it, hooking by ordinal is almost identical to hooking by name. If you look at HookOrdinalExport in Figure 6 and compare it to the previously published HookImportedFunctionsByName, you can see they are almost identical. Handling AfxTrace without hooking the ordinal export was going to require some stack walking and would probably be very slow. If I just ignored AfxTrace, LIMODS would be basically useless for MFC programmers. In the end, I opted for making LIMODS as complete as possible.     For the most part, I did not have too much trouble implementing the LIMODS system. Getting the proper behavior in the checkable tree control in LIMODS.EXE was a little weird, so if you need to implement one, you might want to take a look at the way I handle the lack of check-toggling notification.     The biggest problem I had with the implementation was that I used STL. While I realize that engineers much, much smarter than I wrote STL, I am coming to the conclusion that STL is truly read-only code (code that the developer understands, but no one else can). It took me quite a while to decipher the compilation errors and I absolutely dreaded stepping into the code to see why things failed or how something worked. I would also really appreciate it if the STL code would compile at warning level 4 without errors and the Microsoft® compiler would stop producing the C4786 error, "identifier was truncated to '255' characters in the debug information." It took me forever to get the magic placement of the pragma to shut that one off. Even with those nits, I did save time in using STL instead of reimplementing growable arrays and map classes.     As for the other problem I ran into, I cannot tell if it was a bug in the code generator or a misunderstanding on my part. In LIMODSDLL.DLL, I use a static array of HOOKFUNCDESC to hold the real function pointers for DiagOutputA/W for BugslayerUtil.DLL. In the hook functions, I used the real function pointer out of the structure to do the jump. The problem was that referencing the second item in the array would produce an invalid reference. The inline assembler text

JMP g_stBugslayerUtilRealFuncs[0].pProc

would generate the following assembler code, which was correct:

JMP g_stBugslayerUtilRealFuncs+4h

However, the reference to the second item

JMP g_stBugslayerUtilRealFuncs[1].pProc

would generate JMP g_stBugslayerUtilRealFuncs+5h, when I thought it should generate

JMP g_stBugslayerUtilRealFuncs+0Ch

Consequently, the generated code was jumping off into never-never land. I worked around the problem by using

JMP g_stBugslayerUtilRealFuncs[0x8].pProc

as the reference. This is an isolated problem and should not cause trouble for anyone, but it could be important if you wanted to add your own special tracing statements to LIMODSDLL.DLL. If you add your own functions, use the BugslayerUtil.DLL tables as an example. Where Can it Go?     I am quite happy with how LIMODS version 1.0 came out, but there is always room for improvement. I challenge you to add the following features and to come up with completely new ones. If you do add to LIMODS, I would be happy to post the code on my Web site for others to enjoy.     LIMODS.EXE looks at one module .LOM at a time. It would be nice if it could support an .LOP (LIMODS Project), which would be a collection of individual module .LOM files to be viewed and manipulated at once. You do not need to stick to the checkable tree control metaphor that I used. There might be better ways for users to work with this data in a multiple module project implementation.     Right now, you have to specify the files you want to see trace statements from before you run your application, and the list remains fixed for the length of the run. It would be really cool to set up some sort of communication channel between the running instances of LIMODSDLL.DLL and LIMODS.EXE so that saving a .LOM file automatically updates all running instances of LIMODSDLL.DLL that have hooked that module. I have not done this, but it might be easy to set up with a named pipe. Alas, named pipes only work on Windows NT. The world would give you extra credit if you could make this work for both Windows NT® and Windows® 9x.     Finally, give LIMODS a better icon. My artistic ability extends to sometimes being able to name three of the four primary colors. The icon on LIMODS.EXE is supposed to be a funnel, if you had trouble identifying it. Wrap-up     There you have LIMODS, a utility a long time in the making. I first thought of it five years ago, but up until now have not figured out a way to make it as nonintrusive to source code as possible—and easy to use. The thing I found interesting is how much code reuse I got out of BugslayerUtil.DLL and some ideas from previous columns. I even got code reuse out of Paul DiLascia's code! I used his CModuleVersion class to handle the file version information retrieval in LIMODSDLL.DLL. Thanks, Paul.     Now that you have LIMODS, spew those trace statements—you can afford it. Slap them everywhere and really figure out what is happening in your application. Wanton excess is cool!     I would also like to acknowledge readers Dan Pierson and Scott Lewandowski for reporting bugs they found in BugslayerUtil.DLL. Thanks, guys! Da Tips!     Even though I am writing this when there is a ton of snow on the ground, celebrate spring by sending me your debugging tips to share with your fellow developers. Your brains should be thawed by now! Tip 21 From John Maver: I found a spiffy trick you can do with the debugger watch window. Putting a function in the watch window will cause the function to be executed.     Compile a debug build of VectorWalk.cpp (see Figure 7) and single-step in the debugger until the active line is the vector constructor in main. Notice that the function vectorwalk is not called in the main program at all. Switch to the watch window and type in vectorwalk(a), then run to the for loop. Notice that the value after vectorwalk(a) is zero, which is what you would expect because vectorwalk returns the size of the vector.     Step over the push_back call once and you see the magic happen. The vectorwalk(a) value in the watch window changes to 1, and if you look at the console window for the program, you will see that the value of a[0] has gone to count! Each time you execute the push_back, you see a new value in the watch window reflecting the size as well as the dump each time vectorwalk(a) is reevaluated.     While I am sure you do not want to have the function you place in the watch window calculate pi to 100,000 places, I have found it very useful to have some small functions in key parts of my code that I only call from the debugger. I use them to do some extra data validation and to help me look at convoluted data structures. Just make sure that your special functions treat everything as read-only because you do not need your debugger messing with the real data. Tip 22 From Brad Ek: I really hate trying to figure out problems when you get an error in a C/C++ macro. The bugslaying trick I use is to compile with the CL.EXE /P switch so it will generate the completely preprocessed file, original filename.i, that CL will then compile. This makes it a snap to find out where a macro went bad. Be prepared; the .i files can get huge, on the scale of three to four megabytes if you are doing MFC development.

Have a tricky issue dealing with bugs? Send your questions or bug slaying tips via email to John Robbins: john@jprobbins.com.

From the June 1999 issue of Microsoft Systems Journal.