Extended Debugging Utility Set

CodeGuru content and product recommendations are editorially independent. We may make money when you click on links to our partners. Learn More.

Environment: VC6

Contents

Part I. Overview

The primary goal of the debugging extensions introduced by this utility set is to fill the yawning gap in the functionality provided by the standard VC libraries (CRT, MFC, ATL, and so on). Another issue that has been paid a special attention is ease of use—most facilities are available without any supplementary actions because they are by default configured to support the most frequent scenarious. On the other hand, there are many ways to change the configuration settings to fit even the most specific requirements.

The main features of the utility set are as follows:

1. Transparent way to include important additional information in trace messages. This may include, among other things, the information about names of the functions (where traces are issued from), their argument types, and values.
2. Ease of controlling the amount and type of this additional information.
3. Dumping binary data in the convenient adjustable format.
4. Stack unwinding.
5. Automatic tracking unhandled exceptions with crash report generation, which includes call stack info.
   
6. Provisions for deadlocks detection.
7. Writing trace messages not only to the standard debug output but also in log files, which solves some problems and inconveniences inherent to the OutputDebugString function.
8. Possibility of using a circular memory buffer to accept trace output, that allows to minimize the impact of tracing upon the timing relations between the different parts of the program and allows for tracing in the kernel mode.
9. Ability to assign level values to individual trace/dump messages, which gives way to selectively switch on/off different groups of the messages.
10. Possibility to leave the trace logging active in the release builds of the project.
11. Full UNICODE/ASCII support—all the macros are TCHAR-based.
12. All the code is in the only header file and depends only on the CRT library. Thus this utility set can be used uniformly in Win32, MFC and ATL projects.

Besides there are several other features, the most useful of which are:

1. The time stamp for the message may include milliseconds and microseconds (precise, not rounded). The ability to display microseconds is supported on NT/2K/XP only. On Win98/Me this option is silently ignored.
2. It is not necessary to include the trailing ‘n’ character in the format string anymore because it is added automatically.
3. Trace messages can be removed from the log file. This can be very helpful when hunting the rarely occuring bug. In this situation, you can issue a trace before entering each suspicious piece of code and remove it upon successful passing it. This prevents the log file from enormously growing in size.
4. Extended ASSERTEX macro, that allows to display in the assert dialog an arbitrary message formatted just like the TRACE macro from this utility set does, and simultaneously write this message to the standard debug output and into the log file.
5. The ASSERT macro is mapped to the CRT’s _ASSERTE one, so it can be uniformly used in any kind of a project. Besides, it will replace the MFC’s ASSERT that does not display expression that caused the assertion.
6. An MFC-like VERIFY macro has been added to make it available in any sort of a project.

Getting Started

To start using the capabilities of this utility set, do the following:

1. Include the “debug.h” header in the “stdafx.h” file after any MFC or ATL headers.

2. If you want to change the default additional information being included in the trace messages and/or set the log file(s), insert the SET_TRACE_OPTS and/or SET_TRACE_FILE macros somewhere in the global area of the module. If you are going to exploit message levels, these macros can be used to individually configure settings for each level. By default, all the levels have the same initial settings (see below).

   If you want to change the default stack unwinding parameters, use the SET_STACK_TRACE_OPTS macro. It affects all levels at once (in other words, no individual stack trace settings are supported for different message levels).

   It’s a good practice to always put these macros in the same place. In MFC projects, this may be the CPP file containing the CXxxApp class code, in Win32 projects—the CPP file containing the WinMain function, and so on. Note also that these macros can be used to set individual options for each message level you are using in the program.

   By default, the following additional information is prepended to the trace messages:

   hh:mm:ss.mls.mcs [TID]

   See the Configuration macros and Using symbolic debug info sections for detailed description of how to control the type and amount of additional information. Here are some examples that demonstrate the most frequent scenarios.

   To add the location information (file name and line number) for messages of level 0, use
   

   SET_TRACE_OPTS (0, TraceStdInfo | TraceLocation);

   
   To emulate MFC’s or ATL’s trace behaviour (tracing to the standard debug output and prepending trace messages with the location information), use
   

   SET_TRACE_OPTS (0, TraceDbgOutput | TraceLocation);

   
   To trace messages only (without any additional info), use
   

   SET_TRACE_OPTS (0, TraceDbgOutput);

   
   To add the caller function name (without arguments info) for messages of all levels, use
   

   
   
   SET_TRACE_OPTS (ALL_TRACE_LEVELS, TraceStdInfo |
   
                                     TraceFnName);
   
   

   
   To make the stacks be traced with full template arguments info (by default template arguments are stripped) for messages of all levels, use
   

   SET_STACK_TRACE_OPTS (TraceLocation | TraceFnArgs);

   
   To duplicate all debug output to the file “TraceLog.txt”, add the call
   

   SET_TRACE_FILE (ALL_TRACE_LEVELS, “TraceLog.txt”, 0);

   
   To prevent a new log from being appended to the previous one (appending is the default behaviour), use
   

   
   
   SET_TRACE_FILE (ALL_TRACE_LEVELS, “TraceLog.txt”,
   
                                      TraceNewLog);
   
   

   Additionally, some constants or identifiers can be defined before including the “debug.h” file to modify different aspects of tracing behaviour (see the Defines that Control the Tracing Behaviour section for more info).

3. Because the code in the “debug.h” header makes use of some STL classes, an annoying C4786 warning may occur while compiling your program because of the bug in VC6 (see the MSDN’s article Q167355). To cure it, insert the following pragma
   

   #pragma warning (disable : 4786)

   
   into the “stdafx.cpp” file before including “stdafx.h” header.

4. Now you can freely use any tracing/dumping/asserting/verifying macros from this utility set (see the reference sections below).
   

