Supporting Event counter in .Net core (dotnet#719)

* Add event counters * Add support netstandard 2.1 & fix the conflict in event source * Support new event source types & add the test unit * Remove supporting obsolete types * fix unit test * Add snippet sample code * Address comments * Fix minor typo (#3) * Reformatting counter methods * Fix minor typo * Removed IsEnabled condition and reformatted counter methods * Unit tests for Microsoft.Data.SqlClient.SqlClientEventSource (#2) * Implemented tests for Microsoft.Data.SqlClient.SqlClientEventSource * Updated the EventCounter test to reflect the recent changes in the code * Working on EventCounter tests access event counters through reflection * Updated the EventCounterTest to use reflection * Fixing dangling SqlConnection's left in tests * EventCountersTest now checks hard/soft connects/disconnects counters * Reverted the DataTestUtility changes * Reverted using statements to the old-style in tests * Reverted the ConnectionPoolTest.ReclaimEmancipatedOnOpenTest() * Reverted using statements to the old-style in tests * Reverted using statements to the old-style in tests * Rewrite the EventCounterTest assertions not to conflict with other tests * Code review cleanup * Add more tests (#5) Added EventCounter_ReclaimedConnectionsCounter_Functional & EventCounter_ConnectionPoolGroupsCounter_Functional tests. * Address comments Co-authored-by: Davoud Eshtehari <[email protected]> Co-authored-by: Davoud Eshtehari <[email protected]> Co-authored-by: Karina Zhou <[email protected]> Co-authored-by: Nikita Kobzev <[email protected]>
DavoudEshtehari · Mar 13, 2021 · 884b113 · 884b113
1 parent 0005645
commit 884b113
Show file tree

Hide file tree

Showing 20 changed files with 1,097 additions and 137 deletions.
diff --git a/doc/samples/SqlClientDiagnosticCounter.cs b/doc/samples/SqlClientDiagnosticCounter.cs
@@ -0,0 +1,62 @@
+// <Snippet1>
+using System;
+using System.Collections.Generic;
+using System.Diagnostics.Tracing;
+using System.Linq;
+
+// This listener class will listen for events from the SqlClientEventSource class.
+// SqlClientEventSource is an implementation of the EventSource class which gives 
+// it the ability to create events.
+public class EventCounterListener : EventListener
+{
+    protected override void OnEventSourceCreated(EventSource eventSource)
+    {
+        // Only enable events from SqlClientEventSource.
+        if (eventSource.Name.Equals("Microsoft.Data.SqlClient.EventSource"))
+        {
+            var options = new Dictionary<string, string>();
+            // define time interval 1 second
+            // without defining this parameter event counters will not enabled
+            options.Add("EventCounterIntervalSec", "1");
+            // enable for the None keyword
+            EnableEvents(eventSource, EventLevel.Informational, EventKeywords.None, options);
+        }
+    }
+
+    // This callback runs whenever an event is written by SqlClientEventSource.
+    // Event data is accessed through the EventWrittenEventArgs parameter.
+    protected override void OnEventWritten(EventWrittenEventArgs eventData)
+    {
+        if (eventData.Payload.FirstOrDefault(p => p is IDictionary<string, object> x && x.ContainsKey("Name")) is IDictionary<string, object> counters)
+        {
+            if (counters.TryGetValue("DisplayName", out object name) && name is string cntName
+                && counters.TryGetValue("Mean", out object value) && value is double cntValue)
+            {
+                // print event counter's name and mean value
+                Console.WriteLine($"{cntName}\t\t{cntValue}");
+            }
+        }
+    }
+}
+
+class Program
+{
+    static void Main(string[] args)
+    {
+        // Create a new event listener
+        using (var listener = new EventCounterListener())
+        {
+            string connectionString = "Data Source=localhost; Integrated Security=true";
+
+            for (int i = 0; i < 50; i++)
+            {
+                // Open a connection
+                SqlConnection cnn = new SqlConnection(connectionString);
+                cnn.Open();
+                // wait for sampling interval happens
+                System.Threading.Thread.Sleep(500);
+            }
+        }
+    }
+}
+// </Snippet1>
diff --git a/....Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs b/....Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs
@@ -25,7 +25,7 @@ internal abstract partial class DbConnectionFactory
         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 
+        // 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];
@@ -124,6 +124,7 @@ internal DbConnectionInternal CreateNonPooledConnection(DbConnection owningConne
             DbConnectionInternal newConnection = CreateConnection(connectionOptions, poolKey, poolGroupProviderInfo, null, owningConnection, userOptions);
             if (null != newConnection)
             {
+                SqlClientEventSource.Log.HardConnectRequest();
                 newConnection.MakeNonPooledObject(owningConnection);
             }
             SqlClientEventSource.Log.TryTraceEvent("<prov.DbConnectionFactory.CreateNonPooledConnection|RES|CPOOL> {0}, Non-pooled database connection created.", ObjectID);
@@ -138,6 +139,7 @@ internal DbConnectionInternal CreatePooledConnection(DbConnectionPool pool, DbCo
             DbConnectionInternal newConnection = CreateConnection(options, poolKey, poolGroupProviderInfo, pool, owningObject, userOptions);
             if (null != newConnection)
             {
+                SqlClientEventSource.Log.HardConnectRequest();
                 newConnection.MakePooledConnection(pool);
             }
             SqlClientEventSource.Log.TryTraceEvent("<prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> {0}, Pooled database connection created.", ObjectID);
@@ -281,6 +283,7 @@ internal DbConnectionPoolGroup GetConnectionPoolGroup(DbConnectionPoolKey key, D
 
                         // lock prevents race condition with PruneConnectionPoolGroups
                         newConnectionPoolGroups.Add(key, newConnectionPoolGroup);
+                        SqlClientEventSource.Log.EnterActiveConnectionPoolGroup();
                         connectionPoolGroup = newConnectionPoolGroup;
                         _connectionPoolGroups = newConnectionPoolGroups;
                     }
@@ -304,7 +307,7 @@ private void PruneConnectionPoolGroups(object state)
         {
             // when debugging this method, expect multiple threads at the same time
             SqlClientEventSource.Log.TryAdvancedTraceEvent("<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
@@ -324,6 +327,7 @@ private void PruneConnectionPoolGroups(object state)
                             {
                                 _poolsToRelease.Remove(pool);
                                 SqlClientEventSource.Log.TryAdvancedTraceEvent("<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> {0}, ReleasePool={1}", ObjectID, pool.ObjectID);
+                                SqlClientEventSource.Log.ExitInactiveConnectionPool();
                             }
                         }
                     }
@@ -348,6 +352,7 @@ private void PruneConnectionPoolGroups(object state)
                             {
                                 _poolGroupsToRelease.Remove(poolGroup);
                                 SqlClientEventSource.Log.TryAdvancedTraceEvent("<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> {0}, ReleasePoolGroup={1}", ObjectID, poolGroup.ObjectID);
+                                SqlClientEventSource.Log.ExitInactiveConnectionPoolGroup();
                             }
                         }
                     }
@@ -372,7 +377,8 @@ private void PruneConnectionPoolGroups(object state)
                         // move idle entries from last prune pass to a queue for pending release
                         // otherwise process entry which may move it from active to idle
                         if (entry.Value.Prune())
-                        { // may add entries to _poolsToRelease
+                        {
+                            // may add entries to _poolsToRelease
                             QueuePoolGroupForRelease(entry.Value);
                         }
                         else
@@ -405,6 +411,8 @@ internal void QueuePoolForRelease(DbConnectionPool pool, bool clearing)
                 }
                 _poolsToRelease.Add(pool);
             }
+            SqlClientEventSource.Log.EnterInactiveConnectionPool();
+            SqlClientEventSource.Log.ExitActiveConnectionPool();
         }
 
         internal void QueuePoolGroupForRelease(DbConnectionPoolGroup poolGroup)
