Using FastTrace

With FastTrace hiding the implementation details, all you need to do is link against FASTTRACE.DLL and start making calls to one of its exports, appropriately named FastTrace, whose prototype is shown here:

FASTTRACE_DLLINTERFACE void FastTrace ( LPCTSTR szFmt     ,                                         ...              ) ;

All tracing output you'll generate will go to files in the same directory as the executable process. Each file will have the following format:

<EXE Name>_<Process ID>_<Thread ID>.FTL

When you open an individual file, you'll notice it's a binary file. Each FastTrace output string is stored with a sequence number so that when merging the files together, the appropriate order can be maintained. Additionally, each output string can have an optional timestamp.

To keep FastTrace simple and fast, I chose to limit the length of a string to 80 characters. If you're running a debug build, you'll get a SUPERASSERT assertion to help you cull out longer strings. If you want longer strings, you can simply redefine MAX_FASTTRACE_LEN in FastTrace.H and rebuild the FastTrace solution.

The function SetFastTraceOptions allows you to set the three options for FastTrace by passing the FASTTRACEOPTIONS structure as a parameter. The first option lets you turn on write through writing. You might want to turn this on if you're chasing down a crash and want to ensure you get all traces immediately flushed as soon as they are written. This obviously slows down performance, so you should turn on this option only if needed. The second option allows you to turn on time stamping for each trace. Timestamps are off by default to squeak out a little more performance. You can turn timing on and off at will. The final option that you can specify is the debugging output function, which is prototyped to match OutputDebugString. By default, FastTrace doesn't call OutputDebugString, as I explained in Chapter 4; it causes an exception and will slow down your application. However, you'll probably want to see those exceptions in debug builds, so the option is there.

Two final functions will help you take control of your tracing. The first is FlushFastTraceFiles, which, as the name implies, will flush all the FastTrace buffers to disk. You might want to consider setting up a background thread that monitors when the server application isn't busy and periodically flushes the tracing. That way, you can ensure you get your traces into the file in case you crash.

The other function is SnapFastTraceFiles. Server applications don't have a definitive ending point, so you need a way to ensure you can look at your traces at any time. The SnapFastTraceFiles function closes any open trace files and renames them to indicate that you have snapped out the files. The naming scheme is as follows:

SNAP_<Snap Number>_<EXE Name>_<Process ID>_<Thread ID>.FTL

The snap number is a decimal number that is unique per process, so you can see the chain of snaps you have taken. After closing and renaming all active trace files, SnapFastTraceFiles reopens tracing files for each thread so that you won't miss a thing. As with FlushFastTraceFiles, you'll want a way to trigger your calls to SnapFastTraceFiles so that you can generate them when you need them. Also keep in mind that both SnapFastTraceFiles and FlushFastTraceFiles have to acquire a critical section to protect internal data structures, so it will block any trace calls during that time.

Merging Trace Logs

As I mentioned, the log files are in binary format, so use the FastTraceLog.EXE program to look at individual logs or combine logs to see the linear flow. Dumping a log to the screen is as simple as passing –d <Individual log file> on the FastTraceLog.EXE command line. The output will show the sequence number and if time stamping was turn on, the date/time followed by the individual trace string done at that time.

Merging, or combining, the log files is only a little more difficult. The command line passed to FastTraceLog.EXE is –c <Optional SNAP and number>_<EXE Name>_<Process ID>. For example, when you run the test program FTSimpTest.EXE, you'll see that it produces some of these trace file names:

FTSimpTest_2720_0400.FTL FTSimpTest_2720_1644.FTL FTSimpTest_2720_2332.FTL FTSimpTest_2720_2368.FTL FTSimpTest_2720_2424.FTL FTSimpTest_2720_2560.FTL FTSimpTest_2720_2584.FTL FTSimpTest_2720_2640.FTL FTSimpTest_2720_2688.FTL

The command to combine these individual thread logs is as follows:

FastTraceLog.exe -c FTSimpTest_2720

The merged trace file is written to a text file—in the preceding case, it's FTSimpTest_2720.TXT. The output in the text file looks very similar to the dump, and you can see that time stamping was on and turned off before the last line.

[0x0B3C 57 1/1/2003 17:52:47:205] Hello from CThread -> 3! [0x0B50 58 1/1/2003 17:52:47:205] Hello from CThread -> 3! [0x0B50 59 1/1/2003 17:52:47:486] Hello from CThread -> 4! [0x0B20 60 1/1/2003 17:52:47:486] Hello from CThread -> 4! [0x0B20 61 1/1/2003 17:52:47:767] Hello from CThread -> 5! [0x0830 62] THIS SHOULD BE THE LAST LINE!

The values in brackets represent the particular thread that generated the message, the sequence number, and the optional date/time stamp of the message, and on the line below the bracketed values is the trace message. I'm proud to point out that the date/ time stamp is internationalized, so the date will appear as you expect it for your local!