EventSource NetCore

src/Microsoft.Data.SqlClient/netcore/src/Common/src/Microsoft/Data/Common/AdapterUtil.cs

@@ -14,6 +14,7 @@
 using System.Threading;
 using System.Threading.Tasks;
 using System.Transactions;
+using Microsoft.Data.SqlClient;
 
 namespace Microsoft.Data.Common
 {
@@ -30,7 +31,14 @@ internal static partial class ADP
         internal const CompareOptions DefaultCompareOptions = CompareOptions.IgnoreKanaType | CompareOptions.IgnoreWidth | CompareOptions.IgnoreCase;
         internal const int DefaultConnectionTimeout = DbConnectionStringDefaults.ConnectTimeout;
 
-        static partial void TraceException(string trace, Exception e);
+        static private void TraceException(string trace, Exception e)
+        {
+            Debug.Assert(null != e, "TraceException: null Exception");
+            if (null != e)
+            {
+                SqlClientEventSource.Log.TraceEvent(trace, e.ToString());
+            }
+        }
 
         internal static void TraceExceptionAsReturnValue(Exception e)
         {
@@ -40,7 +48,7 @@ internal static void TraceExceptionAsReturnValue(Exception e)
         internal static void TraceExceptionWithoutRethrow(Exception e)
         {
             Debug.Assert(ADP.IsCatchableExceptionType(e), "Invalid exception type, should have been re-thrown!");
-            TraceException("<comm.ADP.TraceException|ERR|CATCH> '%ls'\n", e);
+            TraceException("<comm.ADP.TraceException|ERR|CATCH> '{0}'", e);
         }
 
         internal static ArgumentException Argument(string error)

src/Microsoft.Data.SqlClient/netcore/src/Common/src/Microsoft/Data/Common/DbConnectionOptions.Common.cs

@@ -8,6 +8,7 @@
 using System.Globalization;
 using System.Text;
 using System.Text.RegularExpressions;
+using Microsoft.Data.SqlClient;
 
 namespace Microsoft.Data.Common
 {
@@ -110,6 +111,8 @@ internal Dictionary<string, string> Parsetable
         public string UsersConnectionString(bool hidePassword) =>
             UsersConnectionString(hidePassword, false);
 
+        internal string UsersConnectionStringForTrace() => UsersConnectionString(true, true);
+
         private string UsersConnectionString(bool hidePassword, bool forceHidePassword)
         {
             string connectionString = _usersConnectionString;
@@ -156,7 +159,27 @@ private static bool CompareInsensitiveInvariant(string strvalue, string strconst
             (0 == StringComparer.OrdinalIgnoreCase.Compare(strvalue, strconst));
 
         [System.Diagnostics.Conditional("DEBUG")]
-        static partial void DebugTraceKeyValuePair(string keyname, string keyvalue, Dictionary<string, string> synonyms);
+        private static void DebugTraceKeyValuePair(string keyname, string keyvalue, Dictionary<string, string> synonyms)
+        {
+            if (SqlClientEventSource.Log.IsAdvanceTraceOn())
+            {
+                Debug.Assert(string.Equals(keyname, keyname?.ToLower(), StringComparison.InvariantCulture), "missing ToLower");
+                string realkeyname = ((null != synonyms) ? (string)synonyms[keyname] : keyname);
+
+                if ((KEY.Password != realkeyname) && (SYNONYM.Pwd != realkeyname))
+                {
+                    // don't trace passwords ever!
+                    if (null != keyvalue)
+                    {
+                        SqlClientEventSource.Log.AdvanceTrace("<comm.DbConnectionOptions|INFO|ADV> KeyName='{0}', KeyValue='{1}'", keyname, keyvalue);
+                    }
+                    else
+                    {
+                        SqlClientEventSource.Log.AdvanceTrace("<comm.DbConnectionOptions|INFO|ADV> KeyName='{0}'", keyname);
+                    }
+                }
+            }
+        }
 
         private static string GetKeyName(StringBuilder buffer)
         {

src/Microsoft.Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs

@@ -9,6 +9,7 @@
 using System.Threading.Tasks;
 using Microsoft.Data.Common;
 using System;
+using Microsoft.Data.SqlClient;
 
 namespace Microsoft.Data.ProviderBase
 {
@@ -21,13 +22,16 @@ internal abstract partial class DbConnectionFactory
         private const int PruningDueTime = 4 * 60 * 1000;           // 4 minutes
         private const int PruningPeriod = 30 * 1000;           // thirty seconds
 
+        private static int _objectTypeCount; // EventSource counter
+        internal int ObjectID { get; } = Interlocked.Increment(ref _objectTypeCount);
 
         // s_pendingOpenNonPooled is an array of tasks used to throttle creation of non-pooled connections to 
         // a maximum of Environment.ProcessorCount at a time.
         private static uint s_pendingOpenNonPooledNext = 0;
         private static Task<DbConnectionInternal>[] s_pendingOpenNonPooled = new Task<DbConnectionInternal>[Environment.ProcessorCount];
         private static Task<DbConnectionInternal> s_completedTask;
 
+
         protected DbConnectionFactory()
         {
             _connectionPoolGroups = new Dictionary<DbConnectionPoolKey, DbConnectionPoolGroup>();
@@ -45,38 +49,60 @@ abstract public DbProviderFactory ProviderFactory
 
         public void ClearAllPools()
         {
-            Dictionary<DbConnectionPoolKey, DbConnectionPoolGroup> connectionPoolGroups = _connectionPoolGroups;
-            foreach (KeyValuePair<DbConnectionPoolKey, DbConnectionPoolGroup> entry in connectionPoolGroups)
+            long scopeID = SqlClientEventSource.Log.ScopeEnterEvent("<prov.DbConnectionFactory.ClearAllPools|{0}>", "API");
+            try
             {
-                DbConnectionPoolGroup poolGroup = entry.Value;
-                if (null != poolGroup)
+                Dictionary<DbConnectionPoolKey, DbConnectionPoolGroup> connectionPoolGroups = _connectionPoolGroups;
+                foreach (KeyValuePair<DbConnectionPoolKey, DbConnectionPoolGroup> entry in connectionPoolGroups)
                 {
-                    poolGroup.Clear();
+                    DbConnectionPoolGroup poolGroup = entry.Value;
+                    if (null != poolGroup)
+                    {
+                        poolGroup.Clear();
+                    }
                 }
             }
+            finally
+            {
+                SqlClientEventSource.Log.ScopeLeaveEvent(scopeID);
+            }
         }
 
         public void ClearPool(DbConnection connection)
         {
             ADP.CheckArgumentNull(connection, nameof(connection));
-
-            DbConnectionPoolGroup poolGroup = GetConnectionPoolGroup(connection);
-            if (null != poolGroup)
+            long scopeID = SqlClientEventSource.Log.ScopeEnterEvent("<prov.DbConnectionFactory.ClearPool|API> {0}#", GetObjectId(connection));
+            try
             {
-                poolGroup.Clear();
+                DbConnectionPoolGroup poolGroup = GetConnectionPoolGroup(connection);
+                if (null != poolGroup)
+                {
+                    poolGroup.Clear();
+                }
+            }
+            finally
+            {
+                SqlClientEventSource.Log.ScopeLeaveEvent(scopeID);
             }
         }
 
         public void ClearPool(DbConnectionPoolKey key)
         {
             Debug.Assert(key != null, "key cannot be null");
             ADP.CheckArgumentNull(key.ConnectionString, nameof(key) + "." + nameof(key.ConnectionString));
-
-            DbConnectionPoolGroup poolGroup;
-            Dictionary<DbConnectionPoolKey, DbConnectionPoolGroup> connectionPoolGroups = _connectionPoolGroups;
-            if (connectionPoolGroups.TryGetValue(key, out poolGroup))
+            long scopeID = SqlClientEventSource.Log.ScopeEnterEvent("<prov.DbConnectionFactory.ClearPool|API> connectionString");
+            try
             {
-                poolGroup.Clear();
+                DbConnectionPoolGroup poolGroup;
+                Dictionary<DbConnectionPoolKey, DbConnectionPoolGroup> connectionPoolGroups = _connectionPoolGroups;
+                if (connectionPoolGroups.TryGetValue(key, out poolGroup))
+                {
+                    poolGroup.Clear();
+                }
+            }
+            finally
+            {
+                SqlClientEventSource.Log.ScopeLeaveEvent(scopeID);
             }
         }
 
@@ -100,6 +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);
             return newConnection;
         }
 
@@ -113,6 +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);
             return newConnection;
         }
 
@@ -167,6 +195,8 @@ 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);
+
                 // reusing existing pool option in case user originally used SetConnectionPoolOptions
                 DbConnectionPoolGroupOptions poolOptions = connectionPoolGroup.PoolGroupOptions;
 
@@ -272,6 +302,9 @@ 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);
+
             // First, walk the pool release list and attempt to clear each
             // pool, when the pool is finally empty, we dispose of it.  If the
             // pool isn't empty, it's because there are active connections or
@@ -290,6 +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);
                             }
                         }
                     }
