Custom ASP.NET Page Tracing

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.

This entry was posted in Uncategorized. Bookmark the permalink. Follow any comments here with the RSS feed for this post.

4 Responses to Custom ASP.NET Page Tracing

  1. karl says:

    Nathan:
    I created my own appender:

    public class TracerAppender : AppenderSkeleton
    {
    protected override void Append(LoggingEvent loggingEvent)
    {
    Tracer.Log(loggingEvent.RenderedMessage, loggingEvent.LoggerName);
    }
    }

    I did a bit more changes to clean up the NHibernate output, but that was essentially it.

  2. Nathan says:

    I think your missing piece is log4net (which nhibernate uses); we wanted much the same as you (an expandable div you can click in the header) and just joined that up to the log4net output

    The good thing is you can still use log4net’s file-based logging too, which we use in production

  3. Ben Duguid says:

    Hi Karl,

    An alternative to all those preprocessor directives is the Conditional attribute.

    If you mark your Log method with [Conditional(“TRACER”)] then the compiler will only knows that this method should only be called when the “TRACER” symbol is set, otherwise it generates an empty method, which as you point out, the JIT compiler then skips.

    If you decorate your method with multiple Conditional attributes, then it will be called if either symbol is defined:

    [Conditional(“DEBUG”), Conditional(“TRACER”)]
    public static void Log(string message, TracerItemType type, params object[] arguments)
    { […] }

    Hope that helps,

    Ben

  4. Charles F says:

    My friend wrote something similar for a JSP application a couple years back. The ultra-useful feature he included was dumping the trace data out to a separate browser window. What really brings his solution to mind was that his new window was multi-tabbed and included a Hibernate log tab among other things (even his client side Javascript dumped trace out to a Javascript tab). With a feature like that I would integrate a library like this into my application right away so I could really make use of dual monitors while debugging.