Skip to content

Commit

Permalink
Added basic diagnostics to SqlConnection
Browse files Browse the repository at this point in the history
  • Loading branch information
@trstringer
trstringer committed May 18, 2016
1 parent bcb89b7 commit d024756
Show file tree
Hide file tree
Showing 3 changed files with 324 additions and 0 deletions.
130 changes: 130 additions & 0 deletions src/System.Data.SqlClient/src/System/Data/SqlClient/SqlClientDiagnosticListenerExtensions.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,10 +12,19 @@ internal static class SqlClientDiagnosticListenerExtensions
public const string DiagnosticListenerName = "SqlClientDiagnosticListener";

private const string SqlClientPrefix = "System.Data.SqlClient.";

public const string SqlBeforeExecuteCommand = SqlClientPrefix + nameof(WriteCommandBefore);
public const string SqlAfterExecuteCommand = SqlClientPrefix + nameof(WriteCommandAfter);
public const string SqlErrorExecuteCommand = SqlClientPrefix + nameof(WriteCommandError);

public const string SqlBeforeOpenConnection = SqlClientPrefix + nameof(WriteConnectionOpenBefore);
public const string SqlAfterOpenConnection = SqlClientPrefix + nameof(WriteConnectionOpenAfter);
public const string SqlErrorOpenConnection = SqlClientPrefix + nameof(WriteConnectionOpenError);

public const string SqlBeforeCloseConnection = SqlClientPrefix + nameof(WriteConnectionCloseBefore);
public const string SqlAfterCloseConnection = SqlClientPrefix + nameof(WriteConnectionCloseAfter);
public const string SqlErrorCloseConnection = SqlClientPrefix + nameof(WriteConnectionCloseError);

This comment has been minimized.

Sign in to view

Copy link
@nbilling

nbilling May 18, 2016 •
edited
Loading

Wasn't there some discussion before of using an attribute for the caller name? Did that end up not working this scenario?

This comment has been minimized.

Sign in to view

Copy link
@trstringer

trstringer May 18, 2016

Author Owner

@nbilling that's correct, and I implemented this as well in the extension method definitions. I.e. see L86.

This comment has been minimized.

Sign in to view

Copy link
@nbilling

nbilling May 18, 2016 •
edited
Loading

Oh I am confusing the operation names and the write event names. Disregard.