@@ -313,6 +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);
                             }
                         }
                     }
@@ -375,6 +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);
 
             lock (_poolGroupsToRelease)
             {
@@ -427,6 +463,8 @@ protected virtual DbMetaDataFactory CreateMetaDataFactory(DbConnectionInternal i
 
         abstract internal DbConnectionInternal GetInnerConnection(DbConnection connection);
 
+        abstract protected int GetObjectId(DbConnection conne);
+
         abstract internal void PermissionDemand(DbConnection outerConnection);
 
         abstract internal void SetConnectionPoolGroup(DbConnection outerConnection, DbConnectionPoolGroup poolGroup);

src/Microsoft.Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs

@@ -3,6 +3,7 @@
 // See the LICENSE file in the project root for more information.
 
 using Microsoft.Data.Common;
+using Microsoft.Data.SqlClient;
 using System;
 using System.Data;
 using System.Data.Common;
@@ -224,6 +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);
 
 #if DEBUG
             int activateCount = Interlocked.Decrement(ref _activateCount);
@@ -247,12 +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);
         }
 
         /// <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);
         }
 
         protected internal virtual DataTable GetSchema(DbConnectionFactory factory, DbConnectionPoolGroup poolGroup, DbConnection outerConnection, string collectionName, string[] restrictions)
