Tracing with Log4Net and the Context Singleton Design Pattern

• Download source files - 261 Kb

Abstract:

This article describes techniques than enable ASP.Net trace style performance information to be outputted to any appender using log4net. In building this utility class, we also delve into a design pattern that enables developer’s to create a single instance of a class for a single ASP.Net request, the Context Singleton pattern.

Introduction

Log4Net is a flexible, powerful open source logging library that many .Net developers swear by. On my last project, I had the opportunity to work with it and its many flexible “appenders.” For more information on using log4net, I recommend visiting some of the resources listed at the end of this article.

But despite its power, I found myself missing the simple to understand output that you get with the normal ASP.Net Trace.

Figure 1 - Example ASP.Net Trace Output

The ASP.Net Trace output makes it very easy to see how long each step takes and identify potential performance bottlenecks. The other advantage of this style of output is that you are only looking at a single request. Trying to correlate the same information from a log file when the server is serving many simultaneous requests is a difficult task.

If each message was its own log statement, each would be a separate log entry, with entries from other requests intermingled between them. The only thing that would make it unique would be the thread id, which ASP.Net reuses over and over again.

2006-08-10 22:53:48,236 [1176] INFO  TraceLogger.TraceLogger [NDC] 
Info Statement #1 from Request 1

2006-08-10 22:53:48,533 [4616] INFO  TraceLogger.TraceLogger [NDC] 
Info Statement #1 from Request 2

2006-08-10 22:53:48,555 [1176] INFO  TraceLogger.TraceLogger [NDC] 
Info Statement #2 from Request 1

2006-08-10 22:53:48,623 [4616] INFO  TraceLogger.TraceLogger [NDC] 
Info Statement #2 from Request 2

2006-08-10 22:53:48,725 [4616] INFO  TraceLogger.TraceLogger [NDC] 
Info Statement #3 from Request 2

2006-08-10 22:53:48,801 [1176] INFO  TraceLogger.TraceLogger [NDC] 
Info Statement #3 from Request 1

2006-08-10 22:53:48,915 [1176] INFO  TraceLogger.TraceLogger [NDC] 
Info Statement #4 from Request 1

Above is the log file output for two requests occurring around the same time. Just think how much more difficult it would be if there were 100 simultaneous requests. Imagine having to identify where the performance bottlenecks were under that load.

In order to leverage log4net’s flexible configuration and produce output formatted with the same style that the ASP.Net trace produces, we must build a utility class to keep track of the time that each message is logged and insert that information into the log files.

This utility class must be accessible from each class that we might want to log from, and it must be able to correlate all the log messages for a single request across all of those classes. Essentially, we need to ensure that only a single instance of our utility class exists for each request.

Problems with the GOF Singleton in ASP.Net

When you think of ensuring only one instance of a class can exist, you typically think of the Singleton design pattern. A typical implementation of this pattern has the following characteristics:

• The constructor is made private or protected
• The class keeps a static readonly instance variable that is returned to the caller through the static public “GetInstance” method.

//GOF Singleton Implementation
class Singleton
  {
    private static Singleton instance = new Singleton;

    protected Singleton() 
    {
    }

    public static Singleton Instance()
    {
      return instance;
    }
  }

The problem with using this approach for our TraceLogger utility class is that the static instance is actually shared between all the requests to our application, not just each request individually. Static members in ASP.Net are equivalent in scope to Application objects; they exist for the lifetime of the worker process. Static members are also not thread safe by default.

The ASP.Net Context Singleton

In order to circumvent this problem, we must design the class to keep the instance only for the current request. Luckily for us, ASP.Net offers a Context object which we can store any item we wish. With this knowledge we can redesign the singleton pattern to use the Context object to store the instance instead of a static read only instance variable. Figure 3 illustrates a typical implementation of this new “Context Singleton” pattern.

//Context Singleton Implementation
class ContextSingleton
  {
    protected ContextSingleton()
    {            
    }

    public static ContextSingleton Instance()
    {
        ContextSingleton instance = null;
        instance = HttpContext.Current.Items["ContextSingleton"] as 
                ContextSingleton;
    if (instance == null)
    {
      instance = new ContextSingleton();
      HttpContext.Current.Items.Add("ContextSingleton", instance);
    }
    return instance;
    }
  }

