Writing trace messages in multi-threaded C++ applications

• Download source files - 4 Kb

Introduction

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

/************ 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

/********** 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.

This article has no explicit license attached to it but may contain usage terms in the article text or the download files themselves. If in doubt please contact the author via the discussion board below.

A list of licenses authors might use can be found here