Skip to content

Commit

Permalink
Standardization of Event Source tracing + Improvements for readability (
Browse files Browse the repository at this point in the history 
#484)
  • Loading branch information
@cheenamalhotra
cheenamalhotra authored Mar 24, 2020
1 parent 2874114 commit 29b65c0
Show file tree
Hide file tree
Showing 71 changed files with 1,997 additions and 1,577 deletions.
6 changes: 3 additions & 3 deletions ...Data.SqlClient/netcore/src/Common/src/Microsoft/Data/Common/DbConnectionOptions.Common.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -161,7 +161,7 @@ private static bool CompareInsensitiveInvariant(string strvalue, string strconst
[System.Diagnostics.Conditional("DEBUG")]
private static void DebugTraceKeyValuePair(string keyname, string keyvalue, Dictionary<string, string> synonyms)
{
if (SqlClientEventSource.Log.IsAdvanceTraceOn())
if (SqlClientEventSource.Log.IsAdvancedTraceOn())
{
Debug.Assert(string.Equals(keyname, keyname?.ToLower(), StringComparison.InvariantCulture), "missing ToLower");
string realkeyname = ((null != synonyms) ? (string)synonyms[keyname] : keyname);
Expand All @@ -171,11 +171,11 @@ private static void DebugTraceKeyValuePair(string keyname, string keyvalue, Dict
// don't trace passwords ever!
if (null != keyvalue)
{
SqlClientEventSource.Log.AdvanceTrace("<comm.DbConnectionOptions|INFO|ADV> KeyName='{0}', KeyValue='{1}'", keyname, keyvalue);
SqlClientEventSource.Log.AdvancedTraceEvent("<comm.DbConnectionOptions|INFO|ADV> KeyName='{0}', KeyValue='{1}'", keyname, keyvalue);
}
else
{
SqlClientEventSource.Log.AdvanceTrace("<comm.DbConnectionOptions|INFO|ADV> KeyName='{0}'", keyname);
SqlClientEventSource.Log.AdvancedTraceEvent("<comm.DbConnectionOptions|INFO|ADV> KeyName='{0}'", keyname);
}
}
}
Expand Down
18 changes: 9 additions & 9 deletions ....Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -49,7 +49,7 @@ abstract public DbProviderFactory ProviderFactory

public void ClearAllPools()
{
long scopeID = SqlClientEventSource.Log.ScopeEnterEvent("<prov.DbConnectionFactory.ClearAllPools|{0}>", "API");
long scopeID = SqlClientEventSource.Log.ScopeEnterEvent("<prov.DbConnectionFactory.ClearAllPools|API");
try
{
Dictionary<DbConnectionPoolKey, DbConnectionPoolGroup> connectionPoolGroups = _connectionPoolGroups;
Expand All @@ -71,7 +71,7 @@ public void ClearAllPools()
public void ClearPool(DbConnection connection)
{
ADP.CheckArgumentNull(connection, nameof(connection));
long scopeID = SqlClientEventSource.Log.ScopeEnterEvent("<prov.DbConnectionFactory.ClearPool|API> {0}#", GetObjectId(connection));
long scopeID = SqlClientEventSource.Log.ScopeEnterEvent("<prov.DbConnectionFactory.ClearPool|API> {0}", GetObjectId(connection));
try
{
DbConnectionPoolGroup poolGroup = GetConnectionPoolGroup(connection);
Expand Down Expand Up @@ -126,7 +126,7 @@ internal DbConnectionInternal CreateNonPooledConnection(DbConnection owningConne
{
newConnection.MakeNonPooledObject(owningConnection);
}
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionFactory.CreateNonPooledConnection|RES|CPOOL> {0}#, Non-pooled database connection created.", ObjectID);
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionFactory.CreateNonPooledConnection|RES|CPOOL> {0}, Non-pooled database connection created.", ObjectID);
return newConnection;
}

Expand All @@ -140,7 +140,7 @@ internal DbConnectionInternal CreatePooledConnection(DbConnectionPool pool, DbCo
{
newConnection.MakePooledConnection(pool);
}
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> {0}#, Pooled database connection created.", ObjectID);
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> {0}, Pooled database connection created.", ObjectID);
return newConnection;
}

Expand Down Expand Up @@ -195,7 +195,7 @@ private DbConnectionPool GetConnectionPool(DbConnection owningObject, DbConnecti
// however, don't rebuild connectionOptions if no pooling is involved - let new connections do that work
if (connectionPoolGroup.IsDisabled && (null != connectionPoolGroup.PoolGroupOptions))
{
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionFactory.GetConnectionPool|RES|INFO|CPOOL> {0}#, DisabledPoolGroup={1}#", ObjectID, connectionPoolGroup.ObjectID);
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionFactory.GetConnectionPool|RES|INFO|CPOOL> {0}, DisabledPoolGroup={1}", ObjectID, connectionPoolGroup.ObjectID);

// reusing existing pool option in case user originally used SetConnectionPoolOptions
DbConnectionPoolGroupOptions poolOptions = connectionPoolGroup.PoolGroupOptions;
Expand Down Expand Up @@ -303,7 +303,7 @@ internal DbConnectionPoolGroup GetConnectionPoolGroup(DbConnectionPoolKey key, D
private void PruneConnectionPoolGroups(object state)
{
// when debugging this method, expect multiple threads at the same time
SqlClientEventSource.Log.AdvanceTrace("<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> {0}#", ObjectID);
SqlClientEventSource.Log.AdvancedTraceEvent("<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> {0}", ObjectID);

// First, walk the pool release list and attempt to clear each
// pool, when the pool is finally empty, we dispose of it. If the
Expand All @@ -323,7 +323,7 @@ private void PruneConnectionPoolGroups(object state)
if (0 == pool.Count)
{
_poolsToRelease.Remove(pool);
SqlClientEventSource.Log.AdvanceTrace("<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> {0}#, ReleasePool={1}#", ObjectID, pool.ObjectID);
SqlClientEventSource.Log.AdvancedTraceEvent("<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> {0}, ReleasePool={1}", ObjectID, pool.ObjectID);
}
}
}
Expand All @@ -347,7 +347,7 @@ private void PruneConnectionPoolGroups(object state)
if (0 == poolsLeft)
{
_poolGroupsToRelease.Remove(poolGroup);
SqlClientEventSource.Log.AdvanceTrace("<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> {0}#, ReleasePoolGroup={1}#", ObjectID, poolGroup.ObjectID);
SqlClientEventSource.Log.AdvancedTraceEvent("<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> {0}, ReleasePoolGroup={1}", ObjectID, poolGroup.ObjectID);
}
}
}
Expand Down Expand Up @@ -410,7 +410,7 @@ internal void QueuePoolForRelease(DbConnectionPool pool, bool clearing)
internal void QueuePoolGroupForRelease(DbConnectionPoolGroup poolGroup)
{
Debug.Assert(null != poolGroup, "null poolGroup?");
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionFactory.QueuePoolGroupForRelease|RES|INFO|CPOOL> {0}#, poolGroup={1}#", ObjectID, poolGroup.ObjectID);
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionFactory.QueuePoolGroupForRelease|RES|INFO|CPOOL> {0}, poolGroup={1}", ObjectID, poolGroup.ObjectID);

lock (_poolGroupsToRelease)
{
Expand Down
10 changes: 5 additions & 5 deletions ...Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -225,7 +225,7 @@ internal void DeactivateConnection()
{
// Internal method called from the connection pooler so we don't expose
// the Deactivate method publicly.
SqlClientEventSource.Log.PoolerTraceEvent("<prov.DbConnectionInternal.DeactivateConnection|RES|INFO|CPOOL> {0}#, Deactivating", ObjectID);
SqlClientEventSource.Log.PoolerTraceEvent("<prov.DbConnectionInternal.DeactivateConnection|RES|INFO|CPOOL> {0}, Deactivating", ObjectID);

#if DEBUG
int activateCount = Interlocked.Decrement(ref _activateCount);
Expand All @@ -249,14 +249,14 @@ internal void DeactivateConnection()
protected internal void DoNotPoolThisConnection()
{
_cannotBePooled = true;
SqlClientEventSource.Log.PoolerTraceEvent("<prov.DbConnectionInternal.DoNotPoolThisConnection|RES|INFO|CPOOL> {0}#, Marking pooled object as non-poolable so it will be disposed", ObjectID);
SqlClientEventSource.Log.PoolerTraceEvent("<prov.DbConnectionInternal.DoNotPoolThisConnection|RES|INFO|CPOOL> {0}, Marking pooled object as non-poolable so it will be disposed", ObjectID);
}

/// <devdoc>Ensure that this connection cannot be put back into the pool.</devdoc>
protected internal void DoomThisConnection()
{
_connectionIsDoomed = true;
SqlClientEventSource.Log.PoolerTraceEvent("<prov.DbConnectionInternal.DoomThisConnection|RES|INFO|CPOOL> {0}#, Dooming", ObjectID);
SqlClientEventSource.Log.PoolerTraceEvent("<prov.DbConnectionInternal.DoomThisConnection|RES|INFO|CPOOL> {0}, Dooming", ObjectID);
}

protected internal virtual DataTable GetSchema(DbConnectionFactory factory, DbConnectionPoolGroup poolGroup, DbConnection outerConnection, string collectionName, string[] restrictions)
Expand Down Expand Up @@ -377,7 +377,7 @@ internal void PrePush(object expectedOwner)
throw ADP.InternalError(ADP.InternalErrorCode.PushingObjectSecondTime); // pushing object onto stack a second time
}

SqlClientEventSource.Log.PoolerTraceEvent("<prov.DbConnectionInternal.PrePush|RES|CPOOL> {0}#, Preparing to push into pool, owning connection {1}#, pooledCount={2}", ObjectID, 0, _pooledCount);
SqlClientEventSource.Log.PoolerTraceEvent("<prov.DbConnectionInternal.PrePush|RES|CPOOL> {0}, Preparing to push into pool, owning connection {1}, pooledCount={2}", ObjectID, 0, _pooledCount);
_pooledCount++;
_owningObject.Target = null; // NOTE: doing this and checking for InternalError.PooledObjectHasOwner degrades the close by 2%
}
Expand Down Expand Up @@ -406,7 +406,7 @@ internal void PostPop(object newOwner)
}
_owningObject.Target = newOwner;
_pooledCount--;
SqlClientEventSource.Log.PoolerTraceEvent("<prov.DbConnectionInternal.PostPop|RES|CPOOL> {0}#, Preparing to pop from pool, owning connection {1}#, pooledCount={2}", ObjectID, 0, _pooledCount);
SqlClientEventSource.Log.PoolerTraceEvent("<prov.DbConnectionInternal.PostPop|RES|CPOOL> {0}, Preparing to pop from pool, owning connection {1}, pooledCount={2}", ObjectID, 0, _pooledCount);

//3 // The following tests are retail assertions of things we can't allow to happen.
if (null != Pool)
Expand Down
6 changes: 3 additions & 3 deletions ...ata.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionPoolGroup.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -229,7 +229,7 @@ private bool MarkPoolGroupAsActive()
if (PoolGroupStateIdle == _state)
{
_state = PoolGroupStateActive;
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionPoolGroup.ClearInternal|RES|INFO|CPOOL> {0}#, Active", ObjectID);
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionPoolGroup.ClearInternal|RES|INFO|CPOOL> {0}, Active", ObjectID);
}
return (PoolGroupStateActive == _state);
}
Expand Down Expand Up @@ -281,12 +281,12 @@ internal bool Prune()
if (PoolGroupStateActive == _state)
{
_state = PoolGroupStateIdle;
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionPoolGroup.ClearInternal|RES|INFO|CPOOL> {0}#, Idle", ObjectID);
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionPoolGroup.ClearInternal|RES|INFO|CPOOL> {0}, Idle", ObjectID);
}
else if (PoolGroupStateIdle == _state)
{
_state = PoolGroupStateDisabled;
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionPoolGroup.ReadyToRemove|RES|INFO|CPOOL> {0}#, Disabled", ObjectID);
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionPoolGroup.ReadyToRemove|RES|INFO|CPOOL> {0}, Disabled", ObjectID);
}
}
return (PoolGroupStateDisabled == _state);
Expand Down
4 changes: 2 additions & 2 deletions src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/DataException.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -31,8 +31,8 @@ static private void TraceException(
Debug.Assert(null != e, "TraceException: null Exception");
if (null != e)
{
SqlClientEventSource.Log.AdvanceTrace(trace, e.Message);
SqlClientEventSource.Log.AdvanceTrace("<comm.ADP.TraceException|ERR|ADV> Environment StackTrace = '{0}'", Environment.StackTrace);
SqlClientEventSource.Log.AdvancedTraceEvent(trace, e.Message);
SqlClientEventSource.Log.AdvancedTraceEvent("<comm.ADP.TraceException|ERR|ADV> Environment StackTrace = '{0}'", Environment.StackTrace);
}
}

Expand Down
4 changes: 2 additions & 2 deletions src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -163,7 +163,7 @@ internal bool TryGetConnection(DbConnection owningConnection, TaskCompletionSour
// connection creation failed on semaphore waiting or if max pool reached
if (connectionPool.IsRunning)
{
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionFactory.GetConnection|RES|CPOOL> {0}#, GetConnection failed because a pool timeout occurred.", ObjectID);
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionFactory.GetConnection|RES|CPOOL> {0}, GetConnection failed because a pool timeout occurred.", ObjectID);
// If GetConnection failed while the pool is running, the pool timeout occurred.
throw ADP.PooledOpenTimeout();
}
Expand All @@ -181,7 +181,7 @@ internal bool TryGetConnection(DbConnection owningConnection, TaskCompletionSour

if (connection == null)
{
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionFactory.GetConnection|RES|CPOOL> {0}#, GetConnection failed because a pool timeout occurred and all retries were exhausted.", ObjectID);
SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionFactory.GetConnection|RES|CPOOL> {0}, GetConnection failed because a pool timeout occurred and all retries were exhausted.", ObjectID);
// exhausted all retries or timed out - give up
throw ADP.PooledOpenTimeout();
}
Expand Down
Loading

0 comments on commit 29b65c0

Please sign in to comment.