Home > View Post

Brighten up your traces with a splash of colour

I've been getting my hands dirty with some WCF and I'm slowly porting some of the concepts I've been using in .ASMX over to this brave new world.

Those who know me well will know of my unhealthy fascination with tracing and logging. I find it particularly useful to be able to link a series of trace events together using some kind of contextual identifier so I can pull an entire trace together for any specific 'transaction'.

Let me explain.

Imagine we have a web site with a page called Default.aspx which, when rendered, performs three actions: DoOne(), DoTwo() and DoThree() - all method calls that do something magical to help us create our web page. Further imagine that we write a trace event as each method is called, like this:

public void DoOne()
{
    System.Diagnostics.Trace.TraceInformation("DoOne called");
    // Do something magical
}

In this case, a 'transaction' is the rendering of the whole Default.aspx page and the trace for this would look something like this (plus the time of the trace and all the other juicy information you get free with System.Diagnostics.Trace):

  • DoOne called
  • DoTwo called
  • DoThree called

Great, except on a busy web server the actual trace is going to look like this:

  • DoOne called
  • DoTwo called
  • DoOne called
  • DoOne called
  • DoTwo called
  • DoThree called
  • DoOne called
  • DoThree called
  • ...
Which is pretty useless, because I have no idea which DoTwo followed which DoOne. The reason we're hitting this problem is because we're not accounting for the multithreaded nature of the web server. If we could just flavour the thread with some contextual identifier then we could make sense of it all.

And we can, using the CorrelationManager available in System.Diagnostics (.NET 2.0 and later) to 'colour' our trace calls and reconstruct our 'transaction'.

  • DoOne called
  • DoTwo called
  • DoOne called
  • DoOne called
  • DoTwo called
  • DoThree called
  • DoOne called
  • DoThree called
  • ...
Except we don't actually use colours because:
  1. We'd run out of them
  2. It would be silly
Instead we use something we're not going to run out of: GUIDs. The CorrelationManager is available as a static property on the Trace class and has a number of members of interest in this space. You could use the StartLogicalOperation() and StopLogicalOperation() methods but I prefer to use the ActivityId property.

void Application_BeginRequest(object sender, EventArgs e)
{
    System.Diagnostics.Trace.CorrelationManager.ActivityId = Guid.NewGuid();
}

There are a number of approaches including the one shown above where I have added a handler for the Application_BeginRequest event to our Global.asax. This will give us a nice fresh GUID for each 'transaction'. All Trace calls on that thread will now be coloured with this activity id for analysis later.

Tags: .NET

 
Josh Post By Josh Twist
9:16 AM
28 Nov 2006

» Next Post: Smuggling Headers with WCF
« Previous Post: Setting up two web sites in IIS7

Comments are closed for this post.

© 2005 - 2017 Josh Twist - All Rights Reserved.