@@ -372,6 +376,8 @@ 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);
             _pooledCount++;
             _owningObject.Target = null; // NOTE: doing this and checking for InternalError.PooledObjectHasOwner degrades the close by 2%
         }
@@ -400,6 +406,8 @@ 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);
+
             //3 // The following tests are retail assertions of things we can't allow to happen.
             if (null != Pool)
             {

src/Microsoft.Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionPoolGroup.cs

@@ -4,9 +4,11 @@
 
 
 using Microsoft.Data.Common;
+using Microsoft.Data.SqlClient;
 using System.Collections.Concurrent;
 using System.Data.Common;
 using System.Diagnostics;
+using System.Threading;
 
 namespace Microsoft.Data.ProviderBase
 {
@@ -39,6 +41,8 @@ sealed internal class DbConnectionPoolGroup
         private DbConnectionPoolGroupProviderInfo _providerInfo;
         private DbMetaDataFactory _metaDataFactory;
 
+        private static int s_objectTypeCount; // EventSource counter
+
         // always lock this before changing _state, we don't want to move out of the 'Disabled' state
         // PoolGroupStateUninitialized = 0;
         private const int PoolGroupStateActive = 1; // initial state, GetPoolGroup from cache, connection Open
@@ -83,6 +87,8 @@ internal DbConnectionPoolGroupProviderInfo ProviderInfo
 
         internal bool IsDisabled => (PoolGroupStateDisabled == _state);
 
+        internal int ObjectID { get; } = Interlocked.Increment(ref s_objectTypeCount);
+
         internal DbConnectionPoolGroupOptions PoolGroupOptions => _poolGroupOptions;
 
         internal DbMetaDataFactory MetaDataFactory
@@ -223,6 +229,7 @@ private bool MarkPoolGroupAsActive()
             if (PoolGroupStateIdle == _state)
             {
                 _state = PoolGroupStateActive;
+                SqlClientEventSource.Log.TraceEvent("<prov.DbConnectionPoolGroup.ClearInternal|RES|INFO|CPOOL> {0}#, Active", ObjectID);
             }
             return (PoolGroupStateActive == _state);
         }
@@ -274,10 +281,12 @@ internal bool Prune()
                     if (PoolGroupStateActive == _state)
                     {
                         _state = PoolGroupStateIdle;
+                        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);
                     }
                 }
                 return (PoolGroupStateDisabled == _state);

src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj

@@ -566,6 +566,8 @@
     <Reference Include="System.Memory" />
   </ItemGroup>
   <ItemGroup>
+    <Compile Include="Microsoft\Data\SqlClient\SqlClientEventSource.cs" />
+    <Compile Include="Microsoft\Data\SqlClient\SqlClientLogger.cs" />
     <Compile Include="Resources\SR.Designer.cs">
       <DesignTime>True</DesignTime>
       <AutoGen>True</AutoGen>

src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/DataException.cs

@@ -3,6 +3,8 @@
 // See the LICENSE file in the project root for more information.
 
 using System;
+using System.Diagnostics;
+using Microsoft.Data.SqlClient;
 
 namespace Microsoft.Data
 {
@@ -23,8 +25,19 @@ internal static class ExceptionBuilder
         // The resource Data.txt will ensure proper string text based on the appropriate
         // locale.
 
+        static private void TraceException(
+           string trace, Exception e)
+        {
+            Debug.Assert(null != e, "TraceException: null Exception");
+            if (null != e)
+            {
+                SqlClientEventSource.Log.AdvanceTrace("<comm.ADP.TraceException|ERR|ADV> Environment StackTrace = '{0}'", Environment.StackTrace);
+            }
+        }
+
         internal static void TraceExceptionAsReturnValue(Exception e)
         {
+            TraceException("<comm.ADP.TraceException|ERR|THROW> Message='{0}'", e);
         }
 
         //