@@ -416,6 +424,8 @@ internal void QueuePoolGroupForRelease(DbConnectionPoolGroup poolGroup)
             {
                 _poolGroupsToRelease.Add(poolGroup);
             }
+            SqlClientEventSource.Log.EnterInactiveConnectionPoolGroup();
+            SqlClientEventSource.Log.ExitActiveConnectionPoolGroup();
         }
 
         virtual protected DbConnectionInternal CreateConnection(DbConnectionOptions options, DbConnectionPoolKey poolKey, object poolGroupProviderInfo, DbConnectionPool pool, DbConnection owningConnection, DbConnectionOptions userOptions)

diff --git a/...Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs b/...Data.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs
@@ -231,6 +231,7 @@ internal void DeactivateConnection()
             int activateCount = Interlocked.Decrement(ref _activateCount);
 #endif // DEBUG
 
+            SqlClientEventSource.Log.ExitActiveConnection();
 
             if (!_connectionIsDoomed && Pool.UseLoadBalancing)
             {

diff --git a/...ata.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionPoolGroup.cs b/...ata.SqlClient/netcore/src/Common/src/Microsoft/Data/ProviderBase/DbConnectionPoolGroup.cs
@@ -187,15 +187,16 @@ internal DbConnectionPool GetConnectionPool(DbConnectionFactory connectionFactor
                                     newPool.Startup(); // must start pool before usage
                                     bool addResult = _poolCollection.TryAdd(currentIdentity, newPool);
                                     Debug.Assert(addResult, "No other pool with current identity should exist at this point");
+                                    SqlClientEventSource.Log.EnterActiveConnectionPool();
                                     pool = newPool;
                                 }
                                 else
                                 {
                                     // else pool entry has been disabled so don't create new pools
                                     Debug.Assert(PoolGroupStateDisabled == _state, "state should be disabled");
 
-                                    // don't need to call connectionFactory.QueuePoolForRelease(newPool) because		
-                                    // pool callbacks were delayed and no risk of connections being created		
+                                    // don't need to call connectionFactory.QueuePoolForRelease(newPool) because
+                                    // pool callbacks were delayed and no risk of connections being created
                                     newPool.Shutdown();
                                 }
                             }
