Once in a while I’ll get lucky and find a good sample of a solution to exactly the problem I’m having. Last Friday was my day for this. I’ve been working on a portal-style web application which includes security and logging on everything. I make some logging calls from within my global.asax file. Running ASP.NET web apps under development isn’t the fastest thing in the world and it’s always a bit of a problem to get a good feel for it’s speed in production. However, I had a few pages which felt particularly sluggish.

I’ve played around with various .NET code profilers and while they’ve all been OK, I haven’t committed to buying any of them. This time around I downloaded and installed ANTS Profiler from Red Gate. Once limitation that most profilers seem to have is that they require me to debug under IIS, which means I have to screw around with the code a bit to get it ready for deployment before I can look into any performance issues (although you can usually force them to fire up Cassini and profile it that way, it’s usually not very intuitive). So it was kind of nice to be able to profile an app. directly from ANTS.

After a quick profile test it was pretty clear the problem was in the logging code. There isn’t much going on here, grab some info. about the request (IP Address, page, time, user ID, etc.) create a connection, then create and run the insert SQL code. It was adding around 250ms to every page hit. I couldn’t do much to optimize this code, but I thought I might be able to create a new thread to run this on so the user wouldn’t have to wait while it ran. I found an excellent example of the exact issue by Peter Bromberg on the Egghead Café site: http://www.eggheadcafe.com/tutorials/aspnet/aa5ff306-16a1-4014-a51d-6ffde0894a0d/aspnet-request-logging-w.aspx

I didn’t need his connection or logging code, so I just snagged the thread class. Then I created a delegate for the logging method call.

My delegate code:

public delegate void SqlExecDelegate(SqlCommand command);

Then I just wrapped the call and passed in the SqlCommand variable I needed:

ThreadUtil.FireAndForget(new SqlExecDelegate(SqlExec), Command);

Here’s the code I grabbed from Peter – his article explains how it works in detail:

using System;
using System.Runtime.CompilerServices; 

namespace WirelessToyz.Utility
{
    /// <summary>
    /// Downloaded this class from:
    /// http://www.eggheadcafe.com/tutorials/aspnet/aa5ff306-16a1-4014-a51d-6ffde0894a0d/aspnet-request-logging-w.aspx
    /// </summary>
    public class ThreadUtil
    {
        private static AsyncCallback callback = new AsyncCallback(ThreadUtil.EndWrapperInvoke);
        private static DelegateWrapper wrapperInstance = new DelegateWrapper(ThreadUtil.InvokeWrappedDelegate);
 
        private static void EndWrapperInvoke(IAsyncResult ar)
        {
            wrapperInstance.EndInvoke(ar);
            ar.AsyncWaitHandle.Close();
        }
 
        public static void FireAndForget(Delegate d, params object[] args)
        {
            wrapperInstance.BeginInvoke(d, args, callback, null);
        } 

        private static void InvokeWrappedDelegate(Delegate d, object[] args)
        {
            d.DynamicInvoke(args);
        } 

        private delegate void DelegateWrapper(Delegate d, object[] args);
    }
}

I immediately saw a difference in my app. The pages felt a noticeable snappier. While it still takes 250ms to run my logging code, I no longer have to make the user wait for it.

Links

http://www.eggheadcafe.com/tutorials/aspnet/aa5ff306-16a1-4014-a51d-6ffde0894a0d/aspnet-request-logging-w.aspx