How can I measure login time on a SqlConnection while using pooling?

Question

I'd like to capture some statistics about an application using SqlConnection, specifically how long its spending physically logging into the server.

The simple approach would be something like:

using (SqlConnection connection = ...)
{
    Stopwatch loginTimer = Stopwatch.StartNew();
    connection.Open()
    loginTimer.Stop();
}

The twist is that I'm also using connection pooling and don't want to turn it off. As a result, my metrics get skewed because most calls to .Open() are actually just grabbing an existing, open physical connection from the pool, so I'll see:

00:00:01.39
00:00:00.02
00:00:00.02
00:00:00.02
...

The application uses enough connections and is targeting SqlAzure, so I do expect to see physical logins happening often enough.

I've tried testing the connection before trying:

if (sqlConnection.State != ConnectionState.Open)
{
    // Time and call .Open()
}

Unfortunately, the logical SqlConnection doesn't reflect the state of the physical connection, so the if block is always executed.

I know it's possible to create my own pool of connections, from which I'd draw from and execute on, but never close, thus I could track the actual state of the physical connection via the state of the logical connection, but I'd really prefer to not do this.

Answer 1

Expanding on Alexander's answer with some concrete code.

Within the constraints of using pooling for all connections, one can measure the time spent physically logging into a server / database by keeping track of the SqlConnection.ClientConnectionId value generated by SqlClient for each physical login. Below is a sample extension method to measure and report this time. To use it, change calls of SqlConnection.Open() to SqlConnection.Login(out openTime), where the result will be true if a login occurred, and false otherwise.

internal static class SqlConnectionExtension
{
    private static readonly PropertyInfo _clientConnectionIdPropertyInfo = typeof(SqlConnection).GetProperty("ClientConnectionId");
    private static readonly HashSet<Guid> _clientConnectionIds = new HashSet<Guid>();

    /// <summary>
    /// Method that calls <see cref="SqlConnection.Open()"/>, measuring the time it takes.
    /// </summary>
    /// <param name="sqlConnection">The <see cref="SqlConnection"/> to open.</param>
    /// <param name="openTime">The total time that the call to <see cref="SqlConnection.Open()"/> took.</param>
    /// <returns>True if a login took place; false if a connection was returned from a connection pool.</returns>
    public static bool Login(this SqlConnection sqlConnection, out TimeSpan openTime)
    {
        Stopwatch loginTimer = Stopwatch.StartNew();
        sqlConnection.Open();
        loginTimer.Stop();

        openTime = loginTimer.Elapsed;

    #if NET_4_0_3
        Guid clientConnectionId = sqlConnection.ClientConnectionId;
    #else
        Guid clientConnectionId = Guid.Empty;
        if (_clientConnectionIdPropertyInfo != null)
        {
            clientConnectionId = (Guid)_clientConnectionIdPropertyInfo.GetValue(sqlConnection, null);
        }
    #endif
        if (clientConnectionId != Guid.Empty && !_clientConnectionIds.Contains(clientConnectionId))
        {
            lock (_clientConnectionIds)
            {
                if (_clientConnectionIds.Add(clientConnectionId))
                {
                    return true;
                }
            }
        }
        return false;
    }
}

In my own environment, we're still using VS2010, and not all clients have the 4.0.3 multi-targeting pack, thus the #if NET_4_0_3 section.

Answer 2

Probably you can use ClientConnectionId property to track sql connections. It is regenerated every time new physical connection is created, and retained when connection is returned from pool. But it is available only starting from .net 4.5.

Another possibility is to skip connection pooling only for -some- of connections, just to measure physical time, keeping pooling for other connections.

For example, you can have static counter, which will keep incrementing. For every value divisible by 10, you can add Pooling='false' to your connection string, to skip adding it to pool. This will open new connection, and you can measure physical time.