Trace Message Levels

As it was noted above, individual TRACE… or DUMP… calls may have been assigned different levels. By default, their level is 0. To specify another level value, use it as the first argument of the corresponding macro. For example, the first of the following two traces has the level of 2 and the second, the level of 0:

TRACE (2, _T(“Example of a trace message of the level 2”));

TRACE (_T(“By default the level is %d”), 0);

By default, messages of all levels are enabled. The following macros are used to disable messages of specific levels.

SET_MAX_TRACE_LEVEL( int nMaxLevel );

SET_ACTIVE_TRACE_LEVEL( int nLevel );

SET_ACTIVE_TRACE_LEVELS( int nCount, int* pLevels );

The first of them disables all the messages with the level above its argument. The second one disables messages of all levels except the level specified as its argument. The third one disables messages of all levels except those listed in the array pointed to by the pLevels parameter. The nCount argument specifies the size of this array.

For example, the following two operators placed in the global area of the module disable all messages except of the levels 1 and 2:

static int  g_aLevels[2] = {1, 2};

SET_ACTIVE_TRACE_LEVELS(2, g_aLevels);

The maximum level value that can be used is MAX_SUPPORTED_TRACE_LEVEL. By default, this value is 9. That is, 10 different levels are available (from 0 to 9, inclusively). Yet, if it is necessary to have more different levels, you can properly define the MAX_SUPPORTED_TRACE_LEVEL constant before including the “debug.h” header.

Configuration macros described later can be used to set individual options for each level. Thus, you can direct the messages of level 0 to the standard debug output only, while the messages of the level 1 will be additionaly logged to a file. On the other hand, the constant ALL_TRACE_LEVELS may be used with the SET_TRACE_OPTS and SET_TRACE_FILE macros to propagate corresponding settings to all message levels.

Another predefined constant, CRASH_REPORT_LEVEL, can be used to supply specific settings for the crash report. See the Crash Reporting section for the detailed description of this level.

Using Files As Tracing Destination

By means of the SET_TRACE_FILE macro, it is possible to assign a log file individually for each message level. Using files as the trace destination has the following advantages over standard debug output:

1. Output to file is performed noticeably faster than through OutputDebugString. The difference grows incredibly when the program works under debugger (see the next section for the figures).
2. To view the standard debug output, the program must be run under a debugger or some external program (such as dbgview) must be used to intercept it. But debuggers, on one hand, substantially degrade the performance of the program being debugged, which may be unacceptable in certain circumstances, and on the other hand don’t support simultaneous debugging of several interacting processes. Using anexternal viewer may be rather inconvenient when the program is to be tested on different computers (especially if these are customer’s ones). Tracing to log files addresses all these issues.
3. What is more important, using OutputDebugString under a debugger may lead to deadlocks in multithreaded applications (see MSDN’s Q173260 article for more info). Tracing to files solves this problem.
4. Because each message level can be associated with an individual file, message levels can be used for logical grouping traces. Writing each group in its own file may substantially facilitate analysis of the program logs. If it is necesary, the high precision time stamps may be used to establish relation between logs in different files.

The access to log files is, by default, protected by means of the temporary priority boost. See the Notes on Multithreading section for more discussion.

Using Circular Memory Buffer As Tracing Destination

The idea of using circular memory buffers has been suggested to me by the Dmitri Leman’s article An Efficient and Flexible Tracing Technique published by CUJ. You can refer to it for the profound investigation of this issue. Besides, it contains a number of liks to other articles concerning debugging.

Here is the brief outline of the most prevalent cases when usual tracing techniques become inappropriate or inconvenient:

1. The time consumed by the trace operations changes the program behaviour to such extent, that bugs cease to be well reproduceable.
2. A bug manifests itself quite rarely and resides in the intensively executed part of the program. In this case, running the program under a debugger may slow it down unbearably (see the table below) and tracing to a file makes the log too huge to be easyly operable.
3. Kernel mode debugging with interrupts disabled.

The circular memory buffer can help in all these cases.

To demonstrate the performance difference between the standard debug, file, and memory buffer outputs the following operators has been tested on an Athlon XP 2000:

TRACE (“Test TRACE message %06d”, i);

TRACESTRP (“Test TRACESTR messagen”);

TRACESTR (“Test TRACESTR messagen”);

with the following three variants of additional information automatically added to the messages (for TRACE and TRACESTRP macros only):

Variant 1) SourceFile(LineNum) : SystemTyme [ThreadID] :

Variant 2) SystemTyme [ThreadID] :

Variant 3) No additional information

for different output destinations.

The following table contains the time in microseconds per operation for each tested combination:

As this table shows, tracing to the memory buffer is noticeably faster than to the standard debug output. Note also, that tracing to files outperforms OutputDebugString, too (owing to the very efficient NT’s caching), and its speed, as well as the speed of tracing to a memory buffer, does not depend on whether the program is executed under debugger or without it.

To set a memory buffer as the tracing destination, use the SET_TRACE_BUFFER macro to declare the buffer, and the SET_TRACE_OPTS macro with the flag TraceMemBuffer (other flags may be specified as usually) to activate it. When tracing to memory buffer is activated, other tracing destinations are automatically disabled. The only exception is the FLUSH_TRACE_BUFFER macro, the purpose of which is to extract messages from the memory buffer and put them to the standard debug output and/or to the log file (as it is specified for the corresponding message level).

Note that the SET_TRACE_OPTS macro can be used multiply almost anywhere in the program, so it is possible to activate tracing to the memory buffer before entering the critical parts of the code and deactivate it after leaving them (with simultaneous flushing buffer content if necessary).

Using Symbolic Debug Info

The symbolic debug info can be used in two ways. First, as part of the additional information automatically or forcibly prepended to the trace messages and second, during the call stack tracing.

