How I Use SubSonic, Part 3: Caching and Query Auditing

In Part 1 I covered how I created a ControllerBase class that all my SubSonic queries run through. Once I had a central point for processing queries, I wanted to add two features. Request-length caching and the ability to see how long a query was taking to execute.

Adding Request-length Caching

First off, this will only work as shown with web applications due to a dependency on HttpContext.Items. You could easily modify this to work without this dependency.

The way my templates are structured gives me access to related objects through lazy-loaded properties on my domain objects. All of these properties use the Get(id) method on their respective Controller. Throughout the length of a single request, there’s no reason to retrieve a given entity from the database more than once. Using my CacheManager I added the following to the ControllerBase.Get() method:

public static ItemType Get(object id)
{
    if (id == null)
        return default(ItemType);

    CacheManager cache = new CacheManager(new RequestProvider());
    string cacheToken = string.Format("{0}_{1}", typeof(ItemType), id);

    ItemType item = cache.Get(cacheToken);

    if (item == null)
    {
        item = DB.Get(id);

        // subsonic returns a new item if a get by ID fails
        // but we want a null object
        if (item.IsNew)
        {
            return default(ItemType);
        }
        else
        {
            cache.Store(cacheToken, item);
        }
    }

    return item;
}

The cache is first checked for an existing object matching the type and ID. If it’s not found, the entity is retrieved from the database and stored in the cache. If it is found, the database hit is skipped. There’s also a section in there to handle how SubSonic deals with .Get() calls that don’t find a record. I prefer to return null in this case, but your preference may vary.

I don’t yet cache the results of collections, only single objects. Caching the results of collections is an intriguing problem that I may revisit in the future.

Query Auditing

After caching reduced the number of times I hit the database on each request, I wanted to find out how long individual queries were taking so I could optimize where needed. I also wanted a way to print out a list of every query called with the SubSonic-generated SQL.

First up was creating the Auditor class to handle creating and storing entries. I don’t want to spend time on the internals, so you can view the source if you want to get a sense of how it works. Briefly, the heart of the Auditor is the CreateEntry method that takes a SubSonic SqlQuery, Query or StoredProcedure and stores it for display later. There’s also Auditor.StartTiming() and Auditor.EndTiming() for determining how long the query took to execute. Each of the methods in ControllerBase that execute queries get the Auditor mixed in like so:

public static ListType GetCollection(SqlQuery q)
{
    Auditor.StartTiming();
    ListType coll = q.ExecuteAsCollection
();
    TimeSpan exTime = Auditor.StopTiming();

    Auditor.CreateEntry(q, Action.Fetch, coll.Count, exTime);

    return coll;
}

And the updated Get() method:

public static ItemType Get(object id)
{
    if (id == null)
        return default(ItemType);

    CacheManager cache = new CacheManager(new RequestProvider());
    string cacheToken = string.Format("{0}_{1}", typeof(ItemType), id);

    ItemType item = cache.Get(cacheToken);

    if (item == null)
    {
        Auditor.StartTiming();
        item = DB.Get(id);

        // subsonic returns a new item if a get by ID fails
        // but we want a null object
        if (item.IsNew)
        {
            Auditor.CreateEntry(cacheToken, Action.Fetch, 0, null, Auditor.StopTiming());
            return default(ItemType);
        }
        else
        {
            Auditor.CreateEntry(cacheToken, Action.Fetch, 1, null, Auditor.StopTiming());
            cache.Store(cacheToken, item);
        }
    }
    else
    {
        Auditor.CreateEntry(cacheToken, Action.LoadFromCache, 1, null, TimeSpan.Zero);
    }

    return item;
}

The Auditor stores the query stats in a List<Entry> in HttpContext.Current.Items. To display these entries, I wrote the following Webforms UserControl (have not yet migrated this to MVC).

<%@ Control Language="C#" AutoEventWireup="true" CodeFile="Auditor.ascx.cs" Inherits="AuditorControl" %>
<asp:Repeater ID="rItems" runat="server" Visible="false" OnItemDataBound="rItems_ItemDataBound">
    <HeaderTemplate>
        <table class="list" style="font-size: 11px;">
            <tr class="header">
                <th>Type</th>
                <th>Count</th>
                <th>Time</th>
                <th class="left">Description</th>
                <th class="left">Params</th>
            </tr>
    </HeaderTemplate>
    <ItemTemplate>
        <tr class="item">
            <td class="center top" style="width: 30px;"><%# Eval("Action") %></td>
            <td class="center top" style="width: 30px;"><%# Eval("ResultCount") %></td>
            <td class="center top" style="width: 30px;"><%# ((TimeSpan)Eval("ExecutionLength")).Milliseconds %>ms</td>
            <td class="top"><%# Eval("DescriptionHtml") %></td>
            <td class="top" style="width: 150px;">
                <asp:Repeater ID="rParams" runat="server">
                    <ItemTemplate>
                        <strong><%# Eval("Key") %>:</strong>
                        <span style="white-space: nowrap;"><%# Eval("Value") %></span><br />
                    </ItemTemplate>
                </asp:Repeater>
            </td>
        </tr>
    </ItemTemplate>
    <FooterTemplate>
        </table>
    </FooterTemplate>
</asp:Repeater>

And the code behind:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Web;
using System.Web.UI;
using System.Web.UI.WebControls;
using SubSonicAuditor;

public partial class AuditorControl : System.Web.UI.UserControl
{
    protected void Page_Load(object sender, EventArgs e)
    {
        if (Auditor.Entries.Count > 0)
        {
            rItems.DataSource = Auditor.Entries;
            // or to exclude cache retrieval:
            // rItems.DataSource = Auditor.Entries.Where(en => en.Action != Action.LoadFromCache);
            rItems.DataBind();
            rItems.Visible = true;
        }
    }

    protected void rItems_ItemDataBound(object sender, RepeaterItemEventArgs e)
    {
        if (e.Item.ItemType == ListItemType.AlternatingItem || e.Item.ItemType == ListItemType.Item)
        {
            Repeater rParams = (Repeater)e.Item.FindControl("rParams");
            Entry entry = (Entry)e.Item.DataItem;

            rParams.DataSource = entry.Parameters;
            rParams.DataBind();
        }
    }
}

Put this user control on any page you want to test (or your site’s master page), make sure you’re running in Debug mode and you should get a list of all the queries executed and how long they took. Here’s a (heavily-blurred for security) example of the output.