Writing trace messages in multi-threaded C++ applications

• Download source files - 4 Kb

Introduction

Writing certain information into a trace file is very important for a complicated application.  This is true not only when you are debugging a program but also when your program is running in the production environment: a good trace file can help a lot if you are trying to diagnose or reproduce a mysterious problem.  But trace files can also get out of hand, I once worked with a complicated system while the trace file can grow to over 100 megabytes in size.  Performance is not the only issue.  Too much information in the trace file can actually hide the real problem.  Even if your program only writes minimal info into the trace file, the file size can still be too big when the program keeps running for weeks or months.  Another issue is how to generate trace messages in multi-threaded programs.  It is probably not a good idea to generate a new trace file for each separate thread, since threads are created on the fly in many server programs.

So what we need is an easy-to-use utility that works with multi-threaded programs and can dynamically control how much info is written (to the trace file).  There are already some great articles and sample code on this site dealing with this problem.  The code I provide with this article is based on my own experience, the readers can make up their own minds on whether my code is better or worse.

The Interface

Here is the header file you need to include when using my code.

/************ XYTrace.h **************/

#include <windows.h>

#include <tchar.h>

#include <stdio.h>


enum TraceLevel
{
    TraceNone = 0, // no trace

    TraceError = 10, // only trace error

    TraceInfo = 20, // some extra info

    TraceDebug = 30, // debugging info

    TraceDetail = 40 // detailed debugging info

};

extern void SetTraceFilePrefix(LPCTSTR strFilePrefix);
extern void SetTraceLevel(const int nLevel);
extern void WriteTrace(const int nLevel, LPCTSTR strFormat, ...);

/********** End of XYTrace.h **********/

Basically, there are only three functions to call.  The first function, SetTraceFilePrefix, is optional.  It determines where the trace file is created and how to name it.  By default, the trace file will be created in the current working directory with the name Trace_yyyymmdd_HHMMSS_XXXXXXXX.txt.  Here yyyymmdd_HHMMSS is the date-time stamp and XXXXXXXX is the hex process id.  If you make the following function call

SetTraceFilePrefix(_T("c:\\windows\\temp\\MyTrace"));

Then the trace file will be created in the directory c:\windows\temp and the name will be MyTrace_yyyymmdd_HHMMSS_XXXXXXXX.txt.  Note that if a trace file is already created, calling this function will close the old trace file and create a new one at a later time.

The second function, SetTraceLevel, controls what level of tracing you will get.  The current trace level is just a non negative integer.  The enum TraceLevel is an example of how to define various levels.  For example, you can have the following statements in your program

