Complex traces you can actually understand by leveraging Activity Tracing

Activity tracing is part of a feature that was initially introduced with WCF, named End-to-End Tracing. Its underlying implementation, however, is baked into the XmlWriterTraceListener and does not depend on WCF in any way. Currently it’s only supported in the SystemDiagnostics implementation.

So what is activity tracing? It can be summarized as:

Activity tracing are special traces that record the processing flow across threads, processes and even machines, allowing for later correlation

The activities are identified by an arbitrary guid, which is placed in the ambient singleton property Trace.CorrelationManager.ActivityId. This ID flows with threads, and in the case of WCF, you can make it flow across processes and machines. This ID must be logged somehow, however, to be picked by a tool that can correlate the traces. For that purpose, this ID is tracked viaTraceSource.Transfer, TraceEventType.Start and TraceEventType.Stop traces.

With the right traces and payloads in place, you can get some pretty amazing diagnostics going, with call graphs and all, as shown on MSDN. The following graph shows what a very complex set of traces could look like, involving several threads, an intermediate warning and an ultimate error that caused a build to fail on some remote build server:

This can be achieved rather easily using the Microsoft Service Trace Viewer, since it’s able to open multiple logs simultaneously and correlate activities automatically. There’s built-in searching and filtering too, and you can also see on the right side what was the trace source for each message, as well as extended information about the computer, thread, exception or even full stack traces.

The Service Trace Viewer tool is available at C:\Program Files (x86)\Microsoft SDKs\Windows\v7.0A\Bin\NETFX 4.0 Tools\SvcTraceViewer.exe(or the folder of your installed version of the Windows SDK).

Generating Trace Logs

The first thing you need to do to generate these great XML logs that can be opened with the viewer is to set up the XmlWriterTraceListener with the trace sources you want to log:

var xmlListener = new XmlWriterTraceListener("log.xml");
Tracer.Manager.AddListener("MyExtension", xmlListener);
Tracer.Manager.SetTracingLevel("MyExtension", SourceLevels.All);

Note: Tracer supports Hierarchical Tracing and configuration.

Your calling code can now just issue normal traces as usual. In order to get activity tracing (those are the conected grouping lines in the graph above), you issue a StartActivity call on the tracer:

private static readonly ITracer tracer = Tracer.Get<MyCommand>();
...
    using (tracer.StartActivity("Starting remote build"))
    {
        // start new tasks/threads, issue more traces, etc.
    }

Activities nest naturally, and the using(..) ensures that they are closed properly. Since the correlation is performed by activity identifier, it’s not necessary to wait for the related activities/tasks to complete before disposing (and therefore stopping) the parent activity.

This is part of the Tracer project. This content will be updated on the Activity Tracing wiki page.