The Performance Hit with WriteIf and WriteLifeIf

One performance tip about WriteIf and WriteLineIf: They build the string even if the variable is false, and building strings is relatively slow. For instance,

Trace.WriteIf(someBool, "s1" + "s2" + "s3" + "s4");

will execute three string concatenations to build the string "s1s2s3s4". It does this even if someBool is false and the string does not need to be logged. In most real-world cases, this performance hit is negligible. However, if speed is critical, you'll get a small improvement by rewriting that line as

if (someBool)
    Trace.Write("s1" + "s2" + "s3" + "s4");

That way, you completely avoid the memory allocations caused by the string concatenations. Actually, this latter approach is slightly faster than using WriteIf even if you're not concatenating strings (because it entirely avoids making a function call when someBool is false). But you probably won't notice any difference unless you're executing this code hundreds of thousands of times.

The Indent and Unindent methods are straightforward, too: They introduce a level of tabbing. Indent can be called as many times as you like, and each call will indent the log text another tab. If you want, you can control the size of a tab with the IndentSize property. And if you want to jump to a certain indentation level without calling Indent/Unindent multiple times, you can just set the IndentLevel property. These methods are very useful for indicating conditions like a nested function call in the logs.

AutoFlush is a property on the Debug and Trace classes that determines whether the logs will be flushed to disk after each write. This property is set to false by default, which means that logged statements will first be written to a buffer and are flushed to the log file only periodically when the disk controller finds it convenient. The advantage of this is performance—it minimizes the number of slow disk writes. But the disadvantage is that you'll have to wait an indeterminate amount of time before your log messages appear, and in the event of a system crash, they may never show up. That's probably rare, though. For most applications, leaving this property set to the default false is fine.

That leaves us with everything explained except for the first line about Trace.Listeners.Add. That is how we specify where to send our logging output. While we're discussing that, we can also talk about.NET switches.

Listeners and Switches in .NET

As we discussed in Chapter 4, Microsoft designed the Debug and Trace classes to be very flexible. Rather than actually doing the logging directly, these classes essentially just broadcast a notification to anyone who's listening: "Hey! Somebody asked to log a message!" It's up to the listeners to decide what to do then. One listener might write that message to the debugging log. Another listener might write the message to the Windows event log, and a third listener might decide to e-mail the message. The point is that the Debug and Trace classes provide a hook to let you log any way you want. And if you decide to change that later, you simply need to change the line where you set the listener—all the rest of your logging code will not need to be modified.

.NET ships with three listeners defined in System.Diagnostics: DefaultTraceListener (writes to OutputDebugString—if you don't know what this is, then don't worry), EventLogTraceListener (writes to the event log), and TextWriterTraceListener (writes to a text file). You can add any or all of these listeners simultaneously. Any log messages will be passed to all the listeners you've selected, so you could have a message logged to multiple places.

Writing Your Own TraceListener

In Chapter 4, we wrote a TraceListener class to customize how asserts work. You can do the same thing to customize the behavior of logging. Do you want to have your log written in Adobe PDF format rather than plain text? Do you want your log to take into account how much disk space you have when deciding whether or not to log a marginally useful message? Do you want your log written one way on Thursday but a different way on Friday?

You might have to write a fair amount of code to create that listener object, but at least once you do, you could switch all your existing code to use the new logging method by changing only a single line. In fact, you could even put that single line in the XML config file and change the logging method without even recompiling your code!

But most developers won't find that necessary in day-to-day work— a good debugging log can almost always be implemented with TextWriterTraceListener. And as we've already seen, it's very easy to set this listener object on the Trace class. Still, the flexibility is there if you need it.

In addition to listeners, the System.Diagnostics namespace also provides the TraceSwitch class so users can dynamically turn logging on or off without a recompile. Actually, TraceSwitches are more flexible than simply on/off because they can have multiple states. Although it's perfectly fine to ignore those multiple states if you like, TraceSwitches have five different levels, so you could arrange for a certain type of message to be logged at level X, but a certain other type of message not to be. (In fact, if you wanted, you could use the TraceSwitch class to dynamically turn on/off ANY feature, not just logging. But logging is the most obvious use for that.)

The following lines create a switch object, set its level, and then log a message if the switch is enabled (which it is in this case):

using System.Diagnostics;
class SwitchExample {
   public static void Main() {
       TraceSwitch ts = new TraceSwitch("switchName", "description");
       ts.Level = TraceLevel.Verbose; //set switch to log everything
       Trace.WriteIf(ts.TraceError, "Log this");
   }
}

A TraceSwitch can be set to any of five different levels, as Table 5-1 describes.

But these levels have meaning only to the programmer, not to.NET. The logging class doesn't "know" whether a particular message is designated as an error or a warning. As far as the TraceSwitch is concerned, those are merely five unrelated boolean properties with no particular meaning. When logging a message, all .NET cares about is whether the level you specified is turned on.

