Using Better Tracing to Understand the Doc/View Architecture

Purpose

One of the hard things about learning the document/view architecture is that it is full of marvelous functions, but nobody tells you which function gets called when. You are supposed to override functions when you want to add functionality, but it is not clear which function is the right one.

One way to find out is to override each function you want to know about and put a TRACE statement in it. Now each time one of your functions is called, a line of text appears in the debug window. Start the program, see what happens. Click the mouse, see what happens.

This is fine as far as it goes. But to understand the document/view architecture, you want to see a lot of functions. The debug window quickly turns into a mess. You don't learn anything. It would help if the debug window was more readable.

The CIndentedTrace class helps with this. You can use it to make the debug window look more like C++ code. By adding a line of code to a function like the CMyClass member function MyFunc(), CIndentedTrace prints

CMyClass::MyFunc() {

when it is called. When the function exits, CIndentedTrace prints

}

Functions called by MyFunc() can be treated the same way, except that their text will be indented. If MyFunc() calls SubFunc(), the debug window looks like this

CMyClass::MyFunc() {
CMyClass::SubFunc() {
}
}

CIndentedTrace can also be used to add lines of text that look like C++ comments. E.g.

CIndentedTrace contains other utility functions for such things as hex dumps of strings and displaying text strings for GetLastError() messages.

TRACE is a macro whose behavior depends on whether _DEBUG is defined. When compiled with a debug configuration, TRACE does its job. When compiled with a release configuration, it disappears. The CIndentedTrace header file contains macros to do the same thing. If you use these macros instead of calling CIndentedTrace yourself, CIndentedTrace will only be called in debug versions of your program.

Running the demos

You may want to try out the demos before seeing how they work.

The TraceEasy demo shows an easy example of using the CIndentedTrace class without macros. It is for understanding the class.

The TraceMacro demo is an example of how to use all the features of the CIndentedTrace class with macros.

The TraceSDI and TraceMDI demos use CIndentedTrace to make the inner workings of the single and multiple document interface visible.

All demos work only from the development environment with debugging active. No compiled code has been included.

===

To run the demos,

1) Download and unzip them. Put each one in a separate directory. Each demo should have some source files and 3 or 4 files in a res subdirectory.

2) Make sure tracing must be enabled. This is done with the Tracer utility found in the VC++ tools (Task bar, start button, Programs, Microsoft Visual C++, Microsoft Visual C++ Tools, Tracer). The Enable tracing checkbox should be checked. You will probably not want any of the other checkboxes checked under most circumstances.

3) Use the Visual C++ development environment to open the workspace file (the dsw file). In most cases, this can be done by double clicking on the file in Windows Explorer.

4) Make sure a debug configuration is selected. Check it on the Build menu, Set Active Configuration option.

5) Compile the demo application. On the Build menu, choose the Build option.

6) If you have just finished compiling, the output window is probably open and displaying 0 error(s), 0 warning(s). If not, on the View menu, select the Output option.

There is a row of tabs along the bottom of the Output window that say Build, Debug, etc. When the program runs, TRACE output and other messages go in the Debug window.

7) Run the demo from the development environment. On the Build menu, select the Start Debug option, Go sub-option.

8) At any time while the program is running or after it has stopped, switch back to the development environment and look in the Debug window.

===

The SDI and MDI demos trace MFC code through a Single Document Interface application and a Multiple Document Interface application. In each, a vanilla application was created with the app wizard. The class wizard was used to override many functions. The IT_IT() macro was added to each override. This macro uses CIndentedTrace to produce formatted TRACE output.

Some functions were not overridden because they produce too much output. For example, the mouse move message handler produces several messages every time the mouse is touched. The screen drawing functions and idle message handlers are also left out. It is good to trace these to see what they do, even if you don't leave macros in them more than long enough to find out.

Tip: Stepping through the MFC source code is another good way to learn about MFC. Add a breakpoint to the function you want to inspect, run the program, and step into the MFC source code. This works only in MFC code. Microsoft does not supply source code for the C run time library, SDK functions, or other code. Darn it.