@@ -262,7 +263,6 @@ internal bool Prune()
                                 // pool into a list of pools to be released when they
                                 // are completely empty.
                                 DbConnectionFactory connectionFactory = pool.ConnectionFactory;
-
                                 connectionFactory.QueuePoolForRelease(pool, false);
                             }
                             else

diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj
@@ -327,6 +327,10 @@
     <Compile Include="Microsoft\Data\SqlClient\VirtualSecureModeEnclaveProviderBase.cs" />
     <Compile Include="Microsoft\Data\SqlClient\AlwaysEncryptedEnclaveProviderUtils.cs" />
 	</ItemGroup>
+  <!-- netcoreapp 3.1 & netstandard 2.1 and above -->
+  <ItemGroup Condition="'$(OSGroup)' != 'AnyOS' AND '$(TargetFramework)' != 'netcoreapp2.1' AND '$(TargetFramework)' != 'netstandard2.0'">
+    <Compile Include="Microsoft\Data\SqlClient\SqlClientEventSource.NetCoreApp.cs" />
+  </ItemGroup>
   <ItemGroup Condition="'$(OSGroup)' != 'AnyOS' AND '$(TargetGroup)' == 'netcoreapp'">
     <Compile Include="Microsoft\Data\Common\DbConnectionStringCommon.NetCoreApp.cs" />
     <Compile Include="Microsoft\Data\ProviderBase\DbConnectionPool.NetCoreApp.cs" />

diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/ProviderBase/DbConnectionFactory.cs
@@ -108,6 +108,7 @@ internal bool TryGetConnection(DbConnection owningConnection, TaskCompletionSour
                     }
 
                     connection = CreateNonPooledConnection(owningConnection, poolGroup, userOptions);
+                    SqlClientEventSource.Log.EnterNonPooledConnection();
                 }
                 else
                 {
@@ -209,6 +210,10 @@ private static void TryGetConnectionCompletedContinuation(Task<DbConnectionInter
                     task.Result.DoomThisConnection();
                     task.Result.Dispose();
                 }
+                else
+                {
+                    SqlClientEventSource.Log.EnterNonPooledConnection();
+                }
             }
         }
     }

diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/ProviderBase/DbConnectionInternal.cs
@@ -219,6 +219,7 @@ internal void ActivateConnection(Transaction transaction)
 #endif // DEBUG
 
             Activate(transaction);
+            SqlClientEventSource.Log.EnterActiveConnection();
         }
 
         internal virtual void CloseConnection(DbConnection owningObject, DbConnectionFactory connectionFactory)
@@ -296,6 +297,7 @@ internal virtual void CloseConnection(DbConnection owningObject, DbConnectionFac
                         else
                         {
                             Deactivate();   // ensure we de-activate non-pooled connections, or the data readers and transactions may not get cleaned up...
+                            SqlClientEventSource.Log.HardDisconnectRequest();
 
                             // To prevent an endless recursion, we need to clear
                             // the owning object before we call dispose so that
@@ -312,6 +314,7 @@ internal virtual void CloseConnection(DbConnection owningObject, DbConnectionFac
                             }
                             else
                             {
+                                SqlClientEventSource.Log.ExitNonPooledConnection();
                                 Dispose();
                             }
                         }
@@ -370,6 +373,7 @@ virtual internal void DelegatedTransactionEnded()
                 // once and for all, or the server will have fits about us
                 // leaving connections open until the client-side GC kicks 
                 // in.
+                SqlClientEventSource.Log.ExitNonPooledConnection();
                 Dispose();
             }
             // When _pooledCount is 0, the connection is a pooled connection
@@ -482,6 +486,7 @@ internal void SetInStasis()
         {
             _isInStasis = true;
             SqlClientEventSource.Log.TryPoolerTraceEvent("<prov.DbConnectionInternal.SetInStasis|RES|CPOOL> {0}, Non-Pooled Connection has Delegated Transaction, waiting to Dispose.", ObjectID);
+            SqlClientEventSource.Log.EnterStasisConnection();
         }
 
         private void TerminateStasis(bool returningToPool)
@@ -494,6 +499,7 @@ private void TerminateStasis(bool returningToPool)
             {
                 SqlClientEventSource.Log.TryPoolerTraceEvent("<prov.DbConnectionInternal.TerminateStasis|RES|CPOOL> {0}, Delegated Transaction has ended, connection is closed/leaked.  Disposing.", ObjectID);
             }
+            SqlClientEventSource.Log.ExitStasisConnection();
             _isInStasis = false;
         }
     }

diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/ProviderBase/DbConnectionPool.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/ProviderBase/DbConnectionPool.cs
@@ -231,6 +231,7 @@ internal void PutTransactedObject(Transaction transaction, DbConnectionInternal
                     }
                     SqlClientEventSource.Log.TryPoolerTraceEvent("<prov.DbConnectionPool.TransactedConnectionPool.PutTransactedObject|RES|CPOOL> {0}, Transaction {1}, Connection {2}, Added.", ObjectID, transaction.GetHashCode(), transactedObject.ObjectID);
                 }
+                SqlClientEventSource.Log.EnterFreeConnection();
             }
 
             internal void TransactionEnded(Transaction transaction, DbConnectionInternal transactedObject)
@@ -293,6 +294,7 @@ internal void TransactionEnded(Transaction transaction, DbConnectionInternal tra
                 // connections, we'll put it back...
                 if (0 <= entry)
                 {
+                    SqlClientEventSource.Log.ExitFreeConnection();
                     Pool.PutObjectFromTransactedPool(transactedObject);
                 }
             }
@@ -600,6 +602,7 @@ private void CleanupCallback(object state)
                     {
                         Debug.Assert(obj != null, "null connection is not expected");
                         // If we obtained one from the old stack, destroy it.
+                        SqlClientEventSource.Log.ExitFreeConnection();
 
                         // Transaction roots must survive even aging out (TxEnd event will clean them up).
                         bool shouldDestroy = true;
@@ -696,11 +699,13 @@ internal void Clear()
             while (_stackNew.TryPop(out obj))
             {
                 Debug.Assert(obj != null, "null connection is not expected");
+                SqlClientEventSource.Log.ExitFreeConnection();
                 DestroyObject(obj);
             }
             while (_stackOld.TryPop(out obj))
             {
                 Debug.Assert(obj != null, "null connection is not expected");
+                SqlClientEventSource.Log.ExitFreeConnection();
                 DestroyObject(obj);
             }
 
@@ -742,6 +747,7 @@ private DbConnectionInternal CreateObject(DbConnection owningObject, DbConnectio
                     }
                     _objectList.Add(newObj);
                     _totalObjects = _objectList.Count;
+                    SqlClientEventSource.Log.EnterPooledConnection();
                 }
 
                 // If the old connection belonged to another pool, we need to remove it from that
