Overview
When an application is running it is often necessary to record the path taken through the code by a user request. It may be the case that the user has found a fault in the application and wants to send detailed data to the development team in order to debug the issue, or it may be that the development team wants to understand more about the performance profile of some part of their application – generally to see where the application spends most of its time.These and other scenarios can be addressed by using the tracing facilities in .NET. Prior to .NET version 2.0 there were limited trace facilities in the framework – you were limited to one trace source and multiple trace listeners. This meant in effect that you couldn’t trace just the code in one assembly – it would be polluted with data from all other running code, making it hard to see where a given issue arose.
In addition the amount of trace data available was also limited – for example you couldn’t obtain details such as a stack trace or the thread ID without significant extra code. These and other issues have now been addressed in .NET 2.0 and the tracing facilities have been expanded to cope with other scenarios too.
In the following sections we'll describe in general terms the pieces that make up the tracing framework within .NET. These are just overviews – we’ll go into further detail later in the paper.
Trace Source
The System.Diagnostics.TraceSource class supersedes the System.Diagnostics.Trace class and should be used in place of this class wherever tracing is needed. It is designed to be used as a shared object, available to code within a namespace or assembly. There could be multiple trace sources active at any time within an application – they are designed this way so that you can enable or disable sources as appropriate without recompiling the code.As an example, consider an application that uses Windows Communication Foundation to communicate to a server. You may want to enable tracing for just the application itself, the application and WCF, the application, WCF and the server services, or any other combination of these. In addition there may be other trace sources on one of these tiers – for example WPF has its own sources, as does System.Transactions and several other parts of .NET.
There are two typical scopes where it makes sense to define a trace source – either on an assembly by assembly basis or on a namespace by namespace basis. As the TraceSource object is just a class you could construct a source for a particular class, or indeed for a particular method, however we would recommend a less fine grained setting such as per assembly or namespace.
Trace Listener
When a trace source has been defined it is also necessary to add one or more TraceListener instances to that source. A listener is simply a sink where messages from a trace source are written. There are a number of listeners built into .NET, however if these do not satisfy your requirements then you can always construct your own.Trace Filter
When messages are raised by a TraceSource it may be necessary to filter these so that only certain messages are actually logged. The TraceSource already defines a ‘level’ that is used to determine whether a particular category of message is actually written to the listener(s), however you may also want to have more fine grained filtering on messages which is where the TraceFilter class comes in.Each listener can have at most one filter defined, and each filter is derived from the abstract TraceFilter class. There is one method defined on this class which is called when a message is about to be traced – that being the abstract ShouldTrace() method.
A listener can have at most one filter defined, so for example you could have one trace source with two listeners, and one listener could record just critical events whilst the other could record all events. A good example would be when using the EventLog to log messages – this should typically only be used for critical events as it’s not really designed to include lots of debug messages.
Tracing in depth
In this section we’ve taken the concepts presented in the overview above and present a full breakdown of how to add tracing to an application, and also how to view the logs that are generated.Constructing a TraceSource
You can construct as many TraceSource instances as you wish – however in practice it makes sense to limit the number of sources to either one per assembly or one per namespace. In this example I’ll use one TraceSource for the client application, one for the processing assembly, and one within the WCF service.The code below constructs a TraceSource instance and stores it as a static property so that it can be accessed within the client application.
/// <summary>
/// This class exposes the trace source for use by the client application
/// </summary>
internal class ClientAppTrace
{
/// <summary>
/// Construct the trace source
/// </summary>
static ClientAppTrace()
{
// Set the default level of this trace source to Critical.
// In the absense of any other configuration this will ensure that
// only critical messages are output
_clientAppSource = new TraceSource("ClientApp", SourceLevels.Critical);
}
/// <summary>
/// Get the trace source for the client app
/// </summary>
internal static TraceSource TraceSource
{
get { return _clientAppSource; }
}
/// <summary>
/// Store the single trace source instance
/// </summary>
private static TraceSource _clientAppSource;
}
Within the static constructor we create the TraceSource instance. There are two constructors on TraceSource – each has a name parameter (the first) and the one shown above provides a default for the level of output expected from this source. Here we’ve defined SourceLevels.Critical, which in the absence of any other configuration information will ensure that only trace events with their level set to Critical will be output.
Tracing Events
Once a TraceSource has been constructed you then need to add code within your application to raise trace events. The TraceSource class contains a number of members that allow you to raise events – these are shown in the table below with some explanation as to what they do.| Method | Description |
|---|---|
| TraceData (TraceEventType, Int32, Object) | Writes the integer and the object to the trace listener(s), typically by using the ToString() method of the object passed to this call. You don't have to use ToString in your listener - indeed if you pass an object that is derived from XPathNavigator and you have the XmlWriterTraceListener defined then this will write out the full XML of the object passed to it. |
| TraceData (TraceEventType, Int32, params Object[]) | Writes the integer and the collection of objects to the trace listener(s). |
| TraceEvent (TraceEventType, Int32) | Writes the integer to the trace listener(s). |
| TraceEvent (TraceEventType, Int32, String) | Writes the integer and the string to the trace listener(s). |
| TraceEvent (TraceEventType, Int32, String, params Object[]) | This uses the passed string as the format specification in a call to string.Format(). The object array is used as the argument array to this function. The integer and formatted string are written to the trace listener(s). |
| TraceInformation (String) | Trace an informational message – this will only be displayed in the trace output if the source level is set to Information or Verbose. |
| TraceInformation (String, params Object[]) | Uses the passed string and object array in a call to string.Format(), and outputs this if the source level is set to Information or Verbose. |
The TraceEventType argument is an enumerated constant defined as one of the following options.
| TraceEventType | Value |
|---|---|
| Critical | 0x0001 |
| Error | 0x0002 |
| Warning | 0x0004 |
| Information | 0x0008 |
| Start | 0x0100 |
| Stop | 0x0200 |
| Suspend | 0x0400 |
| Resume | 0x0800 |
| Transfer | 0x1000 |
When a call is made to any of the Trace methods shown in the table above, the TraceEventType is logically ANDed with the SourceLevels value used in the TraceSource constructor, and if the levels match (i.e. the result of the logical-AND is non zero) then the trace data is written to each listener. We’ll describe the Start/Stop/Suspend/Resume and Transfer types later in the document.
The SourceLevels enumerated values are defined as follows.
| SourceLevels | Value |
|---|---|
| All | 0xFFFF |
| Off | 0x0000 |
| Critical | 0x0001 |
| Error | 0x0003 |
| Warning | 0x0007 |
| Information | 0x000F |
| Verbose | 0x001F |
| ActivityTracing | 0xFF00 |
So, if you were to specify SourceLevels.Error when defining the TraceSource, then only events marked as Warning, Error or Critical would be logged.
Configuring a TraceSource
The TraceSource can be configured within code, but this is more typically going to be done by defining trace options within the application configuration file. The simplest thing you can do within the configuration file is to define a value from the SourceLevels enumeration, so despite defining in the code that the default is to output only Critical events, you can change this by adding the following to the configuration file.
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<system.diagnostics>
<switches>
<add name="ClientApp" value="All"/>
</switches>
</system.diagnostics>
</configuration>
Here we have defined a switch with the name ‘ClientApp’ and the value set to ‘All’. Within the TraceSource class the Initialize() method checks if there is a trace switch defined in the config file with the same name as the TraceSource. If so, the value is parsed and converted to a value from the SourceLevels enum. With the above in place, all events raised from the code will be written to the trace listeners.
There are however a couple of other ways to define the level for a TraceSource.
Configuring using a shared switch
There may be times when you need to enable tracing at a certain level for multiple trace sources. Rather than adding in multiple switches and changing each of these, you can share a switch value across multiple trace sources by defining the switchName attribute on each source, and adding in a switch into the <switches> section of the configuration file.
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<system.diagnostics>
<sources>
<source name="ClientApp" switchName="SharedSwitch"/>
<source name="ProcessingCode" switchName="SharedSwitch"/>
</sources>
<switches>
<add name="SharedSwitch" value="All"/>
</switches>
</system.diagnostics>
</configuration>
In the configuration file above we have defined two trace sources (given the same name as that used in code when constructing the TraceSource instance), and have set the switchName attribute to SharedSwitch. Thus both the ClientApp and ProcessingCode trace sources use the same switch value. If the switchName attribute is defined then this takes precedence over a switch with the same name as the TraceSource.
Configuring the switch value inline
In addition to the two methods above there is a third way to define the level that the trace source will use – you can specify the switchValue attribute of the source to one of the values from the SourceLevels enumeration.
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<system.diagnostics>
<sources>
<source name="ClientApp" switchValue="Verbose" />
</sources>
</system.diagnostics>
</configuration>
This doesn’t require the use of a separate <switch> element in the configuration file, but is functionally equivalent to defining a switch with the name set to ClientApp and value set to Verbose.
As in the shared switch example, the use of the switchValue attribute takes precedence over a named switch. Note that defining both the switchName and switchValue attributes will result in an exception – these are mutually exclusive.
Other TraceSource attributes
The TraceSource class also supports a couple of other attributes. If you define the switchType attribute this is used when constructing the Switch property of the TraceSource class. Your class must derive from the SourceSwitch class, and typically will have a constructor that has one string parameter. When the TraceSource is constructed it will also construct an instance of this switch class, and pass the value from switchValue to it. Thus you can have your own switch type such as 'DaysOfTheWeek', and set the value to 'Saturday, Sunday' to only log events on these days if appropriate.If you derive a class from TraceSource, you can optionally permit custom attributes to be defined and parsed from the configuration file. In order to do this it is necessary to override the GetSupportedAttributes method of TraceSource to return a collection of permitted attributes. These will be read into a StringDictionary and set as the Attributes property of your class. It’s then up to you what you want to use these attributes for. As both of the above items are used in custom solutions we won’t discuss these further on this site.
Trace Listeners
Up to this point in the document we’ve not described how or where trace output is written. If you have typed in any of the code and output some trace data you may have noticed that this output has been directed to the Output window in Visual Studio.The tracing subsystem in .NET uses classes derived from TraceListener to provide output – and by default a single listener is defined which outputs trace data to the Debug stream (using the OutputDebugString API function under the covers). There are two main ways to view this data – either by running your application within Visual Studio, or by using the DebugView tool available for download from Microsoft.
Note
If you are using DebugView in a server application it will serialize calls when writing debug information, and therefore should be used with caution in server scenarios. We would recommend clearing the trace listeners collection within the configuration file and then adding in just the listeners you require. An example is shown in the following section.
You will most probably want to output trace information to somewhere other than the debug stream, and this is where trace listeners come in.
Defining Trace Listeners
You can define trace listeners in code, however once again we would recommend using the configuration file approach which is what we will discuss here.There are two places within the configuration file that you can define listeners – you can define a set of shared listeners that can be used by all TraceSource instances by specifying these listeners in the <sharedListeners> section, and you can also define listeners that apply to a specific trace source by including the details of the listener within the traceSource element.
The configuration file below shows an example of defining a shared listener and also a listener that is only used for a single trace source.
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<system.diagnostics>
<sources>
<source name="ClientApp" switchValue="All">
<listeners>
<clear/>
<add name="EventLog"
type="System.Diagnostics.EventLogTraceListener"
traceOutputOptions="DateTime,ThreadId,Timestamp"
initializeData="ClientAppEventLog"/>
<add name="xml"/>
</listeners>
</source>
</sources>
<sharedListeners>
<add name="xml"
type="System.Diagnostics.XmlWriterTraceListener"
traceOutputOptions="Callstack,LogicalOperationStack,ProcessId "
initializeData="C:\logs\Test.svclog"/>
</sharedListeners>
</system.diagnostics>
</configuration>
Here we have defined a single trace source, and it has two trace listeners defined. The first, the EventLogTraceListener logs entries into the Windows event log. The second writes data to an XML file on disk.
There are a number of event listeners available with the .NET framework, and if these do not suffice for your needs you can always write your own. The inbuilt listeners are listed in the table below.
| Name | Description |
|---|---|
| DefaultTraceListener | Logs all events to the Debug stream. |
| EventProviderTraceListener | Writes events to Vista’s ETW infrastructure. Highly performant. |
| EventLogTraceListener | Logs events to the system wide event log. |
| TextWriterTraceListener | Sends output to a TextWriter or Stream. |
| ConsoleTraceListener | Writes events to the Console stream. |
| DelimitedListTraceListener | Writes output in a delimited format (by default a semicolon). Useful for importing logs into Excel. |
| EventSchemaTraceListener | Logs events in a standardised manner so that tools can read these events. The logs created are in an XML format. Highly performant. |
| XmlWriterTraceListener | Writes the output data to an XML file. |
You can add as many or as few listeners to the configuration file. Each listener can be further configured using attributes within the config file. In the example above we have specified a set of TraceOutputOptions for each listener – these define what is written by the listener. These options are defined within the config file as a comma-delimited list, and the options are Callstack, DateTime, LogicalOperationStack, None (the default), ProcessId, ThreadId and Timestamp.
These values give you a lot more information that was available with the 1.x versions of the framework. More information on writing events in Windows Vista (and also Windows Server 2008) can be found at here.
Trace Filters
The last main area of extension for tracing is the use of the TraceFilter class. A filter is used to determine whether a given event should be traced, and derives from the abstract TraceFilter class.There are two built-in trace filters – the SourceFilter which determines if an event should be traced by testing the name of the source that raised the event, and the EventTypeFilter which determines whether to log the event based on a value from the SourceLevels enum.
In this section we’ll describe a custom filter that only records events from a set of pre-defined methods. This might be useful when tracking down a problem as it allows you to have fine-grained control over which methods are traced and which are omitted. This is an over-simplified example of what's available within the logging framework presented on this site. The code below shows a simple implementation of this custom trace filter.
public class MethodFilter : TraceFilter
{
public MethodFilter(string options)
{
_options = options;
}
public override bool ShouldTrace(TraceEventCache cache, string source,
TraceEventType eventType, int id,
string formatOrMessage, object[] args,
object data1, object[] data)
{
return true;
}
private string _options;
}
This filter doesn’t actually filter anything at the moment, and simply returns true from the ShouldTrace method. The .NET framework will call this method for each event that is raised, and information about the event itself is available from the parameters passed to the method.
To hook this filter into the application you should alter the configuration file as shown below.
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<system.diagnostics>
<sources>
<source name="ClientApp" switchValue="All">
<listeners>
<clear/>
<add name="EventLog"
type="System.Diagnostics.EventLogTraceListener"
traceOutputOptions="DateTime,ThreadId,Timestamp"
initializeData="ClientAppEventLog">
<filter type="ClientApp.MethodFilter, ClientApp" initializeData="UI"/>
</add>
</listeners>
</source>
</sources>
</system.diagnostics>
</configuration>
When the framework initializes the trace listeners and filters it will check if the initializeData attribute has been defined (and is not empty). If so it will attempt to call a constructor on the filter class which takes a string parameter. If the initializeData attribute is missing or empty then the default constructor will be called. This can cause your code to fail if a default constructor is not defined, or conversely if you don’t have a constructor which takes a single string parameter. The error message shown isn’t all that helpful either, so it’s best to ensure that your trace filter has both constructors, and uses an appropriate default value if no initializeData attribute is defined.
As this filter is intended to filter method calls to a set of known methods, we need some way to define which methods to log and which to omit. We’ll use a custom configuration section handler to provide a list of methods that should be traced using the configuration file schema as shown below.
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<configSections>
<section name="methodFilters" type="ClientApp.MethodFiltersSection, ClientApp"/>
</configSections>
<system.diagnostics>
...
</system.diagnostics>
<methodFilters>
<methodFilter name="UI">
<method name="mainForm.buttonPlus_Click"/>
<method name="mainForm.buttonMinus_Click"/>
</methodFilter>
</methodFilters>
</configuration>
Here we’ve defined a custom section <methodFilters> and within that a named set of methodFilter elements. Within the <methodFilter> element we’ve defined the <method> element which names a method that should be considered for trace output.
The code within the MethodFilter class has been updated too – the initializeData attribute in the configuration file names the <methodFilter> element that should be used when filtering events. So, with the configuration file as above (including the system.diagnostics section from the previous example) the code will only produce a trace event if the call stack includes the mainForm.buttonPlusClick or the mainForm.buttonMinusClick methods.
The updated code for the MethodFilter is shown below.
public class MethodFilter : TraceFilter
{
public MethodFilter(string name)
{
_methods = new List<string>();
MethodFiltersSection section = ConfigurationManager.GetSection("methodFilters")
as MethodFiltersSection;
if (null != section)
{
MethodFilterElement mfe = section.MethodFilter[name];
if (null != mfe)
{
foreach (MethodElement me in mfe.Methods)
_methods.Add(me.MethodName);
}
}
}
In the constructor we create a list used to store method names, and then lookup the named <methodFilter> section. If found we then iterate through each <method> element and add it to the collection that maintains the list of methods that tracing is enabled for.
public override bool ShouldTrace(TraceEventCache cache, string source,
TraceEventType eventType, int id,
string formatOrMessage, object[] args,
object data1, object[] data)
{
bool shouldTrace = false;
if (null != _methods)
{
for (int pos = 0; pos < _methods.Count; pos++)
{
if (cache.Callstack.Contains(_methods[pos]))
{
shouldTrace = true;
break;
}
}
}
return shouldTrace;
}
private List<string> _methods;
}
In the ShouldTrace method we then iterate through the list of methods, and check if the callstack (available as string on the TraceEventCache object) contains the method name. If so we return true and hence the event will be traced. Any call stack that does not contain a method name read from the configuration file is not traced.
Note - Using the Callstack in a filter can adversely affect performance. Grabbing a callstack is a relatively slow operation, so only use this if absolutely necessary, and then only in debug builds.
There are many other ways that you could use the parameters passed to the ShouldTrace method in order to manufacture a trace filter appropriate for your situation. You might want to use a combination of the call stack and source parameter, or the id passed to the filter to enable or disable event logging. You could also use the arguments passed to the ShouldTrace function – for example you may have a bug that can only be replicated when an object (let’s say it’s a bitmap) of a particular size or dimension is passed to a function.
Tracing in practice
Now we have provided a thorough understanding of the TraceSource, TraceListener and TraceFilter classes, we’ll describe in this section how you could utilise the facilities available with the .NET tracing framework in your own code.Method entry and exit
A fairly common request is to be able to trace the start and end of a method, and you’re typically doing this so as to get some understanding of how long a method takes to execute. With the facilities already mentioned you probably have an idea how to do this already. In the example below we’ve assumed that there is a static TraceSource available, and have added code to log both the start and the end of a method.
private void buttonDivide_Click(object sender, EventArgs e)
{
ClientAppTrace.TraceSource.TraceInformation("Started buttonDivide_Click");
...
ClientAppTrace.TraceSource.TraceInformation("Finished buttonDivide_Click");
}
With these two lines in place the logs will record the entry and exit from the method. Note however that you also need to define the traceOutputOptions attribute within the configuration file for the listener(s) to include DateTime and/or Timestamp (the latter is a tick count).
Adding the above code to each method is a little unwieldy, and in the face of exceptions the Finished message might not be output. In order to minimise the amount of code needed to expose method entry and exit traces we would recommend creating a class to wrap entry/exit calls in a disposable class which will simplify generation of method entry/exit log information, and can also simplify other logging operations too. Your code might then look something like that below.
private void buttonMinus_Click(object sender, EventArgs e)
{
using (Log methodLog = Log.BeginTrace(ClientAppTrace.TraceSource, 123,
"buttonMinus_Click", false, "{0},{1}", sender, e))
{
methodLog.TraceInformation("Inside the using block, about to sleep");
Thread.Sleep(1000);
methodLog.TraceInformation("Finished Sleeping");
}
}
The object within the using clause outputs a method start trace entry at the start of the code, and when the object is disposed it records a method stop trace. The output from this set of traces shown on the debug log is as follows.
ClientApp Start: 123 : buttonMinus_Click (System.Windows.Forms.Button, Text: -,
System.Windows.Forms.MouseEventArgs)
ClientApp Information: 123 : Inside the using block, about to sleep
ClientApp Information: 123 : Finished Sleeping
ClientApp Stop: 123 : buttonMinus_Click
The number ‘123’ is an arbitrary ID that is associated with a logical operation. In the above trace you’ll see the ‘Start’ and ‘Stop’ events as well as informational events. We said earlier that we would discuss these events and also Suspend, Resume and Transfer and these are the subject of the next section.
Logging other events
In addition to logging informational messages you may also want to be able to log particular operations, such as running a long computation or logging between different assemblies in an application.The TraceSource class exposes a number of methods for logging events, and uses the TraceEventType to define the type of event that is being logged. We briefly mentioned the Start/Stop/Suspend/Resume and Transfer events earlier in the document, and in this section we’ll describe these more fully.
Trace data raised from your application typically has two types – typically either errors being logged or informational messages. With the .NET tracing framework it is possible to categorise types of information further, so you can use an informational message but you could further refine this with one of the types mentioned.
As an example, in the method entry and exit section you saw events categorised as ‘Start’ and ‘Stop’. These were raised by the Log object on entry to and exit from a function. This is a good use of these event types and it makes it easy to spot method calls in the traces produced.
Similarly there are often sections of code in a multi-threaded application that have to wait for some data to be returned. These are good candidates for the Suspend and Resume event types. You could imagine constructing a wait handle and logging a Suspend message immediately prior to waiting on that handle, and when the wait was completed you would raise a Resume event. The code below shows an example of where a suspend/resume pair might be used.
using (Log methodLog = Log.BeginTrace(ClientAppTrace.TraceSource, 456,
"buttonTimes_Click", false))
{
methodLog.TraceEvent(TraceEventType.Suspend, 456, "Waiting for data...");
_waitObject.WaitOne();
methodLog.TraceEvent(TraceEventType.Resume, 456, "Received data");
}
In the above we’ve logged a Suspend event immediately prior to waiting on an object (in this case it’s a class derived from WaitHandle), and then raised a Resume event after that wait has completed.
The only other undefined event type is Transfer.
When you call from one section of code to another (say from your client library to your processing library) it is often useful to know that this transition has been made. That’s what the Transfer event is used for and it is discussed in the following section.
Tracing between tiers
Arguably the most useful facility available with the new tracing architecture in .NET is its ability to correlate traces between application tiers. In a typical application you may have some client code, some form of communication code, and some code that executes requests on the server.To effectively debug an issue it is necessary to be able to correlate activity on the client with that of the transport and also the server. The tracing facilities within .NET have the ability to do this by using the CorrelationManager class defined in System.Diagnostics.
This class maintains an ActivityId property (a GUID) which can be set when a logical operation begins, so you would typically set this to a value when starting an operation. Consider the example below where a client application calls a service over WCF.
Here the user initiates some action that is routed over the transport to the server. The server processes the request and sends some form of response back to the client. Being able to correlate activity between hosts is crucial when debugging as then you can follow the path of a request between different tiers of the application. In the example above there are three places where a request can be traced – the client application, the communication transport and the server.
With .NET tracing you could define a trace source for each of these as shown in the image below.
Here there are two log files, one for operations that execute on the client (and the client half of the communication transport), and one for operations on the server (including the server portion of the communications). Note that it is not necessary to have the trace sources writing to the same file – you could just as easily have one file on the client for the client operations, one on the client for the communication transport and so on. Indeed the data doesn’t necessarily have to be stored within a file – you could use any of the trace listeners defined by .NET or maybe use a home-grown listener that logs events to a SQL database.
The important part of this is the ActivityId. This GUID value can be set in your own code at the start of the operation. This value is set on the logical call context, which has been around since .NET 1.0 and it allows you to store state that is essentially thread specific (that’s not quite true but will suffice for this example).
This ActivityId is then available to objects along the call chain, and the WCF designers have also added the ability to flow this Id between client and server by setting an attribute on the System.ServiceModel trace listener. When this attribute is defined, WCF includes an extra element in the SOAP header sent across the wire, and the receiver can then set its ActivityId to that obtained from the other end of the connection.
With this facility in place it is therefore possible to correlate a request between tiers in an application. In order to simplify correlation it is common to use the Transfer event to indicate a logical break between different sections of code. In the above example you might transfer from the main application into the operation the user executed, then from that into the service layer where the message is routed to the server. On the server end you then might transfer into your processing method and ultimately return data back to the caller.
A Transfer event is used to indicate that processing has moved from one area to another – so in the above example there could be a transfer event raised when the user clicks on a button (which indicates the start of an operation), a transfer into a second assembly that makes the WCF call, and possibly other transfers as the code within the WCF library is executed. Similarly there may be transfer calls within the server to indicate that WCF is now calling the server method(s).
When a transfer from one section of code to another occurs, it is typical to indicate this change by altering the ActivityId. The following method shows an example of how this might look in code...
public void DoSomething(TraceSource source)
{
Guid oldActivityId = Guid.Empty;
try
{
oldActivityId = Trace.CorrelationManager.ActivityId;
Guid newActivityId = Guid.NewGuid();
source.TraceTransfer(111, "Calling service", newActivityId);
Trace.CorrelationManager.ActivityId = newActivityId;
// Call service here...
}
finally
{
source.TraceTransfer(111, "Return", oldActivityId);
Trace.CorrelationManager.ActivityId = oldActivityId;
}
}
Here the current value of the ActivityId is read from the Trace.CorrelationManager and stored for later use. A call is then made to TraceTransfer which will result in an entry being made into the log file. The current value of the ActivityId is then set to this new GUID. Once the call to the service (or whatever code) is complete, another TraceTransfer event is written and finally the ActivityId is returned to its initial value.
With many of the inbuilt trace listeners, the data that is written out by the TraceTransfer method includes the current ActivityId – so in the case of the code above this would indicate that there were two transfers, one from the extant ActivityId to the newly created GUID in the code, and then one back to the original ActivityId. If you were to use the XmlWriterTraceListener to record the above code you would see something like the following in the log file.
<E2ETraceEvent xmlns="http://schemas.microsoft.com/2004/06/E2ETraceEvent">
<System xmlns="http://schemas.microsoft.com/2004/06/windows/eventlog/system">
<EventID>111</EventID>
<Type>3</Type>
<SubType Name="Transfer">0</SubType>
<Level>255</Level>
<TimeCreated SystemTime="2007-11-16T15:06:15.1178000Z" />
<Source Name="TestSource" />
<Correlation ActivityID="{b76b9ffb-2b8c-4568-b0bd-2d541406ea36}"
RelatedActivityID="{493bf9ca-ffed-4199-a75d-64437c2f5557}" />
<Execution ProcessName="VSTestHost" ProcessID="3632" ThreadID="52" />
<Channel/>
<Computer>MORGANSK-SLAP</Computer>
</System>
<ApplicationData>Calling service</ApplicationData>
</E2ETraceEvent>
<E2ETraceEvent xmlns="http://schemas.microsoft.com/2004/06/E2ETraceEvent">
<System xmlns="http://schemas.microsoft.com/2004/06/windows/eventlog/system">
<EventID>111</EventID>
<Type>3</Type>
<SubType Name="Transfer">0</SubType>
<Level>255</Level>
<TimeCreated SystemTime="2007-11-16T15:06:15.1334000Z" />
<Source Name="TestSource" />
<Correlation ActivityID="{493bf9ca-ffed-4199-a75d-64437c2f5557}"
RelatedActivityID="{b76b9ffb-2b8c-4568-b0bd-2d541406ea36}" />
<Execution ProcessName="VSTestHost" ProcessID="3632" ThreadID="52" />
<Channel/>
<Computer>MORGANSK-SLAP</Computer>
</System>
<ApplicationData>Return</ApplicationData>
</E2ETraceEvent>
Here there are two Transfer events. Note the values defined by the Correlation element – these include the current ActivityId and the RelatedActivityId. The first indicates the value of the ActivityId parameter on Trace.CorrelationManager when the event is logged, and the second indicates the ActivityId of the new activity (i.e. the value set in the code above).
The second trace event specifies the values the other way around – now the activity that is ‘current’ is that which was transferred to in the first event and the related ID indicates what we’re returning back to.
It is therefore possible to write an application that can read these log files and correlate activity ID’s together, showing a hierarchical list of methods calling other methods. The hard work has been done for you however as we have also released the Service Trace Viewer (SvcTraceViewer.exe, typically in C:\Program Files\Microsoft SDKs\Windows\v6.0A\bin).
When you have obtained logs from client, server, and anywhere else you can load these into the trace viewer which will then display a breakdown of the calls that have been made, and allow you to drill down through the calls to understand what code was called. In addition it also provides information on how long a call took – typically useful when you want to understand where time is spent in an application without wishing to run your code under a profiler.
The image belowshows an abridged output from a client application that calls into a server over WCF, shown within the Service Trace Viewer application. For more details of see the documentation on the Service Trace Viewer on MSDN.
To generate this we created a client application, referenced a WCF service, and setup logging on both ends to a logfile. We then executed the client and once complete loaded both the client and server log files into the trace viewer.
The first event logged (at 16:47:23:187) indicates a transfer from the main application into the event handler for the button click event. This was generated using code similar to that shown above. You will note that the are other transfers within the application, and ultimately a call from the client to the server. A lot of the data output is based on the code within System.ServiceModel.
If you disable logging for System.ServiceModel then the trace becomes much simpler to understand as shown in the following image.
The Service Trace Viewer also allows you to view properties of each event, including the raw XML that was produced when the event was recorded.
Here you can see information such as the activity that was executing (in this case the button1_Click handler), the timestamp, level and other useful information. Included further down in the Diagnostics Information section is a stack trace which was removed for clarity. The data available here is dependent on the flags set on the traceOutputOptions attribute of the listener.