From 278a3b407cc7317444e0f340f515dbf98b02709b Mon Sep 17 00:00:00 2001 From: Cheena Malhotra Date: Thu, 1 Apr 2021 14:47:37 -0700 Subject: [PATCH 1/3] Trace Improvements - SPID log changes ServerProcessId can throw exception for a closed connection, and need not be captured in traces with all command executions, only trace when new value fetched from header. --- .../Microsoft/Data/SqlClient/SqlCommand.cs | 96 +++++++++---------- .../Data/SqlClient/SqlTransaction.cs | 2 +- .../Data/SqlClient/TdsParserStateObject.cs | 2 + 3 files changed, 51 insertions(+), 49 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs index 271f76ea4a..f13d0db719 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs @@ -450,7 +450,7 @@ private SqlCommand(SqlCommand from) : this() } } _activeConnection = value; - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Set_Connection | API | ObjectId {0}, Client Connection Id {1}, SPID {2}", ObjectID, value?.ClientConnectionId, value?.ServerProcessId); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Set_Connection | API | ObjectId {0}, Client Connection Id {1}", ObjectID, value?.ClientConnectionId); } } @@ -561,7 +561,7 @@ internal SqlStatistics Statistics } } _transaction = value; - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Set_Transaction | API | Object Id {0}, Internal Transaction Id {1}, Client Connection Id {2}, SPID {3}", ObjectID, value?.InternalTransaction?.TransactionId, Connection?.ClientConnectionId, Connection?.ServerProcessId); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Set_Transaction | API | Object Id {0}, Internal Transaction Id {1}, Client Connection Id {2}", ObjectID, value?.InternalTransaction?.TransactionId, Connection?.ClientConnectionId); } } @@ -575,7 +575,7 @@ protected override DbTransaction DbTransaction set { Transaction = (SqlTransaction)value; - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Set_DbTransaction | API | Object Id {0}, Client Connection Id {1}, SPID {2}", ObjectID, Connection?.ClientConnectionId, Connection?.ServerProcessId); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Set_DbTransaction | API | Object Id {0}, Client Connection Id {1}", ObjectID, Connection?.ClientConnectionId); } } @@ -594,7 +594,7 @@ public override string CommandText PropertyChanging(); _commandText = value; } - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Set_CommandText | API | Object Id {0}, String Value = '{1}', Client Connection Id {2}, SPID {3}", ObjectID, value, Connection?.ClientConnectionId, Connection?.ServerProcessId); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Set_CommandText | API | Object Id {0}, String Value = '{1}', Client Connection Id {2}", ObjectID, value, Connection?.ClientConnectionId); } } @@ -619,7 +619,7 @@ public override int CommandTimeout PropertyChanging(); _commandTimeout = value; } - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Set_CommandTimeout | API | ObjectId {0}, Command Timeout value {1}, Client Connection Id {2}, SPID {3}", ObjectID, value, Connection?.ClientConnectionId, Connection?.ServerProcessId); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Set_CommandTimeout | API | ObjectId {0}, Command Timeout value {1}, Client Connection Id {2}", ObjectID, value, Connection?.ClientConnectionId); } } @@ -665,7 +665,7 @@ public override CommandType CommandType default: throw ADP.InvalidCommandType(value); } - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Set_CommandType | API | ObjectId {0}, Command type value {1}, Client Connection Id {2}, SPID {3}", ObjectID, (int)value, Connection?.ClientConnectionId, Connection?.ServerProcessId); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Set_CommandType | API | ObjectId {0}, Command type value {1}, Client Connection Id {2}", ObjectID, (int)value, Connection?.ClientConnectionId); } } } @@ -731,7 +731,7 @@ public override UpdateRowSource UpdatedRowSource default: throw ADP.InvalidUpdateRowSource(value); } - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.UpdatedRowSource | API | ObjectId {0}, Updated row source value {1}, Client Connection Id {2}, SPID {3}", ObjectID, (int)value, Connection?.ClientConnectionId, Connection?.ServerProcessId); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.UpdatedRowSource | API | ObjectId {0}, Updated row source value {1}, Client Connection Id {2}", ObjectID, (int)value, Connection?.ClientConnectionId); } } @@ -757,7 +757,7 @@ internal void OnStatementCompleted(int recordCount) { try { - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.OnStatementCompleted | Info | ObjectId {0}, Record Count {1}, Client Connection Id {2}, SPID {3}", ObjectID, recordCount, Connection?.ClientConnectionId, Connection?.ServerProcessId); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.OnStatementCompleted | Info | ObjectId {0}, Record Count {1}, Client Connection Id {2}", ObjectID, recordCount, Connection?.ClientConnectionId); handler(this, new StatementCompletedEventArgs(recordCount)); } catch (Exception e) @@ -785,7 +785,7 @@ public override void Prepare() SqlStatistics statistics = null; long scopeID = SqlClientEventSource.Log.TryScopeEnterEvent("SqlCommand.Prepare | API | Object Id {0}", ObjectID); - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.Prepare | API | Correlation | Object Id {0}, ActivityID {1}, Client Connection Id {2}, SPID {3}", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.Prepare | API | Correlation | Object Id {0}, ActivityID {1}, Client Connection Id {2}", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId); try { statistics = SqlStatistics.StartTimer(Statistics); @@ -908,7 +908,7 @@ internal void Unprepare() public override void Cancel() { long scopeID = SqlClientEventSource.Log.TryScopeEnterEvent("SqlCommand.Cancel | API | Object Id {0}", ObjectID); - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.Cancel | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.Cancel | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); SqlStatistics statistics = null; try @@ -1028,7 +1028,7 @@ public override object ExecuteScalar() SqlStatistics statistics = null; long scopeID = SqlClientEventSource.Log.TryScopeEnterEvent("SqlCommand.ExecuteScalar | API | ObjectId {0}", ObjectID); - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteScalar | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteScalar | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); Exception e = null; bool success = false; @@ -1039,8 +1039,8 @@ public override object ExecuteScalar() statistics = SqlStatistics.StartTimer(Statistics); WriteBeginExecuteEvent(); SqlDataReader ds; - ds = IsRetryEnabled ? - RunExecuteReaderWithRetry(0, RunBehavior.ReturnImmediately, returnStream: true) : + ds = IsRetryEnabled ? + RunExecuteReaderWithRetry(0, RunBehavior.ReturnImmediately, returnStream: true) : RunExecuteReader(0, RunBehavior.ReturnImmediately, returnStream: true, method: nameof(ExecuteScalar)); success = true; @@ -1123,7 +1123,7 @@ public override int ExecuteNonQuery() SqlStatistics statistics = null; long scopeID = SqlClientEventSource.Log.TryScopeEnterEvent("SqlCommand.ExecuteNonQuery | API | Object Id {0}", ObjectID); - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteNonQuery | API | Correlation | Object Id {0}, ActivityID {1}, Client Connection Id {2}, SPID {3}, Command Text {4}", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteNonQuery | API | Correlation | Object Id {0}, ActivityID {1}, Client Connection Id {2}, Command Text {4}", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); Exception e = null; try { @@ -1165,13 +1165,13 @@ public override int ExecuteNonQuery() /// public IAsyncResult BeginExecuteNonQuery(AsyncCallback callback, object stateObject) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.BeginExecuteNonQuery | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.BeginExecuteNonQuery | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); return BeginExecuteNonQueryInternal(0, callback, stateObject, 0, inRetry: false); } private IAsyncResult BeginExecuteNonQueryAsync(AsyncCallback callback, object stateObject) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.BeginExecuteNonQueryAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.BeginExecuteNonQueryAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); return BeginExecuteNonQueryInternal(0, callback, stateObject, CommandTimeout, inRetry: false, asyncWrite: true); } @@ -1363,7 +1363,7 @@ public int EndExecuteNonQuery(IAsyncResult asyncResult) } finally { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteNonQuery | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteNonQuery | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); } } @@ -1382,7 +1382,7 @@ private void ThrowIfReconnectionHasBeenCanceled() /// public int EndExecuteNonQueryAsync(IAsyncResult asyncResult) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteNonQueryAsync | Info | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteNonQueryAsync | Info | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); Debug.Assert(!_internalEndExecuteInitiated || _stateObj == null); Exception asyncException = ((Task)asyncResult).Exception; @@ -1619,7 +1619,7 @@ public XmlReader ExecuteXmlReader() SqlStatistics statistics = null; long scopeID = SqlClientEventSource.Log.TryScopeEnterEvent("SqlCommand.ExecuteXmlReader | API | Object Id {0}", ObjectID); - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteXmlReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteXmlReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); int? sqlExceptionNumber = null; Exception e = null; @@ -1630,7 +1630,7 @@ public XmlReader ExecuteXmlReader() // use the reader to consume metadata SqlDataReader ds; ds = IsRetryEnabled ? - RunExecuteReaderWithRetry(CommandBehavior.SequentialAccess, RunBehavior.ReturnImmediately, returnStream: true): + RunExecuteReaderWithRetry(CommandBehavior.SequentialAccess, RunBehavior.ReturnImmediately, returnStream: true) : RunExecuteReader(CommandBehavior.SequentialAccess, RunBehavior.ReturnImmediately, returnStream: true); success = true; return CompleteXmlReader(ds); @@ -1672,13 +1672,13 @@ public IAsyncResult BeginExecuteXmlReader() /// public IAsyncResult BeginExecuteXmlReader(AsyncCallback callback, object stateObject) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.BeginExecuteXmlReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.BeginExecuteXmlReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); return BeginExecuteXmlReaderInternal(CommandBehavior.SequentialAccess, callback, stateObject, 0, inRetry: false); } private IAsyncResult BeginExecuteXmlReaderAsync(AsyncCallback callback, object stateObject) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.BeginExecuteXmlReaderAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.BeginExecuteXmlReaderAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); return BeginExecuteXmlReaderInternal(CommandBehavior.SequentialAccess, callback, stateObject, CommandTimeout, inRetry: false, asyncWrite: true); } @@ -1797,13 +1797,13 @@ public XmlReader EndExecuteXmlReader(IAsyncResult asyncResult) } finally { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteXmlReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteXmlReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); } } private XmlReader EndExecuteXmlReaderAsync(IAsyncResult asyncResult) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteXmlReaderAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteXmlReaderAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); Debug.Assert(!_internalEndExecuteInitiated || _stateObj == null); Exception asyncException = ((Task)asyncResult).Exception; @@ -1908,14 +1908,14 @@ private XmlReader CompleteXmlReader(SqlDataReader ds, bool isAsync = false) /// public IAsyncResult BeginExecuteReader(AsyncCallback callback, object stateObject, CommandBehavior behavior) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.BeginExecuteReader | API | Correlation | Object Id {0}, Behavior {1}, Activity Id {2}, Client Connection Id {3}, SPID {4}, Command Text '{5}'", ObjectID, (int)behavior, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.BeginExecuteReader | API | Correlation | Object Id {0}, Behavior {1}, Activity Id {2}, Client Connection Id {3}, Command Text '{4}'", ObjectID, (int)behavior, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); return BeginExecuteReaderInternal(behavior, callback, stateObject, 0, inRetry: false); } /// protected override DbDataReader ExecuteDbDataReader(CommandBehavior behavior) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteDbDataReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteDbDataReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); return ExecuteReader(behavior); } @@ -1923,7 +1923,7 @@ protected override DbDataReader ExecuteDbDataReader(CommandBehavior behavior) new public SqlDataReader ExecuteReader() { SqlStatistics statistics = null; - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteReader | API | Correlation | ObjectID {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteReader | API | Correlation | ObjectID {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); try { statistics = SqlStatistics.StartTimer(Statistics); @@ -1954,7 +1954,7 @@ protected override DbDataReader ExecuteDbDataReader(CommandBehavior behavior) WriteBeginExecuteEvent(); statistics = SqlStatistics.StartTimer(Statistics); return IsRetryEnabled ? - RunExecuteReaderWithRetry(behavior, RunBehavior.ReturnImmediately, returnStream: true) : + RunExecuteReaderWithRetry(behavior, RunBehavior.ReturnImmediately, returnStream: true) : RunExecuteReader(behavior, RunBehavior.ReturnImmediately, returnStream: true); } catch (Exception ex) @@ -1994,13 +1994,13 @@ public SqlDataReader EndExecuteReader(IAsyncResult asyncResult) } finally { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); } } internal SqlDataReader EndExecuteReaderAsync(IAsyncResult asyncResult) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteReaderAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteReaderAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); Debug.Assert(!_internalEndExecuteInitiated || _stateObj == null); Exception asyncException = ((Task)asyncResult).Exception; @@ -2440,8 +2440,8 @@ private SqlDataReader InternalEndExecuteReader(IAsyncResult asyncResult, bool is /// public override Task ExecuteNonQueryAsync(CancellationToken cancellationToken) - => IsRetryEnabled ? - InternalExecuteNonQueryWithRetryAsync(cancellationToken) : + => IsRetryEnabled ? + InternalExecuteNonQueryWithRetryAsync(cancellationToken) : InternalExecuteNonQueryAsync(cancellationToken); private Task InternalExecuteNonQueryWithRetryAsync(CancellationToken cancellationToken) @@ -2449,7 +2449,7 @@ private Task InternalExecuteNonQueryWithRetryAsync(CancellationToken cancel private Task InternalExecuteNonQueryAsync(CancellationToken cancellationToken) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.InternalExecuteNonQueryAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.InternalExecuteNonQueryAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); Guid operationId = _diagnosticListener.WriteCommandBefore(this, _transaction); TaskCompletionSource source = new TaskCompletionSource(); @@ -2536,7 +2536,7 @@ protected override Task ExecuteDbDataReaderAsync(CommandBehavior b /// new public Task ExecuteReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken) => IsRetryEnabled ? - InternalExecuteReaderWithRetryAsync(behavior, cancellationToken) : + InternalExecuteReaderWithRetryAsync(behavior, cancellationToken) : InternalExecuteReaderAsync(behavior, cancellationToken); private Task InternalExecuteReaderWithRetryAsync(CommandBehavior behavior, CancellationToken cancellationToken) @@ -2544,8 +2544,8 @@ private Task InternalExecuteReaderWithRetryAsync(CommandBehavior private Task InternalExecuteReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.InternalExecuteReaderAsync | API | Correlation | Object Id {0}, Behavior {1}, Activity Id {2}, Client Connection Id {3}, SPID {4}, Command Text '{5}'", ObjectID, (int)behavior, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalExecuteReaderAsync | API> {0}, Client Connection Id {1}, SPID {2}, Command Text = '{3}'", ObjectID, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.InternalExecuteReaderAsync | API | Correlation | Object Id {0}, Behavior {1}, Activity Id {2}, Client Connection Id {3}, Command Text '{4}'", ObjectID, (int)behavior, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalExecuteReaderAsync | API> {0}, Client Connection Id {1}, Command Text = '{2}'", ObjectID, Connection?.ClientConnectionId, CommandText); Guid operationId = default(Guid); if (!_parentOperationStarted) { @@ -2613,8 +2613,8 @@ private void SetCachedCommandExecuteReaderAsyncContext(ExecuteReaderAsyncCallCon /// public override Task ExecuteScalarAsync(CancellationToken cancellationToken) - => IsRetryEnabled ? - InternalExecuteScalarWithRetryAsync(cancellationToken) : + => IsRetryEnabled ? + InternalExecuteScalarWithRetryAsync(cancellationToken) : InternalExecuteScalarAsync(cancellationToken); private Task InternalExecuteScalarWithRetryAsync(CancellationToken cancellationToken) @@ -2622,8 +2622,8 @@ private Task InternalExecuteScalarWithRetryAsync(CancellationToken cance private Task InternalExecuteScalarAsync(CancellationToken cancellationToken) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.InternalExecuteScalarAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalExecuteScalarAsync | API> {0}, Client Connection Id {1}, SPID {2}, Command Text = '{3}'", ObjectID, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.InternalExecuteScalarAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalExecuteScalarAsync | API> {0}, Client Connection Id {1}, Command Text = '{3}'", ObjectID, Connection?.ClientConnectionId, CommandText); _parentOperationStarted = true; Guid operationId = _diagnosticListener.WriteCommandBefore(this, _transaction); @@ -2712,8 +2712,8 @@ public Task ExecuteXmlReaderAsync() /// public Task ExecuteXmlReaderAsync(CancellationToken cancellationToken) - => IsRetryEnabled ? - InternalExecuteXmlReaderWithRetryAsync(cancellationToken) : + => IsRetryEnabled ? + InternalExecuteXmlReaderWithRetryAsync(cancellationToken) : InternalExecuteXmlReaderAsync(cancellationToken); private Task InternalExecuteXmlReaderWithRetryAsync(CancellationToken cancellationToken) @@ -2721,7 +2721,7 @@ private Task InternalExecuteXmlReaderWithRetryAsync(CancellationToken private Task InternalExecuteXmlReaderAsync(CancellationToken cancellationToken) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.InternalExecuteXmlReaderAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.InternalExecuteXmlReaderAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); Guid operationId = _diagnosticListener.WriteCommandBefore(this, _transaction); TaskCompletionSource source = new TaskCompletionSource(); @@ -3263,7 +3263,7 @@ private Task RunExecuteNonQueryTds(string methodName, bool isAsync, int timeout, // no parameters are sent over // no data reader is returned // use this overload for "batch SQL" tds token type - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteNonQueryTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command executed as SQLBATCH, Command Text '{4}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteNonQueryTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command executed as SQLBATCH, Command Text '{3}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); Task executeTask = _stateObj.Parser.TdsExecuteSQLBatch(this.CommandText, timeout, this.Notification, _stateObj, sync: true); Debug.Assert(executeTask == null, "Shouldn't get a task when doing sync writes"); @@ -4615,7 +4615,7 @@ private SqlDataReader RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavi if (returnStream) { - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteReaderTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command executed as SQLBATCH, Command Text '{4}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, CommandText); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteReaderTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command executed as SQLBATCH, Command Text '{4}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); } string text = GetCommandText(cmdBehavior) + GetResetOptionsString(cmdBehavior); @@ -4677,7 +4677,7 @@ private SqlDataReader RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavi rpc.options = TdsEnums.RPC_NOMETADATA; if (returnStream) { - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteReaderTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command executed as RPC, RPC Name '{4}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, rpc?.rpcName); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteReaderTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command executed as RPC, RPC Name '{4}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, rpc?.rpcName); } Debug.Assert(_rpcArrayOf1[0] == rpc); @@ -4695,7 +4695,7 @@ private SqlDataReader RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavi optionSettings = GetSetOptionsString(cmdBehavior); if (returnStream) { - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteReaderTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}, Command executed as RPC, RPC Name '{4}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId, rpc?.rpcName); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteReaderTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command executed as RPC, RPC Name '{4}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, rpc?.rpcName); } // turn set options ON @@ -6360,7 +6360,7 @@ private void NotifyDependency() public SqlCommand Clone() { SqlCommand clone = new SqlCommand(this); - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Clone | API | Object Id {0}, Clone Object Id {1}, Client Connection Id {2}, SPID {3}", ObjectID, clone.ObjectID, Connection?.ClientConnectionId, Connection?.ServerProcessId); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.Clone | API | Object Id {0}, Clone Object Id {1}, Client Connection Id {2}", ObjectID, clone.ObjectID, Connection?.ClientConnectionId); return clone; } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlTransaction.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlTransaction.cs index 653a8b1526..d80a7c22a0 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlTransaction.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlTransaction.cs @@ -142,7 +142,7 @@ override public void Commit() SqlStatistics statistics = null; long scopeID = SqlClientEventSource.Log.TryScopeEnterEvent("SqlTransaction.Commit | API | Object Id {0}", ObjectID); - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlTransaction.Commit | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, SPID {3}", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, Connection?.ServerProcessId); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlTransaction.Commit | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId); try { statistics = SqlStatistics.StartTimer(Statistics); diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index c2e41d4cb3..b5afd44570 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -1052,6 +1052,7 @@ internal bool TryProcessHeader() _messageStatus = _partialHeaderBuffer[1]; _spid = _partialHeaderBuffer[TdsEnums.SPID_OFFSET] << 8 | _partialHeaderBuffer[TdsEnums.SPID_OFFSET + 1]; + SqlClientEventSource.Log.TryAdvancedTraceEvent("TdsParserStateObject.TryProcessHeader | ADV | State Object Id {0}, Client Connection Id {1}, Server process Id (SPID) {2}", _objectID, _parser?.Connection?.ClientConnectionId, _spid); } else { @@ -1089,6 +1090,7 @@ internal bool TryProcessHeader() _inBuff[_inBytesUsed + TdsEnums.HEADER_LEN_FIELD_OFFSET + 1]) - _inputHeaderLen; _spid = _inBuff[_inBytesUsed + TdsEnums.SPID_OFFSET] << 8 | _inBuff[_inBytesUsed + TdsEnums.SPID_OFFSET + 1]; + SqlClientEventSource.Log.TryAdvancedTraceEvent("TdsParserStateObject.TryProcessHeader | ADV | State Object Id {0}, Client Connection Id {1}, Server process Id (SPID) {2}", _objectID, _parser?.Connection?.ClientConnectionId, _spid); _inBytesUsed += _inputHeaderLen; AssertValidState(); From ab298fc80032103e4a73d7fa7a159f34ea0bbfb1 Mon Sep 17 00:00:00 2001 From: Cheena Malhotra Date: Thu, 1 Apr 2021 15:31:43 -0700 Subject: [PATCH 2/3] Apply suggestions from code review Co-authored-by: Javad --- .../netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs index f13d0db719..c34dc4a0c0 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs @@ -1619,7 +1619,7 @@ public XmlReader ExecuteXmlReader() SqlStatistics statistics = null; long scopeID = SqlClientEventSource.Log.TryScopeEnterEvent("SqlCommand.ExecuteXmlReader | API | Object Id {0}", ObjectID); - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteXmlReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteXmlReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); int? sqlExceptionNumber = null; Exception e = null; @@ -1797,7 +1797,7 @@ public XmlReader EndExecuteXmlReader(IAsyncResult asyncResult) } finally { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteXmlReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.EndExecuteXmlReader | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); } } @@ -2622,7 +2622,7 @@ private Task InternalExecuteScalarWithRetryAsync(CancellationToken cance private Task InternalExecuteScalarAsync(CancellationToken cancellationToken) { - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.InternalExecuteScalarAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{4}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.InternalExecuteScalarAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalExecuteScalarAsync | API> {0}, Client Connection Id {1}, Command Text = '{3}'", ObjectID, Connection?.ClientConnectionId, CommandText); _parentOperationStarted = true; Guid operationId = _diagnosticListener.WriteCommandBefore(this, _transaction); @@ -4695,7 +4695,7 @@ private SqlDataReader RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavi optionSettings = GetSetOptionsString(cmdBehavior); if (returnStream) { - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteReaderTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command executed as RPC, RPC Name '{4}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, rpc?.rpcName); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteReaderTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command executed as RPC, RPC Name '{3}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, rpc?.rpcName); } // turn set options ON From 83167d1aed1dad91cab570cc3725007295146cb6 Mon Sep 17 00:00:00 2001 From: Cheena Malhotra Date: Thu, 1 Apr 2021 18:09:20 -0700 Subject: [PATCH 3/3] Apply suggestions from code review Co-authored-by: David Engel --- .../netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs index c34dc4a0c0..2808df1443 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlCommand.cs @@ -1123,7 +1123,7 @@ public override int ExecuteNonQuery() SqlStatistics statistics = null; long scopeID = SqlClientEventSource.Log.TryScopeEnterEvent("SqlCommand.ExecuteNonQuery | API | Object Id {0}", ObjectID); - SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteNonQuery | API | Correlation | Object Id {0}, ActivityID {1}, Client Connection Id {2}, Command Text {4}", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); + SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.ExecuteNonQuery | API | Correlation | Object Id {0}, ActivityID {1}, Client Connection Id {2}, Command Text {3}", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); Exception e = null; try { @@ -2623,7 +2623,7 @@ private Task InternalExecuteScalarWithRetryAsync(CancellationToken cance private Task InternalExecuteScalarAsync(CancellationToken cancellationToken) { SqlClientEventSource.Log.TryCorrelationTraceEvent("SqlCommand.InternalExecuteScalarAsync | API | Correlation | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command Text '{3}'", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalExecuteScalarAsync | API> {0}, Client Connection Id {1}, Command Text = '{3}'", ObjectID, Connection?.ClientConnectionId, CommandText); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.InternalExecuteScalarAsync | API> {0}, Client Connection Id {1}, Command Text = '{2}'", ObjectID, Connection?.ClientConnectionId, CommandText); _parentOperationStarted = true; Guid operationId = _diagnosticListener.WriteCommandBefore(this, _transaction); @@ -4615,7 +4615,7 @@ private SqlDataReader RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavi if (returnStream) { - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteReaderTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command executed as SQLBATCH, Command Text '{4}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteReaderTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command executed as SQLBATCH, Command Text '{3}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, CommandText); } string text = GetCommandText(cmdBehavior) + GetResetOptionsString(cmdBehavior); @@ -4677,7 +4677,7 @@ private SqlDataReader RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavi rpc.options = TdsEnums.RPC_NOMETADATA; if (returnStream) { - SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteReaderTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command executed as RPC, RPC Name '{4}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, rpc?.rpcName); + SqlClientEventSource.Log.TryTraceEvent("SqlCommand.RunExecuteReaderTds | Info | Object Id {0}, Activity Id {1}, Client Connection Id {2}, Command executed as RPC, RPC Name '{3}' ", ObjectID, ActivityCorrelator.Current, Connection?.ClientConnectionId, rpc?.rpcName); } Debug.Assert(_rpcArrayOf1[0] == rpc);