To automatically include symbolic debug info in additional information use the SET_TRACE_OPTS macro with a proper combination of the TraceFn… flags. By default, this additional information does not contain any debug symbols because obtaining them is rather processor intensive. Yet, if some extra processor load is not critical (for the most applications it is just so), adding the name of the function (plus its class, if it is a member one) where the trace comes from to the automatically traced data can greatly facilitate tracking the control path of the program (by reducing typing effort at the first place).

Besides the function name, it is possible to add its argument types (TraceFnArgTypes flag) and argument values (TraceFnArgs flag) info. If used, the latter of them automatically activates the former. When working with template classes, type info may enormously grow in size as the result of the template arguments expansion. Usually, this data is unnecessary during tracing, so the flag TraceFnStripTemplArgs may be used to remove template argument types from the log. For example, the type

std::basic_string<char,struct

     std::char_traits<char>,class std::allocator<char> >

will be displayed as

basic_string<>

Another flag—TraceFnStripStringArgs—can be used to remove string pointer numerical values from the argument list leaving in the log only the string texts.

There are two more issues regarding the string values tracing. First, the debug info does not differentiate between the wide character string pointers (wchar_t*) and opaque WORD arrays. So, when the unsigned short* argument type is occurred during function parameters tracing, a heuristic algorithm is used to determine whether it is a pointer to a wide character string or a pointer to an opaque WORD array. As the result, many real WORD arrays may be treated as strings. If such a behaviour is annoying, the TraceFnNoRawWideStrings flag can be used to suppress it. Second, the length of the string argument reproduced in the log is limited by the value of 32 characters. To change this limit in either direction, properly define the MAX_STR_ARG_LEN constant before including the “debug.h” header.

For the system DLLs, the argument type info is unavailable, so their decorated names (for __stdcall convention only) are used to estimate the total arguments list size and the arguments list is logged as a sequence of DWORDs.

When the debug info is absent, which for example may take place when tracing a stack in a release build, the addresses of the calls will be traced instead of the function names, and the raw stack content will be logged as argument lists. By default, the size of the logged data is 5 DWORDs. To change this value, properly define the BLIND_ARG_LIST_DEPTH constant before including the “debug.h” header.

By default, the signed integral values are traced as decimal numbers and unsigned integral values as hexadecimal ones. To change this default, the TraceFnDecIntArgs and TraceFnHexIntArgs flags can be used.

If an argument is a passed by value class or structure that is unknown to the parsing algorithm (currently it is any class/structure except STL’s basic_string, MFC’s CString or _bstr_t), its first several DWORDS (as specified by the BLIND_ARG_LIST_DEPTH define) are traced as its value. Values of all the subsequent arguments will be traced as ?? because the size of the previous class/structure is unknown. Yet, if the BLIND_ARG_LIST_DEPTH is big enough, the values of these ignored arguments may in fact have been traced as the content of the previous class/structure.

If a member function a has __cdecl or __stdcall calling convention, the value of the this pointer is traced as the first argument. If a function has a __fastcall calling convention, the values of its first arguments (passed through CPU registers) are unavailable.

As a rule, inserting information about argument types and values in every trace message will reduce the log readability, so it is recommended to use only the TraceFnName flag as the general setting. Where is necessary to trace a function arguments, the TRACE_ARGS and TRACE_ARGS_FULL macros can be used. They act just as an usual TRACE macro, but additionally force the argument types and values info to be added to the message. The former produces stripped info, the latter, unabridged.