public static Guid WriteCommandBefore(this DiagnosticListener @this, SqlCommand sqlCommand, [CallerMemberName] string operation = "")
{
if (@this.IsEnabled(SqlBeforeExecuteCommand))
Expand All @@ -28,6 +37,7 @@ public static Guid WriteCommandBefore(this DiagnosticListener @this, SqlCommand
{
OperationId = operationId,
Operation = operation,
ConnectionId = sqlCommand.Connection.ClientConnectionId,

This comment has been minimized.

Sign in to view

Copy link
@nbilling

nbilling May 18, 2016

I think Connection can be null.
Command = sqlCommand
});

Expand All @@ -47,6 +57,7 @@ public static void WriteCommandAfter(this DiagnosticListener @this, Guid operati
{
OperationId = operationId,
Operation = operation,
ConnectionId = sqlCommand.Connection.ClientConnectionId,
Command = sqlCommand,
Statistics = sqlCommand.Statistics?.GetDictionary(),
Timestamp = Stopwatch.GetTimestamp()
Expand All @@ -64,11 +75,130 @@ public static void WriteCommandError(this DiagnosticListener @this, Guid operati
{
OperationId = operationId,
Operation = operation,
ConnectionId = sqlCommand.Connection.ClientConnectionId,
Command = sqlCommand,
Exception = ex,
Timestamp = Stopwatch.GetTimestamp()
});
}
}

public static Guid WriteConnectionOpenBefore(this DiagnosticListener @this, SqlConnection sqlConnection, [CallerMemberName] string operation = "")
{
if (@this.IsEnabled(SqlBeforeOpenConnection))
{
Guid operationId = Guid.NewGuid();

@this.Write(
SqlBeforeOpenConnection,
new
{
OperationId = operationId,
Operation = operation,
Connection = sqlConnection,
Timestamp = Stopwatch.GetTimestamp()
});

return operationId;
}
else
return Guid.Empty;
}

public static void WriteConnectionOpenAfter(this DiagnosticListener @this, Guid operationId, SqlConnection sqlConnection, [CallerMemberName] string operation = "")
{
if (@this.IsEnabled(SqlAfterOpenConnection))
{
@this.Write(
SqlAfterOpenConnection,
new
{
OperationId = operationId,
Operation = operation,
ConnectionId = sqlConnection.ClientConnectionId,
Connection = sqlConnection,
Statistics = sqlConnection.Statistics?.GetDictionary(),
Timestamp = Stopwatch.GetTimestamp()
});
}
}

public static void WriteConnectionOpenError(this DiagnosticListener @this, Guid operationId, SqlConnection sqlConnection, Exception ex, [CallerMemberName] string operation = "")
{
if (@this.IsEnabled(SqlErrorOpenConnection))
{
@this.Write(
SqlErrorOpenConnection,
new
{
OperationId = operationId,
Operation = operation,
ConnectionId = sqlConnection.ClientConnectionId,
Connection = sqlConnection,
Exception = ex,
Timestamp = Stopwatch.GetTimestamp()
});
}
}

public static Guid WriteConnectionCloseBefore(this DiagnosticListener @this, SqlConnection sqlConnection, [CallerMemberName] string operation = "")
{
if (@this.IsEnabled(SqlBeforeCloseConnection))
{
Guid operationId = Guid.NewGuid();

@this.Write(
SqlBeforeCloseConnection,
new
{
OperationId = operationId,
Operation = operation,
ConnectionId = sqlConnection.ClientConnectionId,
Connection = sqlConnection,
Statistics = sqlConnection.Statistics?.GetDictionary(),
Timestamp = Stopwatch.GetTimestamp()
});

return operationId;
}
else
return Guid.Empty;
}

public static void WriteConnectionCloseAfter(this DiagnosticListener @this, Guid operationId, Guid clientConnectionId, SqlConnection sqlConnection, [CallerMemberName] string operation = "")
{
if (@this.IsEnabled(SqlAfterCloseConnection))
{
@this.Write(
SqlAfterCloseConnection,
new
{
OperationId = operationId,
Operation = operation,
ConnectionId = clientConnectionId,
Connection = sqlConnection,
Statistics = sqlConnection.Statistics?.GetDictionary(),

This comment has been minimized.

Sign in to view

Copy link
@trstringer

trstringer May 18, 2016

Author Owner

@avanderhoorn here's where we're capturing the statistics from the connection object.
Timestamp = Stopwatch.GetTimestamp()
});
}
}

public static void WriteConnectionCloseError(this DiagnosticListener @this, Guid operationId, Guid clientConnectionId, SqlConnection sqlConnection, Exception ex, [CallerMemberName] string operation = "")
{
if (@this.IsEnabled(SqlErrorCloseConnection))
{
@this.Write(
SqlErrorCloseConnection,
new
{
OperationId = operationId,
Operation = operation,
ConnectionId = clientConnectionId,
Connection = sqlConnection,
Exception = ex,
Timestamp = Stopwatch.GetTimestamp()
});
}
}
}
}
57 changes: 57 additions & 0 deletions src/System.Data.SqlClient/src/System/Data/SqlClient/SqlConnection.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -462,8 +462,28 @@ private void CloseInnerConnection()

