Trace, Trace, Trace, and Trace

Assertions might be the best proactive programming trick you can learn, but trace statements, if used correctly with assertions, will truly allow you to debug your application without the debugger. For some of you old hands out there, trace statements are essentially printf-style debugging. You should never underestimate the power of printf-style debugging because that's how most applications were debugged before interactive debuggers were invented. Tracing in the .NET world is intriguing because when Microsoft first mentioned .NET publicly, the key benefits were not for developers but rather for network administrators and IT workers responsible for deploying the applications developers write. One of the critical new benefits Microsoft listed was the ability of IT workers to easily turn on tracing to help find problems in applications! I was quite stunned when I read that because it showed Microsoft responding to the pain our end users experience when dealing with buggy software.

The trick to tracing is analyzing how much information you need for solving problems on machines that don't have the development environment installed. If you log too much, you get large files that are a real pain to slog through. If you log too little, you can't solve your problem. The balancing act requires having just enough logged to avoid a last-minute, 5,000-mile plane trip to a customer who just duplicated that one nasty bug—a plane trip in which you have to sit in the middle seat next to a crying baby and a sick person. In general, that means you need two levels of tracing: one level to give you the basic flow through the software so that you can see what's being called when and another level to add key data to the file so that you can look for data-stream–dependent problems.

Unfortunately, each application is different, so I can't give you an exact number of trace statements or other data marks that would be sufficient for your log. One of the better approaches I've seen is giving some of the newer folks on the team a sample log and asking whether they can get enough of a clue from it to start tracking down the problem. If they give up in disgust after an hour or two, you probably don't have enough information. If after an hour or two they can get a general idea of where the application was at the time of the corruption or crash, you've got a good sign that your log is contains the right amount of information.

As I mentioned in Chapter 2, you must have a team-wide logging system. Part of that logging system design has to consider the format of the tracing, especially so that debug build tracing is easier to deal with. Without that format, tracing effectiveness quickly vanishes because no one will want to wade through a ton of text that has no rhyme or reason to it. The good news for .NET applications is that Microsoft did quite a bit of work to make controlling the output easier. For native applications, you will have to come up with your own systems, but I'll give you some hints to get you going later in this chapter in the section "Tracing in Native C++ Applications."

Before I jump into the different platform-specific issues, I want to mention one extremely cool tool you always need to have on your development machines: DebugView. My former neighbor Mark Russinovich wrote DebugView and many other outstanding tools you can download from Sysinternals (www.sysinternals.com). The price is right (free!), many of the tools come with source code, and Mark's tools solve some very difficult problems, so you should visit Sysinternals at least once a month. DebugView monitors any calls to the user mode OutputDebugString or the kernel mode DbgPrint, so you can see any debug output when your application isn't running under a debugger. What makes DebugView even more useful is that it can burrow its way across machines, so you can monitor from a single machine all the machines that are part of a distributed system.

Tracing in Windows Forms and Console .NET Applications

As I mentioned earlier, Microsoft made some marketing noise about tracing in .NET applications. In general, they did a good job creating a clean architecture that better controls tracing in real-world development. I already mentioned the Trace object during the assertion discussion, because you should use it for your tracing. Like the Debug object, the Trace object uses the concept of TraceListeners to handle the output. This is why my ASP.NET assertion code changed the listeners for both objects: so all output would go to the same place. In your development, you'll want your assertion code to do the same thing. The Trace object's method calls are active only if TRACE is defined. The default for both debug and release build projects created by Visual Studio .NET is to have TRACE defined, so the methods are probably already active.

The Trace object has four methods to output trace information: Write, WriteIf, WriteLine, and WriteLineIf. You can probably guess the difference between Write and WriteLine, but understanding the *If methods is a little more challenging: they allow for conditional tracing. If the first parameter to the *If method evaluates to true, the trace happens; evaluating to false means it doesn't. That's quite convenient, but it possibly could lead to some big performance problems if you're not careful. For example, if you write code like that shown in the first portion of the next snippet, you will incur the overhead of the string concatenation every time the line executes because the determination for doing the actual tracing occurs inside the Trace.WriteLineIf call. You're much better off following the second method in the next snippet, where you use an if statement to make the call to Trace.WriteLine only when you need to, minimizing how often you must incur the string concatenation overhead.