@@ -967,9 +973,11 @@ internal void DestroyObject(DbConnectionInternal obj)
                 if (removed)
                 {
                     SqlClientEventSource.Log.TryPoolerTraceEvent("<prov.DbConnectionPool.DestroyObject|RES|CPOOL> {0}, Connection {1}, Removed from pool.", ObjectID, obj.ObjectID);
+                    SqlClientEventSource.Log.ExitPooledConnection();
                 }
                 obj.Dispose();
                 SqlClientEventSource.Log.TryPoolerTraceEvent("<prov.DbConnectionPool.DestroyObject|RES|CPOOL> {0}, Connection {1}, Disposed.", ObjectID, obj.ObjectID);
+                SqlClientEventSource.Log.HardDisconnectRequest();
             }
         }
 
@@ -1301,6 +1309,7 @@ private bool TryGetConnection(DbConnection owningObject, uint waitForMultipleObj
             }
 
             connection = obj;
+            SqlClientEventSource.Log.SoftConnectRequest();
             return true;
         }
 
@@ -1337,6 +1346,7 @@ internal DbConnectionInternal ReplaceConnection(DbConnection owningObject, DbCon
 
             if (newConnection != null)
             {
+                SqlClientEventSource.Log.SoftConnectRequest();
                 PrepareConnection(owningObject, newConnection, oldConnection.EnlistedTransaction);
                 oldConnection.PrepareForReplaceConnection();
                 oldConnection.DeactivateConnection();
@@ -1374,6 +1384,7 @@ private DbConnectionInternal GetFromGeneralPool()
             if (null != obj)
             {
                 SqlClientEventSource.Log.TryPoolerTraceEvent("<prov.DbConnectionPool.GetFromGeneralPool|RES|CPOOL> {0}, Connection {1}, Popped from general pool.", ObjectID, obj.ObjectID);
+                SqlClientEventSource.Log.ExitFreeConnection();
             }
             return (obj);
         }
@@ -1390,6 +1401,7 @@ private DbConnectionInternal GetFromTransactedPool(out Transaction transaction)
                 if (null != obj)
                 {
                     SqlClientEventSource.Log.TryPoolerTraceEvent("<prov.DbConnectionPool.GetFromTransactedPool|RES|CPOOL> {0}, Connection {1}, Popped from transacted pool.", ObjectID, obj.ObjectID);
+                    SqlClientEventSource.Log.ExitFreeConnection();
 
                     if (obj.IsTransactionRoot)
                     {
@@ -1544,12 +1556,13 @@ internal void PutNewObject(DbConnectionInternal obj)
 
             _stackNew.Push(obj);
             _waitHandles.PoolSemaphore.Release(1);
+            SqlClientEventSource.Log.EnterFreeConnection();
         }
 
         internal void PutObject(DbConnectionInternal obj, object owningObject)
         {
             Debug.Assert(null != obj, "null obj?");
-
+            SqlClientEventSource.Log.SoftDisconnectRequest();
 
             // Once a connection is closing (which is the state that we're in at
             // this point in time) you cannot delegate a transaction to or enlist
@@ -1662,6 +1675,8 @@ private bool ReclaimEmancipatedObjects()
             {
                 DbConnectionInternal obj = reclaimedObjects[i];
                 SqlClientEventSource.Log.TryPoolerTraceEvent("<prov.DbConnectionPool.ReclaimEmancipatedObjects|RES|CPOOL> {0}, Connection {1}, Reclaiming.", ObjectID, obj.ObjectID);
+                SqlClientEventSource.Log.ReclaimedConnectionRequest();
+
                 emancipatedObjectFound = true;
 
                 obj.DetachCurrentTransactionIfEnded();