override public void Close()
{
ConnectionState previousState = State;
Guid operationId;
Guid clientConnectionId;

// during the call to Dispose() there is a redundant call to
// Close(). because of this, the second time Close() is invoked the
// connection is already in a closed state. this doesn't seem to be a
// problem except for logging, as we'll get duplicate Before/After/Error
// log entries
if (previousState == ConnectionState.Open)
{
operationId = s_diagnosticListener.WriteConnectionCloseBefore(this);
// we want to cache the ClientConnectionId for After/Error logging, as when the connection
// is closed then we will lose this identifier
//
// note: caching this is only for diagnostics logging purposes
clientConnectionId = ClientConnectionId;
}

SqlStatistics statistics = null;

Exception e = null;
try
{
statistics = SqlStatistics.StartTimer(Statistics);
Expand Down Expand Up @@ -491,9 +511,28 @@ override public void Close()
ADP.TimerCurrent(out _statistics._closeTimestamp);
}
}
catch (Exception ex)
{
e = ex;
throw;
}
finally
{
SqlStatistics.StopTimer(statistics);

This comment has been minimized.

Sign in to view

Copy link
@avanderhoorn

avanderhoorn May 18, 2016

We should probably try and capture the stats here... Do you know if its the same stats instance we have access to in the command?

This comment has been minimized.

Sign in to view

Copy link
@trstringer

trstringer May 18, 2016

Author Owner

@avanderhoorn we do grab statistics from the SqlConnection object, but this is handled inside of WriteConnectionCloseAfter(). It appears as though I should be capturing this in WriteConnectionCloseError() as well though.

// we only want to log this even if the previous state of the

This comment has been minimized.

Sign in to view

Copy link
@nbilling

nbilling May 18, 2016

Remove "even".
// connection is open, as that's the valid use-case
if (previousState == ConnectionState.Open)
{
if (e != null)
{
s_diagnosticListener.WriteConnectionCloseError(operationId, clientConnectionId, this, e);
}
else
{
s_diagnosticListener.WriteConnectionCloseAfter(operationId, clientConnectionId, this);
}
}
}
}

Expand Down Expand Up @@ -524,9 +563,13 @@ private void DisposeMe(bool disposing)

override public void Open()
{
Guid operationId = s_diagnosticListener.WriteConnectionOpenBefore(this);

PrepareStatisticsForNewConnection();

SqlStatistics statistics = null;

Exception e = null;
try
{
statistics = SqlStatistics.StartTimer(Statistics);
Expand All @@ -536,9 +579,23 @@ override public void Open()
throw ADP.InternalError(ADP.InternalErrorCode.SynchronousConnectReturnedPending);
}
}
catch (Exception ex)
{
e = ex;
throw;
}
finally
{
SqlStatistics.StopTimer(statistics);

if (e != null)
{
s_diagnosticListener.WriteConnectionOpenError(operationId, this, e);
}
else
{
s_diagnosticListener.WriteConnectionOpenAfter(operationId, this);
}
}
}

This comment has been minimized.

Sign in to view

Copy link
@avanderhoorn

avanderhoorn May 18, 2016

It looks like there is an OpenAsync method that we will need to instrument as well (and hence track async open vs not).

This comment has been minimized.

Sign in to view

Copy link
@trstringer

trstringer May 18, 2016 •
edited
Loading

Author Owner

@avanderhoorn so this is proving to be a bit of a challenge. The WriteConnectionOpenBefore() should be called directly in OpenAsync(), but this is just a task that is returned. It appears as though the logic to actually connect (whether successful or failed) is deeply nested in a connection factory object. I see a few approaches here:

  1. Report an after event while the connection is still "connecting" (not really indicative of the event though, as it isn't in an "open" state yet at this point)
  2. Pass the operationId through the stack (this doesn't seem like a good idea, as it would be massive changes to existing code to inject this dependency to the connection factory)
  3. Keep all logging logic for connection opening directly in the connection factory

To be honest, I don't really love # 3 either as it is now spanning beyond SqlClient at this point. Curious to your thoughts, we well as @nbilling. It's not appearing as though this is a quick solution with logging an async open.

FYI I'll be away from my machine starting early tomorrow morning until Monday with no connectivity to check comments

This comment has been minimized.

Sign in to view

Copy link
@nbilling

nbilling May 18, 2016

Can you not just put the "After" logic in a continuation on the task returned by completion.Task.ContinueWith(retry.Retry, TaskScheduler.Default) on line 821 (retry case), and also on line 810 (completed first try case)?

This comment has been minimized.

Sign in to view

Copy link
@trstringer

trstringer May 19, 2016

Author Owner

@nbilling that's a really good thought, I'm going to see if I can get that going.

Expand Down
Loading

0 comments on commit d024756

Please sign in to comment.