The TraceLogger Class

Now that we can create an object that exists as one instance per request, we can build a utility class to keep track of log statements and output them in an easy to understand format.

The complete code for the class is below:

using System;
using System.Reflection;
using System.Text;
using System.Web;
using log4net;

namespace TraceLogger
{
 /// <SUMMARY>
 /// The TraceLogger Class Employs a ASP.Net Context Singleton to provide a
 /// mechanism for tracing ASP.Net applications easily using log4Net.
 /// </SUMMARY>
 public class TraceLogger
 {
    private const string contextKey = "TraceLogger";

    #region ASP.Net Context Singleton Pattern
            
    // Note: Constructor is 'protected' 
    protected TraceLogger() 
    {
    this.StartTimer();
    }

    public static TraceLogger Instance
    {
    get
    {
      TraceLogger instance = null;
      instance = HttpContext.Current.Items[contextKey] as TraceLogger;
      if (instance == null)
      {
        instance = new TraceLogger();
        HttpContext.Current.Items.Add(contextKey, instance);
      }                 
      return instance;
    }
    }

    #endregion

    private static readonly ILog Log = 
        LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType); 
    
    private StringBuilder sb;

    private DateTime lastTime;
    public DateTime LastTime
    {
    get { return this.lastTime; }
    set { this.lastTime = value;}
    }

    private DateTime startTime;
    public DateTime StartTime
    {
    get { return this.startTime; }
    set { this.startTime = value; }
    }

    public void StartTimer()
    {
    this.StartTime = DateTime.Now;
    this.LastTime = DateTime.Now;
    sb = new StringBuilder();
    sb.Append("Performance Data for: ");
    sb.Append(HttpContext.Current.Request.Url.ToString());
    sb.Append("\nTime\t\tSince First\tSince Last\tComments\n");
    sb.Append(this.StartTime.ToLongTimeString());
    sb.Append("\t0.0000000\t0.0000000\tTimer Initialized\n");
    }

    public double MilliSecondsSinceStart()
    {
    TimeSpan span = DateTime.Now.Subtract(this.StartTime);
    return span.TotalMilliseconds / 1000;                 
    }

    public double MilliSecondsSinceLast()
    {
    TimeSpan span = DateTime.Now.Subtract(this.LastTime);
    this.LastTime = DateTime.Now;
    return span.TotalMilliseconds / 1000;
    }

    public void Write(string message)
    {
    sb.Append(DateTime.Now.ToLongTimeString());
    sb.Append("\t");
    sb.Append(String.Format("{0:0.0000000}", MilliSecondsSinceStart()));
    sb.Append("\t");
    sb.Append(String.Format("{0:0.0000000}", MilliSecondsSinceLast()));
    sb.Append("\t");
    sb.Append(message);
    sb.Append("\n");
    }

    public void Flush()
    {
       Write("Measurement Complete");
    if (Log.IsInfoEnabled)
    {
      Log.Info(sb.ToString());
    }
    }
  }
}

To use this class to add a log statement to the trace, just use the following code:

TraceLogger.Instance.Write(“sample message”);

The first time you do this, the class will initialize itself and the timer will start. To make sure the trace is written to the log file, you must call the Flush method like in the following code:

TraceLogger.Instance.Flush();

I usually place this code in the unload event of the page to ensure that any log statements I write are included in the trace. Below is a sample of the output:

2006-08-10 23:26:00,134 [1176] INFO  TraceLogger.TraceLogger [(null)]
Performance Data for: http://localhost/TraceLogger/SamplePage.aspx
Time           Since First  Since Last   Comments
11:25:56 PM    0.0000000    0.0000000    Timer Initialized
11:25:56 PM    0.0000000    0.0000000    In Page Init
11:25:57 PM    1.0014400    1.0014400    In Page Load
11:25:58 PM    2.0028800    1.0014400    In PreRender
11:25:59 PM    3.0043200    1.0014400    In Unload
11:26:00 PM    4.0057600    1.0014400    Measurement Complete

This class can be modified to produce exactly the style of output you desire.

Enjoy!

References

Log4Net
http://logging.apache.org/log4net/

Singleton Design Pattern
http://www.dofactory.com/Patterns/PatternSingleton.aspx