Karl Seguin

Starting a new large-scale project with an ASP.NET front-end, I wanted to add a mechanism to get constant feedback about what my app was doing. Something similar to the built-in tracing mechanism, but far more lightweight. <%@Page trace="true"...%> is great for specific cases, but it probably isn't something you want to leave on all the time while developer – and even if you do, there's so much noise you might miss out on those vital pieces of information.

So after googling around for a good solution and being surprised that I couldn't find anything, I decided to write my own. I can't help but think that there's a well known solution that everyone (but me) uses, so if there is, please tell me! Otherwise here are the very simple steps to reproduce what I have so far.

The approach is simple: store log messages in a List within then HttpContext, and dump it to the page. First, we start off with the class that'll hold each trace message. Within this class we'll hold the actual message, a type (log, debug, error), the elapsed time in milliseconds from the first logged message and the delta in milliseconds from the previous message:

public class TracerItem
{
   public TracerItemType Type { get; set; }
   public DateTime Dated { get; set; }
   public string Message { get; set; }
   public int Delta { get; set; }
   public int Elapsed { get; set; }

   public TracerItem() {}

   public TracerItem(DateTime dated, TracerItemType type, string message, int elapsed, int delta)
   {
      Dated = dated;
      Type = type;
      Message = message;
      Elapsed = elapsed;
      Delta = delta;
   }
}

public enum TracerItemType
{
   Info = 1,
   Debug = 2,
   Error = 3,
}

There's really nothing to explain there. Next, we'll create our static Tracer class, which defined the very important Log method:

public static class Tracer
{
   public static List<TracerItem> GetLogs()
   {
      var items = (List<TracerItem>) HttpContext.Current.Items["__tracer"];
      if (items == null)
      {
         items = new List<TracerItem>();
         HttpContext.Current.Items["__tracer"] = items;
      }
      return items;
   }
   public static void Log(string message, params object[] arguments)
   {
#if TRACER
      Log(message, TracerType.Info, arguments);
#endif
   }
   public static void Log(string message, TracerItemType type, params object[] arguments)
   {
#if TRACER
      var now = DateTime.Now;
      var items = GetLogs();
      var delta = items.Count == 0 ? 0 : (int)now.Subtract(items[items.Count - 1].Dated).TotalMilliseconds;
      var elasped = items.Count == 0 ? delta : items[items.Count - 1].Elapsed + delta;
      items.Add(new TracerItem(now, type, string.Format(message, arguments), elasped, delta));
#endif
   }
}

The GetLogs method initializes and gets our list of trace messages (this method isn't thread-safe). Notice that I use a preprocessor directive within the Log methods. According to this codeproject article, the JIT compiler will optimize out empty methods. This means that if we don't define the TRACER symbol our log code won't have any impact on performance (it also means that you need to define the TRACER symbol for it to work).

Next, we can use our classes to actually log events. For example, we might want to trace a specific cache miss:

var user = (User) Cache.Get(string.Format("userbyid_{0}", id));
if (user == null)
{
  Tracer.Log("Cache miss => user by id {0}", id);
  //get the user
}
return user;

The only thing left to do is display the actual content. You'll probably want to change this to fit your site, but this is what I did within a UserControl for an ASP.NET MVC site (loaded via RenderUserControl from my master):

<% var items = Tracer.GetLogs(); %>
<div id="tracer">
   <div class="item header">
      <div class="index">#</div>
      <div class="elapsed">elapsed</div>
      <div class="delta">delta</div>
      <div class="message">message</div>
   </div>
   <% for(int count = 0; count < items.Count; ++count) { %>
   <div class="item <%=items[count].Type %>">
      <div class="index"><%= count+1 %></div>
      <div class="elapsed"><%= items[count].Elapsed %>ms</div>
      <div class="delta"><%= items[count].Delta %>ms</div>
      <div class="message"><%= items[count].Message %></div>
   </div>
   <% } %>
</div>

Along with the accompanying CSS:

#tracer{width:1000px;margin:0 auto;padding:10px;}
#tracer .item {clear:both;}
#tracer .header{font-weight:bold;}
#tracer .item div{float:left;text-align:center;}
#tracer .Info{color:#888;}
#tracer .Debug{color:#2B2;}
#tracer .Error{color:#B22;}
#tracer .item div.index{width:20px;}
#tracer .item div.delta{width:90px;}
#tracer .item div.elapsed{width:90px;}

The whole thing is rendered on top of my header, so I always see what's going on. I am interested in expanding all of this into a stand-alone library. I also want to figure out how to hook into NHibernate's logging and add an "NHibernate" tab so you can see all of the SQL being executed.