Instrumenting Dapper Queries in ASP.NET Core

January 18, 2018

dotnet

In my last post we touched on what we get from EF Core in our Serilog log entries. But what if we are using dapper? How can we trace the SQL and get query execution times?

We already have our Seriog outputting to SQL Server and our middleware from the last post.

Unfortunately, we don’t get any logging out of the box for dapper like we do with EF Core - so, we need to do a bit of work.

We’ll create a class that wraps the dapper methods we use and we’ll instrument those methods. We turn stats on for the connection and get them after the query has finished, passing them to a central method that does the logging.

public async Task<IEnumerable<T>> GetRecords<T>(string sql, object parameters = null)
{
    IEnumerable<T> records = default(IEnumerable<T>);

    using (SqlConnection connection = new SqlConnection(ConnectionString))
    {
        connection.StatisticsEnabled = true;        await connection.OpenAsync();

        try
        {
            records = await connection.QueryAsync<T>(sql, parameters);
        }
        catch (Exception originalException)
        {
            throw AddAdditionalInfoToException(originalException, "Error: GetRecords: " + typeof(T).Name, sql, parameters);
        }

        var stats = connection.RetrieveStatistics();        LogInfo("GetRecords: " + typeof(T).Name, stats, sql, parameters);
    }

    return records;
}

public async Task<T> GetRecord<T>(string sql, object parameters = null)
{
    T record = default(T);

    using (SqlConnection connection = new SqlConnection(ConnectionString))
    {
        connection.StatisticsEnabled = true;        await connection.OpenAsync();

        try
        {
            record = await connection.QueryFirstOrDefaultAsync<T>(sql, parameters);
        }
        catch (Exception originalException)
        {
            throw AddAdditionalInfoToException(originalException, "Error: GetRecord: " + typeof(T).Name, sql, parameters);
        }

        var stats = connection.RetrieveStatistics();        LogInfo("GetRecord: " + typeof(T).Name, stats, sql, parameters);
    }

    return record;
}

The LogInfo() method logs the SQL, parameters and useful stats to Serilog. We could have just logged all the stats by doing .ForContext("Stats", stats, destructureObjects: true) but the log output wouldn’t have been as neat.

private void LogInfo(string logPrefix, IDictionary stats, string sql, object parameters = null)
{
    long elapsedMilliseconds = (long)stats["ConnectionTime"];

    Log.ForContext("SQL", sql)
        .ForContext("Parameters", parameters)
        .ForContext("ExecutionTime", stats["ExecutionTime"])
        .ForContext("NetworkServerTime", stats["NetworkServerTime"])
        .ForContext("BytesSent", stats["BytesSent"])
        .ForContext("BytesReceived", stats["BytesReceived"])
        .ForContext("SelectRows", stats["SelectRows"])
        .Information("{logPrefix} in {ElaspedTime:0.0000} ms", logPrefix, elapsedMilliseconds);
}

The AddAdditionalInfoToException() method makes sure we have the full SQL and parameters in the exception that has occurred ensuring that they are together in our log.

private Exception AddAdditionalInfoToException(Exception originalException, string message, string sql, object parameters = null)
{
    var additionalInfoException = new Exception(message, originalException);
    additionalInfoException.Data.Add("SQL", sql);
    var props = parameters.GetType().GetProperties();
    foreach (var prop in props)
    {
        additionalInfoException.Data.Add(prop.Name, prop.GetValue(parameters));
    }

    return additionalInfoException;
}

Now, to use our DapperWrap class, we need to register it in Startup.

public void ConfigureServices(IServiceCollection services)
{
	...
    services.AddScoped<DapperWrap>();
    ...
}

We can then inject DapperWrap where we need it. I’ve used it in a simple controller below:

[Route("api/Contacts")]
public class ContactsController : Controller
{
    private readonly DapperWrap dapperWrap;

    public ContactsController(DapperWrap dapperWrap)
    {
        this.dapperWrap = dapperWrap;
    }

    [HttpGet]
    public async Task<IActionResult> Get([FromQuery]string name)
    {
        IEnumerable<Contact> contacts = await dapperWrap.GetRecords<Contact>(@"SELECT Title, FirstName, Surname FROM CONTACT");
        return Ok(contacts);
    }

    [HttpGet("{contactId}", Name = "GetContactById")]
    public async Task<IActionResult> GetById(Guid contactId)
    {
        Contact contact = await dapperWrap.GetRecord<Contact>(@"SELECT Title, FirstName, Surname FROM CONTACT WHERE ContactId = @ContactId", new { ContactId = contactId});
        if (contact == null)
        {
            return NotFound();
        }

        return Ok(contact);
    }
}

We then get the following in our serilog log:

… with the following properties:

<properties>
  <property key="logPrefix">GetRecord: Contact</property>
  <property key="ElaspedTime">91</property>
  <property key="SelectRows">1</property>
  <property key="BytesReceived">186</property>
  <property key="BytesSent">303</property>
  <property key="NetworkServerTime">4</property>
  <property key="ExecutionTime">34</property>
  <property key="Parameters">{ ContactId = f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab }</property>
  <property key="SQL">SELECT Title, FirstName, Surname FROM CONTACT WHERE ContactId = @ContactId</property>
  <property key="UserName">Carl</property>
  <property key="ActionId">31fc307c-d14c-4c2c-9fd5-318daa601cae</property>
  <property key="ActionName">DapperLogging.Controllers.ContactsController.GetById (DapperLogging)</property>
  <property key="RequestId">0HLASK145UH2M:00000003</property>
  <property key="RequestPath">/api/contacts/f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab</property>
  <property key="Version">1.0.0.0</property>
  <property key="Type">Diagnostics</property>
</properties>

For an exception we get:

… which includes the full SQL and parameter in the properties:

<properties>
  <property key="errorId">6ca130ec-996b-4953-b591-2245c62687df</property>
  <property key="Exception">
    <structure type="Exception">
      <property key="Message">Error getting record</property>
      <property key="Data">
        <sequence>
          <item>
            <structure type="DictionaryEntry">
              <property key="Key">SQL</property>
              <property key="Value">SELECT Title, FirstName, Surname, BadField FROM CONTACT WHERE ContactId = @ContactId</property>
            </structure>
          </item>
          <item>
            <structure type="DictionaryEntry">
              <property key="Key">ContactId</property>
              <property key="Value">f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab</property>
            </structure>
          </item>
        </sequence>
      </property>
      ...