// Paying the overhead every time Trace.WriteLineIf ( bShowTrace , "Parameters: x=" + x + " y =" + y ) ;     // Causing the concatenation only when necessary if ( true == bShowTrace ) {     Trace.WriteLine ("Parameters: x=" + x + " y =" + y ) ; } 

I think the .NET designers did us all a favor when they added the TraceSwitch class. With the *If methods for the Trace object allowing for conditional compilation, it took only a small step to define a class that provided for multiple levels of tracing and a consistent way to set them. The most important part of TraceSwitch is the name it's given in the first parameter of the constructor. (The second parameter is a descriptive name.) The name enables you to control the switch from outside the application, which I'll talk about in a moment. TraceSwitch objects wrap a tracing level. The levels are shown in Table 3-3. To check whether TraceSwitch matches a particular level, you use a set of properties, such as TraceError, that returns true if the switch condition is met. Combined with the *If methods, using TraceSwitch objects is quite straightforward.

public static void Main ( ) {     TraceSwitch TheSwitch = new TraceSwitch ( "SwitchyTheSwitch",                                               "Example Switch"  );     TheSwitch.Level = TraceLevel.Info ;     Trace.WriteLineIf ( TheSwitch.TraceError ,                         "Error tracing is on!" ) ;     Trace.WriteLineIf ( TheSwitch.TraceWarning ,                         "Warning tracing is on!" ) ;     Trace.WriteLineIf ( TheSwitch.TraceInfo ,                        "Info tracing is on!" ) ;     Trace.WriteLineIf ( TheSwitch.TraceVerbose ,                         "VerboseSwitching is on!" ) ; }

Table 3-3: TraceSwitch Levels

Trace Level	Value
Off	0
Error	1
Warnings (and errors)	2
Info (warnings and errors)	3
Verbose (everything)	4

The real magic of TraceSwitch objects is that they allow you to easily set them from outside the application in the ubiquitous CONFIG file. The switches element under the system.diagnostic element is where you specify the add elements to add and set the name and level. Listing 3-7 shows a complete configuration file for an application. Ideally you have a separate TraceSwitch object for each assembly in your application. Keep in mind that the TraceSwitch settings can also be applied to the global MACHINE.CONFIG.

Listing 3-7: Setting TraceSwitch flags in a configuration file

<?xml version="1.0" encoding="UTF-8" ?> <configuration>     <system.diagnostics>         <switches>             <add name="Wintellect.ScheduleJob" value="4" />             <add name="Wintellect.DataAccess" value="0" />         </switches>     </system.diagnostics> </configuration>

Tracing in ASP.NET Applications and XML Web Services

In spite of the very well designed Trace and TraceSwitch objects, ASP.NET, and by extension, XML Web services, have a completely different tracing system. Based on the location of ASP.NET tracing output, I can see why their systems are different, but I still find these differences confusing. The System.Web.UI.Page class has its own Trace object derived from System.Web.TraceContext. To help keep the different traces straight, I'll refer to the ASP.NET version as TraceContext.Trace. The two key methods for TraceContext.Trace are Write and Warn. Both handle tracing output, but the Warn method writes the output in red. Each method has three overloads, and both take the same parameters: the usual message and category with message versions, but also a version that takes the category, message, and System.Exception. That last version writes out the exception string as well as the source and line where the exception was thrown. To avoid extra overhead processing when tracing isn't enabled, check whether the IsEnabled property is true.

The easiest way to turn on tracing is to set the Trace attribute to true inside the @Page directive at the top of your ASPX files.

<%@ Page Trace="true" %>

That magic little directive turns on a ton of tracing information that appears directly at the bottom of the page, which is convenient, but it will be seen by both you and the users. In fact, there's so much tracing information that I really wish it were divided into several levels. Although seeing the Cookies and Headers Collections as well as the Server Variables is nice, most of the time you don't need them. All sections are self-explanatory, but I want to point out the Trace Information section because any calls you make to TraceContext.Trace appear here. Even if you don't call TraceContext.Trace.Warn/Write, you'll still see output in the Trace Information section because ASP.NET reports when several of its methods have been called. This section is also where the red text appears when you call TraceContext.Trace.Warn.