If you do this, be careful about breakpoints in window activation handlers or screen drawing functions. When you are done stepping through such a function, you might continue running the program. The debugger activates the program widows and redraws them. This calls the message handler you just finish stepping through, triggers its breakpoint, and shows you the code you just tried to get out of. To get out of this loop, you must turn off the breakpoint.

Using CIndentedTrace in your programs

1) Before beginning to deal with a program, tracing must be enabled. This is done with the Tracer utility found in the VC++ tools (Task bar, start button, Programs, Microsoft Visual C++, Microsoft Visual C++ Tools, Tracer). The Enable tracing checkbox should be checked. You will probably not want any of the other checkboxes checked under most circumstances.

2) Make sure you are using a debug configuration. Open your project with Visual Studio. On the Build menu, choose the Set Active Configuration option. Choose the debug configuration. Recompile if needed.

3) Before the class or macros can be used, the IndentedTrace.cpp file must be added to the project (Project, Add To Project, Files...). Just having the file present in the project directory is not enough. The compiler will not compile a source file and the linker will not use the object file unless the source file is part of the project. If the linker doesn't find the CIntendedTrace functions referenced in the code, it will complain with LNK2001 errors.

The IndentedTrace.h file can be added to the project or not. If not, CIndentedTrace will not appear in the Visual Studio class view window and IndentedTrace.h will be listed as an external dependency instead of a header file in the File View.

4) Each project cpp file where CIndentedTrace functions or macros are to be used must reference IndentedTrace.h. This can be done by adding

#include "IndentedTrace.h"

near the top of the cpp file or to a header file the cpp file includes. Perhaps the best way is to just add it once to stdafx.h.

5) In each function you want to trace, add an IT_IT() macro. It should be the first line, so that any code called by the function is properly included inside the function's braces. The IT_IT() macro takes a string argument. The string usually contains the function's class and name. The class should be added because the output window may contain output from many different classes. But you may use any text you want may appear in the output window.

Within a function, an IT_IT() macro must appear before any other IT_ macro can be used. Only one IT_IT() macro can be used in any function.

6) To add a comment to the output window, add an IT_COMMENT() macro somewhere after the IT_IT().

Variables can be displayed with a format like TRACE or printf(). IT_COMMENT1() takes 1 variable. For 2 or 3 variables, use IT_COMMENT2() and IT_COMMENT3().

How CIndentedTrace works

The TraceEasy demo shows how CIndentedTrace works. Only a few CIndentedTrace features are used. No macros are used to make it easy to follow when stepping into CIndentedTrace code.

Look in CTRaceEasyView to find code that uses CIndentedTrace. In OnLButtonUp(), try putting a break point at the CIndentedTrace variable declared. Step into the CIndentedTrace constructor and destructor. To see the destructor, wait until the cursor reaches the closing brace of OnLButtonUp(), and step into the brace.

When a local variable of type CIndentedTrace is created, the CIndentedTrace constructor is called immediately, and the CIndentedTrace destructor is called at the end of the function body when local variables go out of scope. The most important things the constructor does are print its argument and a "{" at the current indent level, and increment the indent level. The most important things the destructor does are decrement the indent level and print a "}".

Note that if the CIndentedTrace variable is declared on the first line of a function, it will be constructed before any other local variables. Its destructor will be called last. This is important.

CIndentedTrace keeps track of the indent level with the static member variable ms_iTraceDepth. Because ms_iTraceDepth is static, all CIndentedTrace objects must share a single copy of it. This makes it an ideal way for CIndentedTrace objects to share information about the current indent level. Each time a new CIndentedTrace object is created, ms_iTraceDepth is incremented. Each time one is destroyed, ms_iTraceDepth is decremented.

Each CIndentedTrace object keeps track of the indent level it was created at with m_nLocalTraceDepth. Since this member variable is not static, no other CIndentedTrace object can touch it. It remains fixed for the life of the object that created it.

Other CIndentedTrace functions, such as Comment(), can only be called in functions that have defined a CIndentedTrace variable. This is obvious in TraceEasy, but when macros are used, the variable definition is hidden in a macro.

