Click here to Skip to main content
Click here to Skip to main content

Fast, low latency and non-synchronizing trace class

, 16 Apr 2004
Rate this:
Please Sign up or sign in to vote.
An article about a ready to use trace class specialized for multithreaded programming.

Introduction

Did you ever tried to find a wired multithreading or synchronization bug using the normally provided method like TRACE() or OutputDebugString()? Did your debug compiled running fine, but your release application got a page fault?

A lot of useful information, which can be generated automatically, is missing in the traditional approaches and you have to provide it on your own. Most of the macros only work in debug mode and are not available in release mode.

But the major point is that, the timing and the flow of the application to be debugged is changed by using the debug tools.

I tried to find a thread synchronization bug in one of my applications and I developed the trace routines provided here as a solution.

Problems

The first problem is the timing, which is changed significantly, for example, by OutputDebugString(). Unfortunately the time depends on the debugger attached to show the output.

I have done 1.000.000 traces in a loop and measured the time for it:

TRACE-Macro
Debug-Code
No Debugger attached
28 sec.
TRACE-Macro
Debug-Code
VS.NET 2003 attached
1600 sec. (based on 20.000 traces)
TRACE-Macro
Debug-Code
DbgView
210 sec. (based on 100.000 traces)
Tracer
Debug-Code
9 sec.
Tracer
Release-Code
5 sec.

As you can see, Tracer is much faster and available even in release mode code.

The second problem which comes with OutputDebugString() is that, this routine seems to be synchronized itself. By using this routine in two concurrent threads very often, you can shift the timing by the internal synchronization of OutputDebugString() ***.

Basics

The trace classes write their output to normal text files on your drive. By using some special tricks, there is as less synchronization and latency as possible. For each thread tracing some information, the tracer creates one file in the application's directory named like "<exe-name>. trace.<threadid>". Each line in the tracing has the form:

00000128fd9f283f-00000320 : CCameraView::SetOptions() entered

The first part is the hardware timer value generated by QueryPerformanceCounter(). The second value is the thread id, which is generated by the tracing. By using the provided TraceMerge.exe utility, the different files can be merged to one big file, sorted by time.

The tracing is switched on and off using an environment variable. The name can be provided in the startup call.

Internals

The tracing code is implemented as a singleton class. The singleton can be accessed using CTracer::Get()->Trace(). The singleton maintains a map containing a TLSDataObject object for each thread. This class contains a big write buffer containing all the trace strings and the handle to the trace file. A critical section is provided for protecting the buffer.

When doing the first trace for a specific thread, the tracer create a TLSDataObject, stores it in the map and in a thread local storage (TLS) index. By using the TLS, a thread can access its own TLSDataObject without any synchronization to other threads. Only the insertion in the map (so the first trace) has to be synchronized.

Tracer starts a background thread which writes down the buffers of each thread. So for a short time, the tracing has to be stopped. But notice, that only the background thread and one application thread at a time are linked together.

Threads, which have been closed, are removed from the map from time to time to release the write buffer memory.

Using the code

Include "singleton.h", "tracer.cpp", "tracer.h", "CritSecLocker.cpp" and "CritSecLocker.h" to your project. Include "tracer.h" in all sources you want to trace.

In InitInstance() (or something similar), startup the tracing using:

CTracer::Get()->Startup("MYAPP_TRACE");

In ExitInstance() (or something similar) don't forget to call:

CTracer::Get()->Shutdown();

In your code, use:

CTracer::Get()->Trace("A number %d",123);

to produce a trace line. Note that appending "\n" is not allowed because it breaks the merging tool.

If you want to flush all available buffers, you may use

CTracer::Get()->Flush();

This writes all buffers of all threads and flushes the Win32 file buffers too. It's useful, for example, before aborting the application in an exception handler.

If you have a member function doing a lot of traces, providing a local reference is useful:

void foo(void)
{
    CTracer &l_tracer = CTracer::Get();

    ...

    l_tracer->Trace("fewfewoifnwefewf");

    ...

    l_tracer->Trace("fewfewoifnwefewf");
}

Using TraceMerger

To create one trace file from all the different files for each thread, a small utility has been provided.

Use it like this:

TraceMerger.exe <Application Exe Path>

TraceMerger will get all the trace files and merge sort them based on time. The results will be saved to a new file named <Application Exe Path>.trace.merge.

License

This package is licensed under The Artistic License.

*** If you know something about the OutputDebugString() synchronization, tell it to me...

License

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

About the Author

Tim Hagemann
Web Developer
Germany Germany
Being a software developer since 1992, I have seen many different programming languages, operating systems and methodologies.
 
My primary technical interest are C++ and Windows-Programming, but due to my work as a project manager, I have even seen J2EE.
 
My everyday work since a couple of years is leading software development teams, mostly in an agile way.
 

Comments and Discussions

 
GeneralUnderstanding Win32 "OutputDebugString" PinmemberDandy Cheung28-Jul-08 5:13 
GeneralOutputDebugString Synchronization PinmemberToby Opferman9-May-04 9:36 
GeneralRe: OutputDebugString Synchronization PinmemberToby Opferman9-May-04 9:56 
BTW, Windows now provides a facility called WMI that gets around this issue. These debug APIs may be a pain to implementat, but they are extremely fast and get around the synchronization issue. I had a syncrhonization issue once that even 1 outputdebug string would cause not to happen. However, I put like 50 print messages in using WMI and was able to find the problem immediately.
 
The WMI works faster since it creates a binary output file and it doesn't pass around any format strings. What happens is only the values passed to the format strings are sent, through another mechanism than I outlined above. You would have to read the MSDN details on it I am not currently that familar with it.
 
However, you can later use tools which then take the binary output and when you compiled you generated the format string tables. The output is then merged with the string tables and we have now generated the trace with a lot less overhead. This can also be used in retail builds as it can be turned on and off automatically using Microsoft tools as well. There's also almost no performance impact at all, even when the trace is on.
 
Windows Management Instrumentation services I believe is the name. I've heard it's simmilar to the debug service that was implemented in OS/2. I have never used OS/2 though.
 
http://msdn.microsoft.com/library/en-us/wmisdk/wmi/wmi_start_page.asp?frame=true
 
I think that's the location. I believe the system may require you to write your own driver to be a provider. Unfortunately, I'm not too familar with the system I simply used an existing implementation and build instrumentation so I didn't have to do anything to get it working. I'm pretty sure the underlying architecture used is WMI.
 


GeneralRe: OutputDebugString Synchronization PinmemberToby Opferman9-May-04 12:36 
QuestionVC 6? PinmemberWREY17-Apr-04 9:08 
AnswerRe: VC 6? PinmemberThomas Freudenberg18-Apr-04 5:25 
GeneralRe: VC 6? PinmemberWREY18-Apr-04 7:12 
GeneralRe: VC 6? PinmemberTim Hagemann19-Apr-04 1:29 
GeneralRe: VC 6? PinmemberToby Opferman9-May-04 8:16 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.

| Advertise | Privacy | Mobile
Web01 | 2.8.140721.1 | Last Updated 17 Apr 2004
Article Copyright 2004 by Tim Hagemann
Everything else Copyright © CodeProject, 1999-2014
Terms of Service
Layout: fixed | fluid