Setting the Trace attribute at the top of each page in your application is tedious, so the ASP.NET designers put a section in WEB.CONFIG that allows you to control tracing. This tracing section, named, appropriately enough, trace element, is shown here:

<?xml version="1.0" encoding="utf-8" ?> <configuration>     <system.web>         <trace             enabled="false"             requestLimit="10"             pageOutput="false"             traceMode="SortByTime"             localOnly="true"         />     </system.web> </configuration>

The enabled attribute dictates whether tracing is turned on for this application. The requestLimit attribute indicates how many trace requests to cache in memory on a per-application basis. (In just a moment, I'll discuss how to view these cached traces.) The pageOutput element tells ASP.NET where to show the trace output. If pageOutput is set to true, the output appears on the page just as it would if you set the Trace attribute in the Page directive. You probably won't want to change the traceMode element so that the Trace Information section in the trace is sorted by time. If you do want to see the sort by category, you can set traceMode to SortByCategory. The final attribute, localOnly, tells ASP.NET whether the output should be visible only on the local machine or visible to any client applications.

To see cached traces when pageOutput is false, append the HTTP handler, trace.axd, to the application directory, which will show a page that allows you to choose the stored trace you'd like to see. For example, if your directory is http://www.wintellect.com/schedules, to see the stored traces, the path would be http://www.wintellect.com/schedules/trace.axd. As soon as the requestLimit is reached, ASP.NET stops recording traces. You can restart the traces by viewing the trace.axd page and clicking the Clear Current Trace link at the top of the page.

As you can see, if you're not careful with tracing, your end users will be looking at them, which is always a little scary since developers are notorious for trace statements that could be career limiting if the output fell into the wrong hands. Luckily, setting localOnly to true keeps the trace viewing only on the local server, even when accessing the trace log through the trace.axd HTTP handler. To view your application trace logs, you'll simply have to use the greatest piece of software known to humankind, Terminal Services, so that you can access the server directly from your office and don't even have to get up from your desk. You'll want to update the customErrors section of WEB.CONFIG so that you have a defaultRedirect page, preventing your end users from seeing the ASP.NET "Server Error in 'AppName' Application" error if they try to access trace.axd from a remote machine. You'll also want to log that someone tried to access trace.axd, especially because an attempted access is probably an indication of a hacker.

At this point, some of you might be wondering about a particular problem with tracing in ASP.NET: ASP.NET has TraceContext.Trace send its output to one place, and DefaultTraceListener for the System.Diagnostic.Trace object sends its output someplace else. With straight ASP.NET, this is a huge problem, but if you use the BugslayerUtil.NET assertion code described earlier in the chapter, the ASPTraceListener is also used as the sole TraceListener for the System.Diagnostic.Trace object, so I redirect all traces to the TraceContext.Trace so that they show up in the same place.

Tracing in Native C++ Applications

Nearly all native tracing is done with a C++ macro traditionally named TRACE and is active only in debug builds. Eventually, the function called by the TRACE macro will call the Windows API OutputDebugString so that you can see the trace either in the debugger or in DebugView. Keep in mind that calling OutputDebugString causes a kernel mode transition. That's no big deal in debug builds, but it can have a negative impact on performance in a release build, so be aware of any calls you might have floating around in your release builds. In fact, when the Windows team was looking for ways to speed up the performance of Windows as a whole, they removed numerous traces we all used to rely on, such as the DLL load conflict message that occurred on a DLL load, and it contributed to a very nice performance boost.

If you don't have a TRACE macro, you can use the one I provide as part of BugslayerUtil.DLL. All the actual work takes place in the DiagOutputA/W functions in DIAGASSERT.CPP. The advantage to my code is that you can call SetDiagOutputFile and pass in a file handle as the parameter and record all tracing to a file.

In addition to providing the TRACE macro, Chapter 18 covers my FastTrace tool for native server applications. The last thing you want to do when it comes to heavily multithreaded applications is force all those threads to block on a synchronization object when you turn on tracing. The FastTrace tool gives you the highest possible tracing performance without losing the all-important flow of information.