Comment() just prints "// " and its argument at the local indent level.

===

The TraceMacro demo shows how to use most CIndentedTrace features, including some explained in the "For more advance users" section. TraceMacro is a little more complex, but mostly does the same things as TraceEasy.

One difference is that TraceMacro uses macros for all CIndentedTrace variable definitions and function calls. The macros are defined at the end of the IndentedTrace header file.

The IT_IT macro creates a local variable with the unlikely name of _IT_vnirrrdaewu in debug compiles. This name was chosen because, in most programs, it will not already be used by another variable. _IT_vnirrrdaewu stands for "Variable Name I Really Really Really Doubt Anyone Else Will Use." If you do not share my doubts, please feel free to rewrite the macros with a name based on a GUID.

Most of the other macros call a CIndentedTrace function. They require that the variable _IT_vnirrrdaewu be defined. This means they can only be used after IT_IT() or IT_EMBEDDED_IT has been used. IT_IT() is intended for the usual local variable case. IT_EMBEDDED_IT is intended for a special case where CIndentedTrace must be a class member variable.

For more advanced users

A constructor with an initialization list may need to be handled a little differently. The initialization list is executed before entering the constructor body. An IT_IT() macro in the constructor body makes it look like the initialization list is not part of the constructor. The thing to do is put CIndentedTrace in the initialization list too. This means it has to be a member variable of the class.

Recall that the order the constructors in an initialization list is set by the order that member variables are declared in the header, NOT the order in the initialization list. If this is not familiar, see Effective C++ by Scott Meyer. In any case, the CIndentedTrace member variable must be declared first in the class.

CIndentedTrace prints a "{" and indents when constructed, and unindents and prints a "}" when destroyed. This means there will be a "{" when the class is constructed and a "}" when it is destroyed. If you want the class constructor and destructor each bracketed with { and }, you will have to call Entry() and Exit() to put them there yourself. A couple Comments() may be useful as well.

Macros can be used for all of this. The IT_EMBEDDED_IT macro creates an uninitialized CIndentedTrace member variable named _IT_vnirrrdaewu. This member variable should be initialized in the constructor initialization list with IT_EMBEDDED_INIT(). You will probably want to add IT_EXIT to the constructor body and IT_ENTRY() to the destructor body. You may want to add IT_COMMENT() as well.

Note that if the IT_IT() macro is used in a member class, a member variable and a local variable with the same name have been declared. This is OK. The local variable hides the member variable. This means that if you add IT_COMMENT() to the function, it will invoke the local CIndentedTrace and print at the local function's indent level.

If you have any doubts about which instance of CIndentedTrace produces what output, add IT_ENABLE_SERIAL_NUM(bEnable). This calls a static function, and so can be used before any CIndentedTrace variables have been defined. The output will identify itself with serial numbers.

===

CIndentedTrace is not thread safe. It would not be hard to protect the static variables with a critical section. But a multithreaded program may already have thread synchronization code. If CIndentedTrace had a critical section, the program using it could wait on two resources at the same time. This creates a potential for deadlock. The cause of a deadlock can be hard to find, particularly when some of the code is buried in macros. The developer of a multithreaded program should make the decision to add a critical section to CIndentedTrace if he wants it.

In the meantime, CIndentedTrace works after a fashion in multithreaded programs. Sometimes the indentation is messed up. This is not a big problem, because indentation is messed up anyway when output from two execution paths are interleaved.

If you are willing to overlook this shortcoming, you can add IT_ENABLE_THREAD_ID(bEnable). This calls a static function, and so can be used before any CIndentedTrace variables have been defined.

The output produced outside the main thread will identify itself with a thread ID. This can be used together with serial numbers.

There is another approach to tracing a multithreaded app. IT_EMBEDDED_IT and IT_EMBEDDED_INIT create a CIndentedTrace member variable in a class. The member variable has the right name, so all the macros can be used in any class function. All the output they produce will have the same indent level, but this can be an advantage in a multithreaded application.

Downloads

All demos are to be run from the development environment after a debug compile. Tracing must be enabled.