Logging ASP.Net WebApi elapsed time for IQueryables by ThinqLinq

I’ve recently been doing a fair amount of work with exposing queryable structures using ASP.Net Web API. In a nutshell, Web API allows you to expose not only the data from a service request, but also the query structure that can be extended. By default, the Web API scaffolding generates Get(id), Get, Post, Put and Delete methods. Of these, the most interesting, from a query perspective, is the Get method that returns a list of values:

    Public Function GetCustomers() As IEnumerable(Of Customer)
        Dim query = cn.Customers
        Return query
    End Function

By returning the default IEnumerable, the database will return everything that matches the service query definition and the consuming application isn’t able to customize this view to meet their needs. If you apply a couple changes, you can enable much greater service flexibility and allow customers to access your resources the way they want rather than just the way you originally intended. Of course with great power comes great responsibility. To make our GetCustomers method queryable, we simply change the output type from IEnumerable to IQueryable.

    Public Function GetCustomers() As IQueryable(Of Customer)
        Dim query = cn.Customers
        Return query
    End Function

In addition, we need to enable the query support for Web API in the Web Api Config’s Register method in the App_Start folder:

Public Module WebApiConfig
    Public Sub Register(ByVal config As HttpConfiguration)
        ' Web API configuration and services

        ' Web API routes
        config.MapHttpAttributeRoutes()

        config.Routes.MapHttpRoute(
            name:="DefaultApi",
            routeTemplate:="api/{controller}/{id}",
            defaults:=New With {.id = RouteParameter.Optional}
        )
        config.EnableQuerySupport()
        
    End Sub
End Module

Now, if we run the service, we can not only get the full list of Customers, but also add querying options like filter (where), orderby, top, skip, etc. For example, the following query gets the first two customers from London ordered by the Company Name. For a complete list of the various url query options, refer to the OData Query Specification URI Convention page.

http://localhost:17413/api/Customer?$filter=City%20eq%20'London'&$orderby=CompanyName&$top=2

Now, how does this fit with the question of logging the requests? If we were to use a traditional logging mechanism, we could just wrap the beginning and end of the service request with a timer and output the difference.

    Public Function GetCustomers() As IQueryable(Of DTO.DtoCustomer)
        Dim sw = New Stopwatch
        sw.Start()

        Dim query = cn.Customers
        sw.Stop()
        System.Diagnostics.Trace.WriteLine("GetCustomers completed in " + sw.ElapsedMilliseconds.ToString)

        Return query
    End Function

This outputs the result: “GetCustomers completed in 1”. Why is the time to execute so short? Remember that with LINQ, the database request is deferred until the results are iterated over (GetEnumerator). In the case of an IQueryable with WebAPI, the query isn’t executed until after our code has returned the base query and WebAPI has had a chance to add on any query parameters that the user supplied. We no longer have access to the query pipeline to hook into, right?

Adding tracing

Not exactly, Mike Wasson pointed out that there is a TraceWriter implementation that you can leverage and extend to hook into the Web API pipeline. For more information, see his article on Tracing in ASP.Net Web API.

In our example, we can output all of the tracing messages as follows. One thing to watch here is that the Kind and Operation are not set until the traceAction is executed, thus you need to execute the action prior to logging the details.

Imports System.Web.Http.Tracing
Imports System.Diagnostics

Public Class ServiceTracer
    Implements ITraceWriter

    Public Sub Trace(request As Net.Http.HttpRequestMessage,
        category As String, 
        level As System.Web.Http.Tracing.TraceLevel, 
        traceAction As Action(Of TraceRecord)) Implements ITraceWriter.Trace
        
        Dim rec = New TraceRecord(request, category, level)
        traceAction(rec)

        System.Diagnostics.Trace.WriteLine(String.Format("{0} - {1}  {2} - {3}", category, level, rec.Kind, rec.Operation))
    End Sub

End Class

We then need to register this implementation with the WebAPI configuration (again in WebApiConfig):

Public Module WebApiConfig
    Public Sub Register(ByVal config As HttpConfiguration)
        ' Web API configuration and services

        ' Web API routes
        config.MapHttpAttributeRoutes()

        config.Routes.MapHttpRoute(
            name:="DefaultApi",
            routeTemplate:="api/{controller}/{id}",
            defaults:=New With {.id = RouteParameter.Optional}
        )
        config.EnableQuerySupport()
        config.Services.Replace(GetType(ITraceWriter), New ServiceTracer)

    End Sub
End Module

If we run our solution again and access our service, we should see the following in the output window:

System.Web.Http.Request - Info  Begin - 
System.Web.Http.Controllers - Info  Begin - SelectController
System.Web.Http.Controllers - Info  End - SelectController
System.Web.Http.Controllers - Info  Begin - CreateController
System.Web.Http.Controllers - Info  Begin - Create
System.Web.Http.Controllers - Info  End - Create
System.Web.Http.Controllers - Info  End - CreateController
System.Web.Http.Controllers - Info  Begin - ExecuteAsync
System.Web.Http.Action - Info  Begin - SelectAction
System.Web.Http.Action - Info  End - SelectAction
System.Web.Http.ModelBinding - Info  Begin - ExecuteBindingAsync
System.Web.Http.ModelBinding - Info  End - ExecuteBindingAsync
System.Web.Http.Filters - Info  Begin - OnActionExecutingAsync
System.Web.Http.Filters - Info  End - OnActionExecutingAsync
System.Web.Http.Action - Info  Begin - InvokeActionAsync
System.Web.Http.Action - Info  Begin - ExecuteAsync
System.Web.Http.Action - Info  End - ExecuteAsync
System.Net.Http.Formatting - Info  Begin - Negotiate
System.Net.Http.Formatting - Info  Begin - GetPerRequestFormatterInstance
System.Net.Http.Formatting - Info  End - GetPerRequestFormatterInstance
System.Net.Http.Formatting - Info  End - Negotiate
System.Web.Http.Action - Info  End - InvokeActionAsync
System.Web.Http.Filters - Info  Begin - OnActionExecutedAsync
System.Web.Http.Filters - Info  End - OnActionExecutedAsync
System.Web.Http.Controllers - Info  End - ExecuteAsync
System.Web.Http.Request - Info  End - 
System.Net.Http.Formatting - Info  Begin - WriteToStreamAsync
System.Net.Http.Formatting - Info  End - WriteToStreamAsync
System.Web.Http.Controllers - Info  Begin - Dispose
System.Web.Http.Controllers - Info  End - Dispose

Boy, that’s a lot of information, but not quite what we want. If you scan through this list, you can see that WebAPI essentially gives us hooks before and after each operation that it does, including selecting the controller from the request URI, serializing any input/body parameters, executing the service, getting the output formatter, formatting the output, and writing the response. In our case, all we want is to log which method was called and how long it took to execute. Instead of wrapping a stopwatch around the beginning and end of our query definition as we did before, we need to find the time difference between the beginning and end of the service request. Given the trace list above, we can see that we can catch the begin SelectAction operation and the corresponding End Dispose operation and log that.

For the solution, we need to set-up a list of TraceRecord objects that we can use to correlate the start and end operations. We’ll use a private items variable to track the start requests. In the write trace method, we can check the Kind and Operation to add the record for the Begin of the SelectAction operation. We also check for the End Dispose operation to write the timings. In the end method, we need to find the item based on the supplied RequestId. (Remember, WebAPI may have multiple service requests executing simultaneously with a single trace writer instance, so you have to take care to get the correct start and end.) The TraceRecord already has a convenient TimeStamp property which is set when the traceAction is executed.  We simply calculate the difference between the start and end timestamps to output the total execution time. After we output the log record, we make sure to remove the starting trace record from the items list to clean up after ourselves. Below is our revised implementation of the trace writer to log the total execution time for the request.

Public Class ServiceTracer
    Implements ITraceWriter

    Dim items As New List(Of TraceRecord)

    Public Sub Trace(request As Net.Http.HttpRequestMessage, 
        category As String, 
        level As System.Web.Http.Tracing.TraceLevel, 
        traceAction As Action(Of TraceRecord)) Implements ITraceWriter.Trace

        Dim rec = New TraceRecord(request, category, level)
        traceAction(rec)

        WriteTrace(rec)
    End Sub

    Private Sub WriteTrace(rec As TraceRecord)
        If rec.Kind = TraceKind.Begin AndAlso rec.Operation = "SelectAction" Then
            items.Add(rec)
        End If
        If rec.Kind = TraceKind.End AndAlso rec.Operation = "Dispose" Then
            WriteServiceEnd(rec)
        End If
    End Sub

    Private Sub WriteServiceEnd(rec As TraceRecord)
        Dim start = items.Find(Function(r) r.RequestId = rec.RequestId)
        If rec.Request IsNot Nothing AndAlso start IsNot Nothing Then
            System.Diagnostics.Trace.WriteLine(String.Format("{0} - {1}: elapsedTime={2}",
                                                             Now,
                                                             rec.Request.RequestUri.PathAndQuery,
                                                             (rec.Timestamp - start.Timestamp).TotalMilliseconds))
            items.Remove(start)
        End If
    End Sub

End Class