WriteTrace(30, _T("The current user is %s"), strUserID);
WriteTrace(20, _T("You are calling the set password service");
WriteTrace(10, _T("System error code = %d"), GetLastError());

The first parameter in the above function calls is the intended trace level for the corresponding trace message.  If the current trace level is greater than or equal to 30, then all three messages will be written to the trace file.  If the current trace level is 10, then only the last message will be written.  If the current trace level is 0, then no message will be written.  Programs can dynamically invoke this function to change its current trace level.  Let's say user reported a production problem in your program.  What you can do is increase the current trace level at run-time (without shutting down), reproduce the problem with detailed trace file, and then decrease the current trace level.  In one of my own programs, I read and reset the current trace level from a .ini file every 2 minutes so that if I want more or less tracing, it is a simple matter of changing the .ini file.

As you can see, the third function WriteTrace may cause a message to be written to the trace file (depending on the current trace level).  The first parameter is the intended trace level for the current message, the second one is a format string, and there can be one or more other parameters.  The format string and the other parameters work exactly as in our old friend printf.

All the three functions are thread-safe, meaning that you can use them in whatever way or whatever order you wish in a multi-threaded application.  Each trace message will end with a new line and it will also be prefixed with a time stamp and the current thread id, like the following

HH:MM:SS_MLS_XXXXXXXX: the actual trace message ...

Here HH:MM:SS_MLS is the time stamp down to milliseconds, and XXXXXXXX is the hex thread id.

What happens if your programs have to run continuously for days and weeks?  Don't worry.  When it goes into a different day, the old trace file will be closed and a new one will be used (automatically!).  It is not hard to hack the code so that a new trace file is only created once a week or once a month.  Isn't it great?

The Implementation and Sample Code

To avoid inconvenience to the users, I have refrained from using any library in my implementation (no MFC, ATL, STL, etc.), just straightforward C++ and Win32 APIs.  I even coded my own version of Lock/Unlock methods to handle multi-threaded environment, which is not hard to do by the way.  To use this utility in your own programs, you need only to add the XYTrace.h and XYTrace.cpp files to your projects and include the header file wherever needed.  Here is a multi-threaded console application that demonstrates the use of these three functions.

/********** Sample Program ******************/

#include <process.h>

#include "XYTrace.h"


void ThreadProc1(void *dummy)
{
    double dblSoft = 872.32;
    double dblHard = 1234.23;
    while(true)
    {
        // write trace messages every 5 seconds

        WriteTrace(TraceInfo,_T("Software = $%3.2lf, hardware = $%3.2lf"),
            dblSoft, dblHard);
        WriteTrace(TraceInfo,_T("Total = $%3.2lf"), 
            dblSoft+dblHard);
        ::Sleep(5000);
    }
}

void ThreadProc2(void *dummy)
{
    TCHAR strTitle[] = _T("\"Hello, world\"");
    TCHAR strText[] = _T("\"This is a test\"");
    while(true)
    {
        // write trace messages every 5 seconds

        WriteTrace(TraceDebug,_T("Title = %s, text = %s"), strTitle, strText);
        ::Sleep(5000);
    }
}

void main()
{
    // set up the trace file (directory and name prefix)

    SetTraceFilePrefix(_T("c:\\temp\\MyTrace"));
    // update trace level

    SetTraceLevel(TraceInfo);
    // write the first trace message

    WriteTrace(TraceInfo, _T("This is the main thread"));
    // create two separate threads, each of them writes trace messages repeatedly

    if(_beginthread(ThreadProc1,0,NULL)==-1||_beginthread(ThreadProc2,0,NULL)==-1)
    {
        // failed to create thread

        return;
    }
    // change trace level every 20 seconds

    while(true)
    {
        ::Sleep(20000);
        SetTraceLevel(TraceDebug);
        ::Sleep(20000);
        SetTraceLevel(TraceInfo);
    }
}

/********** End of Sample *******************/

And here is the output of the above sample program:

16:12:18_230_FFFA7351: This is the main thread
16:12:18_280_FFFA60D5: Software = $872.32, hardware = $1234.23
16:12:18_280_FFFA60D5: Total = $2106.55
16:12:23_340_FFFA60D5: Software = $872.32, hardware = $1234.23
16:12:23_340_FFFA60D5: Total = $2106.55
16:12:28_610_FFFA60D5: Software = $872.32, hardware = $1234.23
16:12:29_100_FFFA60D5: Total = $2106.55
16:12:34_160_FFFA60D5: Software = $872.32, hardware = $1234.23
16:12:34_210_FFFA60D5: Total = $2106.55
16:12:39_210_FFFA60D5: Software = $872.32, hardware = $1234.23
16:12:39_270_FFFA60D5: Total = $2106.55
16:12:43_270_FFFA6549: Title = "Hello, world", text = "This is a test"
16:12:44_260_FFFA60D5: Software = $872.32, hardware = $1234.23
16:12:44_320_FFFA60D5: Total = $2106.55
16:12:48_270_FFFA6549: Title = "Hello, world", text = "This is a test"
16:12:49_320_FFFA60D5: Software = $872.32, hardware = $1234.23
16:12:49_320_FFFA60D5: Total = $2106.55
16:12:53_330_FFFA6549: Title = "Hello, world", text = "This is a test"
16:12:54_370_FFFA60D5: Software = $872.32, hardware = $1234.23
16:12:54_370_FFFA60D5: Total = $2106.55
16:12:59_420_FFFA60D5: Software = $872.32, hardware = $1234.23
16:12:59_420_FFFA60D5: Total = $2106.55
...

Thank you for reading.  Don't forget to check out my other articles and software.
 

History

28 Jan 2002 - updated source files.