If the _NT_SYMBOL_PATH environment variable is configured to use the symbol server (see the corresponding PSDK section) with the remote symbol source, the following problem may arise. If a module (usually a DLL) is copied from the directory, into which it has been placed by the linker, to another directory, which is used as working one, the Microsoft’s symsrv.dll always tries to locate the PDB file in the working directory. If it is absent there, it tries to find it in its remote storage (usually it is http://msdl.microsoft.com/download/symbols), that takes about 30 seconds, during which the program is actually hanging! What makes the situation ridiculous is the fact that subsequently imagehlp.dll correctly locates the PDB file in its original location and uses it to resolve request for debug info. To work around the problem with symsrv.dll, the PDB file must always be copied together with its DLL or EXE.

To avoid this problem in release builds, because the debug information is normally absent at customers’ computers, using symbol server is always suppressed.

Call Stack Unwinding

The call stack tracing can be carried out either in particular points of the program (by means of the TRACE_STACK… macros) or during crash report generation.

All that was said in the Using Symbolic Debug Unfo section is applicable to the call stack tracing except the following:

• The settings for the stack tracing is modified by means of the SET_STACK_TRACE_OPTS macro.
• There are no individual settings for the different message levels. All message levels share the same set of options.
• By default, the stack tracing configuration includes calls locations (TraceLocation flag), argument values, and types in stripped notation (TraceFnArgsStripped flags group), and displacement values (TraceFnCallDisp flag) in decimal notation (these settings are grouped into the TraceStdStackInfo flag).

Note: Stack unwinding and function info tracing won’t work in release versions of a project compiled with the default VC6 options. To keep these features active in release builds, it is necessary to add the /Oy- compiler option to the default ones. This option suppresses the frame pointer omission technique used by default by the compiler. For the most varieties of the projects, this has no appreciable effect on the program size or its productivity. But if it is an issue, this option may be used for beta versions only.

After the /Oy- compiler option is activated, only virtual addresses of the functions from your project will be traced (the names of functions from the system DLLs will be traced as usually). To make type info and consequently function argument values available for tracing, do the following:

• On the C/C++ tab for the category General in the Debug info combo box, select the value Program Database.
• On the Link tab for the category General, select the check box Generate debug info.
• On the Link tab, specify the /OPT:REF key in the edit box Project options (this is the default setting for release builds, but when the /DEBUG option is activated, the development environment automatically suppresses it, so it must be restored manually).

When this is done, the type info will be available for tracing if the PDB file is situated in the EXE module’s directory. If the PDB file is absent there, only virtual addresses will still be traced. But having the PDB file, it is possible to run the program under a debugger later, and track the sequence of calls, using previously recorded logs (perhaps received from customers). What could have been even better, it is possible to make the linker generate a MAP file, and write a utility for converting virtual addresses of the calls into corresponding function names using this file.

Crash Reporting

The crash reporting is performed by means of installing the unhandled exceptions filter at the beginning of the program execution. This is done automatically at the program’s startup. To suppress installing the handler, the TRACE_NO_CRASH_REPORT identifier should be defined before including the “debug.h” header. In release builds, the crash reporting stays enabled by default.

To change settings for the crash report, the CRASH_REPORT_LEVEL constant can be used with the SET_TRACE_OPTS and SET_TRACE_FILE macros. This level has the following peculiarities:

• By default, the file with the predefined name “CrashReport.txt” is used to save the crash reports. This file is opened with flags TraceWriteThrough and TraceNewLog. Of course, these settings can be changed by the SET_TRACE_FILE macro.
• The standard debug output is never used for this level (the TraceDbgOutput flag is silently ignored).
• The ALL_TRACE_LEVELS constand does not include this level.
• This level cannot be disabled by the message level management macros. The only way to disable the crash tracking is with the TRACE_NO_CRASH_REPORT define.

The crash report file is opened only when a fault occurs. This prevents the previous crash report from being instantly erased by the next run of the program.

The crash report starts with the title line such as the following:

Unhandled exception 0xC0000005 (ACCESS_VIOLATION) caught at

          address 0x77F83E91 in the thread 1036.

No additional information is prepended to the title line by default. But this can be changed as it was just described above.

Then, information about the registers and the last error value for the crashed thread are traced:

-> Registers:

       EAX = 0x00000000, EBX = 0x0012FE54, ECX = 0xFFFFFFFF,

                         EDX = 0x00FDFF44,

       ESI = 0x7FFDDBF8, EDI = 0x00000005, EBP = 0x00FDFF4C,

                         ESP = 0x00FDFF30,

       EFlags = 0x00010246, CS = 0x001B, SS = 0x0023,

                            DS = 0x0023, ES = 0x23,

                            FS = 0x0038, GS = 0x0000

-> Last error: 0x00000012

Next, the stacks of all threads are traced, beginning with the crashed ones. See the note below about some problems, which may occur in respect with the stack unwinding.

Stack snippets are followed by the computer configuration information. It includes only the basic information about the OS version and detailed processor information.

-> Computer configuration:

       OS type: WIN32 NT

       OS version: major 5, minor 0, build 2195

       Number of processors: 1

       Processor type: AuthenticAMD, stepping 2, model 6,

                       instruction family 6

       Processor name: AMD Athlon(tm) XP 2000+

       Processor features: FPU, MMX, SSE, MMX extensions,

                           3DNow, 3DNow extensions, RDTSC,

                           CMPXCHG8B, CMOV

       More processor features: VME, DE, PSE, MSR, PAE, MCE,

                                APIC, SEP, MTRR, PGE, MCA, PAT,

                                PSE36, FXSR

The amount of this information is intentionally small, because various programs require absolutely different information about their environment (from database engines and network configuration to the video or specific hardware capabilities). Instead, you can supply your own callback function of the following prototype:

void MyEnvironmentInfoCallback ( LPTSTR pszInfoBuf );

and register it using the SET_COMPUTER_CFG_INFO macro. The callback must fill the pszInfoBuf buffer with any suitable information. The size of the pszInfoBuf is 4096 characters (TCHARS). For an example of the callback function, see the ComputerCfgInfo function in the source code.

At last, if the circular memory buffer is in use, its content is flushed into the crash report. This feature is especially important for implementing tracing in release builds.

Note: When the program is run under VC6 debugger, the unhandled exception filter is never executed because the debugger intercepts all unhandled exceptions.

One more note must be made about stack unwinding. Unfortunately, the StackWalk function, which is used by the most of the stack tracing utilities (including apparently VC debugger), cannot correctly handle stacks containing calls with frame pointers omitted. On the other hand, many functions in the system libraries use FPO. So, if an exception occurs inside one of these functions, the traced stack information may be corrupted in different ways. Sometimes, some extra “phantom” calls may appear near the stack top. Sometimes, part of the stack gets lost. And sometimes, all the stack becomes unavailable.

Realizing that the crash reporting capabilities implemented in this utility set may prove to be insufficient in some circumstances, I’d like to refer you to the Andy Pennell’s article, which gives a detailed description of using minidumps. Another great thing is the article by Michael Carruth, which offers a framework that build a complete debug report, and optionally mail it to the developer.

To facilitate extending crash reporting mechanism, the SET_CRASH_RPT_CALLBACK macro can be used to register the callback function that is called after the crash report has been generated. This function must have the following prototype:

void  CrashReportCallback ( PEXCEPTION_POINTERS pei,

                            HANDLE hRptFile,

                            LPCTSTR pcszRptPath,

                            LPCTSTR pcszRptFileName,

                            LPCTSTR pcszAppFullPath,

                            LPCTSTR pcszAppFileName )

The pei argument receives the pointer initially passed to the exception filter. It can be NULL in case the crash report is generated as the result of the deadlock detection. The hRptFile argument is the handle to the opened report file. However, if all you need is adding some information to the crash report, the easier way to do this is by implementing an additional info callback. The pcszRptPath argument is the full path to the report file, and the pcszRptFileName is the report file name (including extension). The pcszAppFullPath and pcszAppFileName represent the apllication executable file information. See the CrashReportCallback function in the source code for an example of a simple callback.

Deadlock Detection

As it was mentioned above, the ease of use is the priority purpose of this utility set. However, deadlock detection cannot be performed without some changes to your application code. Fortunately, these changes are relatively simlpe. All you need is to change the standard critical sections with the custom ones that support deadlock timeouts. An example of such a critical section is the CCritEx class, the source code of which is in the “CritEx.h” file. This class is based on the OPTEX (optimized mutex) API library written by Jeffrey Richter and published by Microsoft Systems Journal in 1996. It can be used exactly like ATL’s CComAutoCriticalSection class plus some additional customization (if necessary) regarding deadlocks detection. The annotation to the “CritEx.h” contains short description of the CCritEx methods and their arguments.

Constructors of this class allow you to specify the deadlock timeout (by default, 10000 milliseconds timeout is used). If a critical section (an object of CCritEx type ) cannot be entered during this timeout, the crash report is generated just as it is described in the Crash Reporting section. The only differences is the title line; that looks like:

Deadlock detected in the thread 792. Call stack:

the absence of register values, and possibility to continue execution (see the constructor arguments description in the “CritEx.h”).

Yet, the proposed approach is not universal. Deadlocks occurred inside system or third-party libraries cannot be detected in this way, in case they do not bring deadlocks in your own code. The decision of this problem could be intercepting the EnterCriticalSection/LeaveCriticalSection API calls and replacing them with calls to CCritEx methods. But, this is the theme for a separate library. Moreover, most deadlocks are nested in our own code, and the described technique detects them rather effectively.

Tracing in the Release Builds

To leave the trace support in the release version of a project, all that is required is to define the RELEASE_TRACE identifier before including the “debug.h” header. Tracking unhandled exceptions and deadlock detection are active in release builds by default. To suppress them the TRACE_NO_CRASH_REPORT, an identifier must be defined before including the “debug.h” header.

Usually, all the tracing in release versions is reasonably avoided, pimarily because of the application productivity reasons. But, switching off all traces impedes determining reasons of program failures (if they take place, of course). With respect to this problem, the presented debugging utility set allows for one very efficient techniqe, based on using circular memory buffer that provides minimal overhead. The following steps must be done to apply this techniqe most effectively:

1. Determine the places where the potential for errors exist and place proper traces there. Give preference to the following macros (in order of overhead growth):


• TRACESTR
  
• TRACESTRP
  
• TRACENP
  
2. If you make use of the usual TRACE… macros or TRACESTRP, shrink maximally all the additional information included in the messages using the SET_TRACE_OPTS macro.
3. Disable unnecessary groups of traces by means of the message level management macros.
4. Activate using memory buffer as trace destination as it was described earlier.

Now, if an unhandled exception or deadlock occurs, the traces from the memory buffer will be included in the crash report. Making memory buffers short enough allows you to diminish the amount of trace information included into the report.

Notes on Multithreading

1. The access to the log files as well as tracing stacks, flushing memory buffer, and table dumping is protected by means of the temporary priority boost. For simple traces, the boost can be disabled by defining the TRACE_NO_PRIORITY_BOOST identifier. However, for flushing memory buffers, tracing stacks, and table dumping, a priority boost is always used because these operations are relatively rare.
2. The access to the UnDecorateSymbolName function is protected by the temporary priority boost because this imagehlp function may fail if simultaneously accessed from different threads.
3. No other special provision was made in this direction. Such a “neglecting” has been caused by the following reasons (in order of significance):


• Imposing any additional locking semantics will augment the risk for the application being debugged to change its behaviour or even get involved in unexpected deadlocks.
• The design of the utility set prevents the multithreading issues from serious intervening in its work (the major exception is the REMOVE_LAST_TRACE macro).
• The utility set has been used extensivly in the complicated multithreded projects for about two years without any noticeable drawbacks.

Note: A temporary priority boost is used only if an _MT identifier is defined for the project (the IDE defines it automatically, when a multithreaded configuration is chosen).

Part II. Reference

Configuration Macros

The rules of placing these macros in the source code of an application are described in the Configuration Macros Disposition subsection.

Macro

SET_TRACE_FILE( int nLevel, LPCTSTR pszFileName,

                            DWORD dwFileFlags );

specifies the log file to be used along with (or instead of—depending on the current trace options) standard debug output for the messages of the level given by the nLevel argument. The dwFileFlags parameter can be set to 0 to use the default settings or can be a combination of the following flags:

Macro

SET_TRACE_OPTS( int nLevel, DWORD dwTraceFlags );

is used to configure different tracing features for the messages of the specified level. The meaning and possible values of the dwTraceFlags parameter are described later. If this macro is not used, the following settings are in effect: TraceDbgOutput | TraceSystemTime | TraceTID | TraceFnName | TraceMicroseconds.

Macro

SET_TRACE_BUFFER ( long nBufferLen )

declares a circular memory buffer that will be used as a tracing destination. The nBufferLen parameter is the desired size of the buffer in TCHARS. This buffer is shared by messages of all levels. The size of the buffer does not affect the effectivity of its use, so it is recommended to make it as short as possible to not to overflow logs with irrelevant messages (especially in the case of crash reporting).

Macro

SET_STACK_TRACE_OPTS( DWORD dwStackTraceFlags );

is used to set the options that will be used by the stack unwinding macros for all message levels. The dwStackTraceFlags parameter can be a combination of the TraceLocation and TraceFn… flags. In this context, the TraceLocation flag specifies that the names of source files and line numbers (if available) of the function calls forming the stack must be traced along with each function’s information. If this macro is not used, the following settings are in effect: TraceLocation | TraceFnArgsStripped | TraceFnCallDisp.

Macro

SET_COMPUTER_CFG_INFO ( COMPUTER_CFG_INFO fnComputerCfgInfo );

registers the callback function that is called, when an unhandled exception is intercepted or a deadlock detected.

Macro

SET_CRASH_RPT_CALLBACK ( CRASHREPORTCALLBACK fnCrashRptCallback );

registers the callback function that is called, after the crash report has been generated upon an unhandled exception or a deadlock.

Macros

SET_MAX_TRACE_LEVEL( int nMaxLevel );

SET_ACTIVE_TRACE_LEVEL( int nLevel );

SET_ACTIVE_TRACE_LEVELS( int nCount, int* pLevels );

are used to disable messages of specific levels. The first one disables all the messages with the level above its argument. The second disables messages of all levels except the level specified as its argument. The third disables messages of all levels except those listed in the array pointed to by the pLevels parameter. The nCount argument specifies the size of this array.

Configuration Macros Disposition

If used, all SET… macros are usually placed somewhere in the global scope of a module. The SET_TRACE_FILE and SET_TRACE_OPTS macros can be used once for each message level. Changing settings being passed to these macros automatically change the behaviour of all traces or other concerned components in the module.

This has a valuable consequence for the static libraries. After a static library is linked to a main module, all the traces in the library accept settings from this module. So, you need not recompile the debug version of the static library to change the log file or the type of additional information being traced.

Besides the global area, these macros can occur once in the scope of any compound operator {}. The changes made to the debug configuration by the locally placed macros are applied globally (for the whole module) when they are executed. This can be used to dynamically change the tracing options for a particular pieces of code.

If some SET… macro is by chance included in the global area of several files from the project, no problems arise. The only drawback may be in the case when these different invokations impose different settings—the C++ standard does not allow to predict the order of their execution.

Additional Trace Information

The second parameter of the SET_TRACE_OPTS macro is a combination of the flags, specifying which type of additional information must be added at the beginning of every debug message, its representation parameters, and output destination.

The general format of this additional information is

SourceFile(NNN) : hh:mm:ss.mls.mcs [PID,TID]

                  {ProcessTime:ThreadTime}

                   FunctionName(ArgList) :

where:

SourceFile—full path to the file where the TRACE originates from;

NNN—number of the line in the SourceFile, on which the TRACE is placed;

hh:mm:ss.mls.mcs—system time in the form: hours:minutes:seconds.millisecons.microseconds;

PID—process ID;

TID—thread ID;

ProcessTime, ThreadTime—their meaning depends on the presence of the TraceRealPrThrTime flag (see below);

FunctionName—the name of the function where the trace originates from.

ArgList—function argument list with argument types and values.

The dwTraceFlags parameter can be any combination of the following values (though functions information belongs logically to the Additional information flags group; it is separated from it because these flags may be separately used for stack unwinding configuring):

1. Additional information flags:
   

   TraceSystemTime	System time at the moment of the debug message issuing.
   TraceLocation	For TRACE… macros—file path name and line number where the debug message originates from. For stack unwinding—file path name and line number for each function call in the stack.
   TracePID	Current process ID (affected by the TraceRtiHex flag).
   TraceTID	Current thread ID (affected by the TraceRtiHex flag).
   TracePrTime	Current process time.
   TraceThrTime	Current thread time. If the TraceRealPrThrTime flag is set, the current process/thread time is the time the process/thread owned the CPU. In this case, its precision is 10 ms and the TraceMicroseconds flag (if present) is ignored for them. If the TraceRealPrThrTime flag is not set, the current process/thread time is the time elapsed since the process/thread started, its precision being 1 mcs.
   TraceRealPrThrTime	Controls the interpretation of the TracePrTime and TraceThrTime flags.

   
   

2. Functions information flags:
   

   TraceFnName	Output the name of the function where the trace originates from. By default, the function names are undecorated where it is possible. To leave names decorated, the TraceFnDontUndecorate flag must be used.
   TraceFnArgTypes	Output the function argument types. Automatically enables the TraceFnName flag. The TraceFnStripTemplArgs flag affects the type info representation.
   TraceFnArgs	Output the function argument values. Automatically enables the TraceFnArgTypes flag. The TraceFnStripStringArgs, TraceFnNoRawWideStrings, TraceFnDecIntArgs, and TraceFnHexIntArgs flags affect the argument values representation.
   TraceFnCallDisp	Show the displacement of the call from the beginning of the corresponding function (in bytes).
   TraceFnStripTemplArgs	Suppresses output of the template parameter types. Its use allows to reduce greatly the size of the log nd increase its readability.
   TraceFnStripStringArgs	Removes from the results of tracing strings corresponding pointer values, leaving in the log the strings’ text only.
   TraceFnNoRawWideStrings	Makes arguments of the ‘unsigned short*’ type to be always traced as usual pointers to WORD.
   TraceFnDontUndecorate	Leaves function names undecorated.

3. Representation flags:
   
   

   TraceMicroseconds	Increases precision of the system and process/thread times output up to 1 microsecond.
   TraceRtiHex	If specified, the process/thread IDs (Run Time Information) are printed as hexadecimal numbers (by default, they are printed as decimal values).
   TraceFnDecIntArgs	Trace function argument values of all integral types as decimal numbers. By default, the signed integral values are traced as decimal numbers and unsigned integral values—as hexadecimal ones. This flag is mutually exclusive with the TraceFnDecIntArgs one. If specified together, they annihilate one another.
   TraceFnDispHex	Show displacements as hexadecimal values (by default the decimal notation is used).

4. Destination flags:
   

   TraceDbgOutput	Puts the debug message to the standard debug output (works independently from the output to the file).
   TraceMemBuffer	Directs traces to the circular memory buffer. This flag will take effect only if the SET_TRACE_BUFFER macro has been used to initialize the buffer.

5. Predefined flag combinations:
   
   

   TracePrThrID	Current process and thread IDs.
   TracePrThrTime	Current process and thread time.
   TraceRTI	Current process and thread IDs and times.
   TraceFnArgsStripped	= TraceFnArgs | TraceFnStripTemplArgs | TraceFnStripStringArgs
   TraceFnArgTypesStripped	= TraceFnArgTypes | TraceFnStripTemplArgs
   TraceStdInfo	= TraceDbgOutput | TraceSystemTime | TraceTID | TraceMicroseconds. This is the default setting.
   TraceAll	All the possible additional information with full debug info.
   TraceStdStackInfo	= TraceLocation | TraceFnArgsStripped | TraceFnCallDisp

   
   

Defines that Control the Tracing Behaviour

The following names may be defined (using preprocessor’s #define directive) before including “debug.h” header in order to change the default tracing utility set configuration:

Tracing Macros

The following macros can be used to output debug messages:

TRACE ( LPCTSTR pcszFmt, … )

TRACE ( int nLevel, LPCTSTR pcszFmt, … )

TRACENP ( LPCTSTR pcszFmt, … )

TRACENP ( int nLevel, LPCTSTR pcszFmt, … )
TRACENL ( LPCTSTR pcszFmt, … )

TRACENL ( int nLevel, LPCTSTR pcszFmt, … )
TRACENLP ( LPCTSTR pcszFmt, … )

TRACENLP ( int nLevel, LPCTSTR pcszFmt, … )

TRACENPL ( LPCTSTR pcszFmt, … )

TRACENPL ( int nLevel, LPCTSTR pcszFmt, … )
TRACERB ( LPCTSTR pcszFmt, … )

TRACERB ( int nLevel, LPCTSTR pcszFmt, … )
TRACESTR ( LPCTSTR pcszMsg )

TRACESTR ( int nLevel, LPCTSTR pcszMsg )
TRACESTRP ( LPCTSTR pcszMsg )

TRACESTRP ( int nLevel, LPCTSTR pcszMsg )


TRACE_ARGS ( LPCTSTR pcszMsg )

TRACE_ARGS ( int nLevel, LPCTSTR pcszMsg )
TRACE_ARGS_FULL ( LPCTSTR pcszMsg )

TRACE_ARGS_FULL ( int nLevel, LPCTSTR pcszMsg )


TRACE_STACK ( LPCTSTR pcszFmt = NULL, … )

TRACE_STACK ( int nLevel, LPCTSTR pcszFmt = NULL, … )
TRACE_STACKNP ( LPCTSTR pcszFmt = NULL, … )

TRACE_STACKNP ( int nLevel, LPCTSTR pcszFmt = NULL, … )


FLUSH_TRACE_BUFFER ( int nLevel )

The TRACE macro formats and outputs a message into either or both of the following destinations: standard debug output and programmer-specified file. Their first parameter is a sprintf-like format string specification. It can be followed by any number of arguments required by the format. After formatting the message will be automatically prepended by additional information in accordance with the settings established by the SET_TRACE_OPTS macros.

The TRACENP macro suppresses output of the additional information (No Prefix).

It is not necessary to include in the format string the trailing ‘n’ character because it will be added automatically. Yet, if this character or the “rn” sequence is present in the result message (either being in the format string or in the trailing %s parameter), no extra newline will be added to the message. To add an extra newline to the message, use two newline characters (“nn”) for ASCII or a sequence “rnn” for Unicode at the end of the format string.

The TRACENL macro suppresses automatical adding the trailing linefeed (“rn”) sequence (No Linefeed).

The TRACENLP and TRACENPL macros suppress both adding the trailing linefeed sequence and output of the additional information at the beginning of the debug message (No Prefix & Linefeed).

The length of the format string must not exceed MAX_FORMAT_LEN characters. The length of the resulting message (including all additional information) must not exceed MAX_TRACE_MSG_LEN value. By default, they are 1024 characters. If it is necessary to trace longer messages, these constants may be properly defined before including the “debug.h” header.

By using the REMOVE_LAST_TRACE macro, it is possible to remove from the debug log being written into a file the latest messages placed with the macros TRACERB. The maximal depth of such removing is specified by the MAX_ROLLBACKS constant. Currently, there is no protection implemented to support correct rollback semantics in multithreaded processes, so the circular memory buffer is a much better choice in this situation.

The TRACESTRP and TRACESTR macros are enlightened versions of the TRACE macro. They accept the only string pointer as their argument and do not append ‘rn’ automatically. The TRACESTR macro does not prepend any additional information to the trace message as well. Using the TRACESTR macro for the output to the memory buffer allows you to achieve the maximum tracing performance (see the Using circular memory buffer as tracing destination section for more info), that is of the greatest importance when tracing in release builds.

The TRACE_ARGS and TRACE_ARGS_FULL macros do completely the same as the TRACE one does, plus add to the additional data prepended to the message the information about the function that contains these macros. In the case of the TRACE_ARGS_FULL macro, this is the full argument type and value information. In the case of the TRACE_ARGS macro, argument types are formatted as TraceFnStripTemplArgs | TraceFnStripStringArgs flags require.

The TRACE_STACK and TRACE_STACKNP macros combine the functionality of the TRACE and TRACENP ones with the stack unwinding information. The stack is traced on the lines following the message line. The formatting flags controlling the representation of the function calls composing the stack can be set using the SET_STACK_TRACE_OPTS macro. Here is the result of a TRACE_STACK macro placed in the Test0 member function of the template class CTestImgHelpTempl:

18:55:25:090.432 [00664] CTestImgHelpTempl<>::TestBase :

    Call stack info:

  F:ProjectsCommonTest_DebugTest_Debug.cpp(67) :

    CTestImgHelpTempl<>::TestBase(int=8)const + 56 bytes

  F:ProjectsCommonTest_DebugTest_Debug.cpp(76) :

    CTestImgHelpTempl<>::Test1(int=8,DWORD=0xD,CTestImgHelpTempl<>

                       const&=0x0012FDBC)const + 100 bytes

  F:ProjectsCommonTest_DebugTest_Debug.cpp(218) :

    fstr(BasicString<>=”123456789ABCDEF0123456789ABC…”,WORD&

                      =0x1F(‘.’),double&=3.34e-007,float&=32.6)

                      + 234 bytes

  F:ProjectsCommonTest_DebugTest_Debug.cpp(228) :

    fqipdw(DWORD64=0x5500880011003300,int=31,DWORD&

                      =0x22004400,double=3.34e-007,float=32.6)

                      + 183 bytes

  F:ProjectsCommonTest_DebugTest_Debug.cpp(326) :

    _WinMain@16(0x00400000,0x00000000,0x00132C2C,0x0000000)

    + 67 bytes

  crtexe.c(330) :

    _WinMainCRTStartup + 435 bytes

  KERNEL32(?) :

    _BaseProcessStart@4(0x004134D) + 61 bytes

If the format string is omitted or its pointer is NULL, the “Call stack info:” message precedes the stack content part.

The FLUSH_TRACE_BUFFER macro is used to extract messages from the memory buffer and put them to the standard debug output and/or to the file. The specific destinations for flushing are determined by the settings for the message level, specified as the argument of this macro.

Dumping Macros

DUMP ( PVOID pvData, DWORD dwDataSize, DWORD dwParams = 0,

       LPCTSTR pcszFmt = NULL, … )

DUMP ( int nLevel, PVOID pvData, DWORD dwDataSize,

       DWORD dwParams = 0, LPCTSTR pcszFmt = NULL, … )

DUMPNP ( PVOID pvData, DWORD dwDataSize, DWORD dwParams = 0,

         LPCTSTR pcszFmt = NULL, … )

DUMPNP ( int nLevel, PVOID pvData, DWORD dwDataSize,

         DWORD dwParams = 0, LPCTSTR pcszFmt = NULL, … )


DUMPTBL ( PVOID pvData, DWORD dwDataSize, DWORD nCols,

          DWORD dwParams = 0, LPCTSTR pcszFmt = NULL, … )

DUMPTBL ( int nLevel, PVOID pvData, DWORD dwDataSize, DWORD nCols,

          DWORD dwParams = 0, LPCTSTR pcszFmt = NULL, … )

The DUMP macro acts in the following way. The pvData paramemter is a pointer to a binary data array that must be dumped. The dwDataSize parameter specifies the number of bytes in the array. The dwParams argument is a combination of the flags and is optional. A one or none value from each of the following flag groups can be included in the combination:

1. The radix of the numerical representation::
   
   

   DumpHex	hexadecimal (default);
   DumpDec	decimal;

   
   
2. Element size::
   
   

   DumpBytes, Dump8	byte (default);
   DumpWords, Dump16	word;
   DumpDwords, Dump32	double word;
   DumpQwords, Dump64	quad word;

   
   
3. Text equivalent of the data being dumped::
   
   

   DumpNoText	no text equivalent will be generated (default);
   DumpAscii	interpret binary data as ASCII symbols;
   DumpUnicode	interpret binary data as Unicode symbols;
   DumpTchars	interpret binary data in accordance with the current project settings;

   
   
4. Symbolt to bound the group of dumped data:
   
   

   DumpBoundNone	no delimiters (default);
   DumpBoundBrackets	[ data ];
   DumpBoundBraces	{ data };
   DumpBoundAngleBrackets	< data >

   
   
5. Delimiters to separate the elements in the group of dumped data:
   
   

   DumpDelimSpace	a space (default),
   DumpDelimComma	a comma and a space;

   
   

The pcszFmt parameter is an optional sprintf-like format string specification. It can be followed by any amount of arguments required by the format. When the format string is supplied, even if it is empty, it will be processed in the same manner as TRACE macros do (including all the additional information the TRACE would have inserted), and the dumped data will be placed before the trailing CR LF characters.

When the format string is omitted or its pointer is NULL, the dumped data are printed on the separate line without any additional information included.

The length of the format string must not exceed MAX_FORMAT_LEN characters. The length of the dumped data string must not exceed MAX_DUMPED_DATA_LEN.

The DUMPTBL macro is similar to the corresponding DUMP one. The difference between them is that the DUMPTBL macro contains an additional parameter (nCols) that specifies the number of elements dumped per line of output. Note, in contrast to the second parameter (dwDataSize) that is given in bytes, the nCols argument specifies the number of elements. If the format string is specified, the message generated from it is printed on the separate line before the first row of the dumped data table.

The length of the format string must not exceed MAX_FORMAT_LEN characters. The length of the dumped data row must not exceed MAX_DUMPED_DATA_LEN. By default, they are both 1024 characters. If it is necessary to dump larger blocks of data per line, these constants may be properly defined before including the “debug.h” header.

Asserting/Verifying Macros

  ASSERT ( Expression, LPCTSTR pcszFmt, … )

  ASSERTEX ( Expression, LPCTSTR pcszFmt, … )

  VERIFY ( Expression )

The ASSERT macro simly maps to the CRT’s _ASSERTE one.

The ASSERTEX macro allows you to display in the assert dialog a message formatted like the TRACE macro from this utility set does, and simultaneously write this message to the standard debug output and into the log file (if the latter is enabled).

The VERIFY macro acts as its MFC counterpart.

Downloads

Download source – 28 Kb