See the difference? Those five levels are merely numbers. The names of those levels imply that level 1 equals "Errors", level 2 equals "Warnings", etc. But nobody's forcing you to follow that convention. If you think of the levels merely as 1, 2, 3 instead of Error, Warning, Information, then you could mentally redefine them to be anything you wanted. If you want to mentally define level 1 as "Messages created by my coworker" and level 2 as "Messages created by me", you could do it. Personally, I don't use the multi-level features of TraceSwitch. I prefer to use multiple switches instead. But many people do like multi-level switches, so it's good to know about the feature in case you ever come across it.

And that's how the TraceSwitch and TraceListener classes work! Well, except for one minor detail. If you've been paying attention, you may have noticed a problem with my TraceSwitch example:

using System.Diagnostics;
class SwitchExample {
    public static void Main() {
        TraceSwitch ts = new TraceSwitch("switchName", "description");
        ts.Level = TraceLevel.Verbose; //set switch to log everything
        Trace.WriteIf(ts.TraceError, "Log this");
    }
}

TraceLevel.Verbose means "log everything," so compile that code and you'll have full logging. Now how do we turn the logging off, or filter it down to a lower level? No problem—just change the level in the code and recompile. But wait a second. The whole point of the switch was to allow us to dynamically turn the logging on or off without recompiling. How do we do that? The trick lies in the application's XML config file.

XML Config Files

XML config files are new to.NET, and many .NET developers still haven't yet learned of their existence. Have you ever seen an application with an.INI file? Applications often need to save the user's settings from one run of the program to the next, and for years, the method of choice was to write those settings to a text.INI file (INI for INItialization). But after Windows 95 came out, Microsoft encouraged developers to store those user settings in the Windows registry rather than in.INI files. Now, though, we've come full circle. Each application in .NET automatically looks for an XML file called <yourExecutableName>.exe.config. If no such file exists, then the application will still run anyway; but if the file does exist, then .NET will read it to determine some configuration options.

You could store arbitrary information about your program in the config file, and your application can use the APIs in the System.Configuration namespace to read (but not write) those values. But the main thing that interests us when debugging is the ability to specify our TraceSwitches and TraceListeners in the config file. Modifying the config file allows us to change the logging behavior without recompiling our code. Let's look at a typical.config file:

<configuration>
   <runtime>

      ...
   </runtime>
   <system.diagnostics>
     <trace autoflush="true" indentsize="2">
        <listeners>
           <add name="myListener"
             type="System.Diagnostics.TextWriterTraceListener"
             initializeData="c:\\MyListener.log"/>
        </listeners>
     </trace>
     <switches>
        <add name="MySwitch" value="4" />
        <add name="YourSwitch" value="3" />
     </switches>
   </system.diagnostics>
</configuration>

Don't worry about writing your own config file. Visual Studio .NET will automatically output one for you when you create a new project, so you just need to add the extra details. Advanced developers may be interested in learning about the values inside the <runtime> area, but for now, we're only concerned about the values in <system.diagnostics>, because that's how we configure our switches and listeners. These values won't be created by VS .NET; we'll have to manually add them.

The <listeners> section is straightforward. Remember several pages ago when we set a listener on the Trace class with Trace.Listeners.Add? Now that we've specified a listener in the config file, there's no need to do it in the code anymore. Instead, we can use the config file to set the name of the listener (which doesn't really matter in most cases) and the type (for instance, TextWriterTraceListener or EventLogTraceListener). We can also do any necessary initialization of the listener (in the preceding example, we set the name of the file where we want to write our log data). And that's it! Now any messages written with Trace.Write will be sent to the file we specified. Want your log data to go to the Windows event logs instead? Just change this one line in your config file and you're done.

The <switches> section is only slightly more complicated. In the preceding example, I've added two switches—one for me, and one for you—and the value attribute corresponds to the TraceSwitch level we discussed before. There's one small tricky bit: Instead of referring to the level by the symbolic names (TraceLevel.Off, TraceLevel.Verbose, etc.), we have to use the numbers 0 through 4. This is mildly annoying, but it's not too great of a hardship.

In order to use a switch defined in the config file, we need to first define a switch with the same name in the code. But we still set the level in the config file. So the code looks like this:

using System.Diagnostics;
class SwitchExample {
    public static void Main() {
        TraceSwitch ts = new TraceSwitch("switchName", "description");
        //// ts.Level = TraceLevel.Verbose; //DON'T set this line in the code!
       Trace.WriteIf(ts.TraceInfo, "Whatever");
    }
}

Meanwhile the config file would contain these lines:

<switches>
        <add name=" switchName" value="3" />
</switches>

That way, you can still turn the switch on or off by merely changing the config file. Just make sure that you aren't setting the TraceSwitch's level in the code as well. Setting the level in the code will override the value you specify in the config file, so changes made to the config file would have no effect. If you ever notice your switches seem to be malfunctioning, search the code to see if someone is setting the switch level. If so, that's the problem.