Make counters use dedicated thread instead of timer (#25864) (#25978)
authorSung Yoon Whang <suwhang@microsoft.com>
Wed, 7 Aug 2019 16:14:38 +0000 (09:14 -0700)
committerWilliam Godbe <wigodbe@microsoft.com>
Wed, 7 Aug 2019 16:14:38 +0000 (09:14 -0700)
* Make a dedicated polling thread for EventCounters

* Cleanup

* remove debug prints

* nit

* Fix comment

* addressing issues from code review

* Fix an assertion from getting fired when we have multiple listeners

* Fix a test issue

* code review feedback

* Fix a potential deadlock

* Fix another deadlock

* Allow s_sleepDurationInMilliseconds to be reset to a larger value

* More issues fix

* Let thread wake up from sleep if needed

* Some suggestions for the counters fix.

The resulting behavior should be the same as what is there now (assuming I didn't mess anything up), these are all just code simplifications that hopefully make it easier to review and maintain going forward. In total I think this reduces the change size in CounterGroup.cs by ~30%.
- With the addition of the AutoResetEvent the ManualResetEvent is no longer needed, removed it.
- Removed the various if foo != null checks for the shared state, it is all initialized once when then thread is created and then assumed to be non-null elsewhere.
- Removed a 2nd lock acquisition inside OnTimer
- Replaced an if with Math.Min in PollForValues

* fix test

src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/CounterGroup.cs
src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/EventCounter.cs
tests/src/tracing/eventcounter/eventcounter.cs

index 2b4dd1b..d8b285b 100644 (file)
@@ -21,6 +21,7 @@ namespace System.Diagnostics.Tracing
     {
         private readonly EventSource _eventSource;
         private readonly List<DiagnosticCounter> _counters;
+        private static readonly object s_counterGroupLock  = new object();
 
         internal CounterGroup(EventSource eventSource)
         {
@@ -31,13 +32,13 @@ namespace System.Diagnostics.Tracing
 
         internal void Add(DiagnosticCounter eventCounter)
         {
-            lock (this) // Lock the CounterGroup
+            lock (s_counterGroupLock) // Lock the CounterGroup
                 _counters.Add(eventCounter);
         }
 
         internal void Remove(DiagnosticCounter eventCounter)
         {
-            lock (this) // Lock the CounterGroup
+            lock (s_counterGroupLock) // Lock the CounterGroup
                 _counters.Remove(eventCounter);
         }
 
@@ -56,7 +57,7 @@ namespace System.Diagnostics.Tracing
 
                 if (e.Arguments.TryGetValue("EventCounterIntervalSec", out string? valueStr) && float.TryParse(valueStr, out float value))
                 {
-                    lock (this)      // Lock the CounterGroup
+                    lock (s_counterGroupLock)      // Lock the CounterGroup
                     {
                         EnableTimer(value);
                     }
@@ -64,9 +65,9 @@ namespace System.Diagnostics.Tracing
             }
             else if (e.Command == EventCommand.Disable)
             {
-                lock (this)
+                lock(s_counterGroupLock)
                 {
-                    _pollingIntervalInMilliseconds = 0;
+                    DisableTimer();
                 }
             }
         }
@@ -79,11 +80,10 @@ namespace System.Diagnostics.Tracing
         // this table provides the mapping from EventSource -> CounterGroup 
         // which represents this 'attached' information.   
         private static WeakReference<CounterGroup>[]? s_counterGroups;
-        private static readonly object s_counterGroupsLock = new object();
 
         private static void EnsureEventSourceIndexAvailable(int eventSourceIndex)
         {
-            Debug.Assert(Monitor.IsEntered(s_counterGroupsLock));
+            Debug.Assert(Monitor.IsEntered(s_counterGroupLock));
             if (CounterGroup.s_counterGroups == null)
             {
                 CounterGroup.s_counterGroups = new WeakReference<CounterGroup>[eventSourceIndex + 1];
@@ -98,7 +98,7 @@ namespace System.Diagnostics.Tracing
 
         internal static CounterGroup GetCounterGroup(EventSource eventSource)
         {
-            lock (s_counterGroupsLock)
+            lock (s_counterGroupLock)
             {
                 int eventSourceIndex = EventListener.EventSourceIndex(eventSource);
                 EnsureEventSourceIndexAvailable(eventSourceIndex);
@@ -120,32 +120,20 @@ namespace System.Diagnostics.Tracing
 
         private DateTime _timeStampSinceCollectionStarted;
         private int _pollingIntervalInMilliseconds;
-        private Timer? _pollingTimer;
-
-        private void DisposeTimer()
-        {
-            Debug.Assert(Monitor.IsEntered(this));
-            if (_pollingTimer != null)
-            {
-                _pollingTimer.Dispose();
-                _pollingTimer = null;
-            }
-        }
+        private DateTime _nextPollingTimeStamp;
 
         private void EnableTimer(float pollingIntervalInSeconds)
         {
-            Debug.Assert(Monitor.IsEntered(this));
+            Debug.Assert(Monitor.IsEntered(s_counterGroupLock));
             if (pollingIntervalInSeconds <= 0)
             {
-                DisposeTimer();
                 _pollingIntervalInMilliseconds = 0;
             }
             else if (_pollingIntervalInMilliseconds == 0 || pollingIntervalInSeconds * 1000 < _pollingIntervalInMilliseconds)
             {
-                Debug.WriteLine("Polling interval changed at " + DateTime.UtcNow.ToString("mm.ss.ffffff"));
                 _pollingIntervalInMilliseconds = (int)(pollingIntervalInSeconds * 1000);
-                DisposeTimer();
                 ResetCounters(); // Reset statistics for counters before we start the thread.
+
                 _timeStampSinceCollectionStarted = DateTime.UtcNow;
                 // Don't capture the current ExecutionContext and its AsyncLocals onto the timer causing them to live forever
                 bool restoreFlow = false;
@@ -157,7 +145,25 @@ namespace System.Diagnostics.Tracing
                         restoreFlow = true;
                     }
 
-                    _pollingTimer = new Timer(s => ((CounterGroup)s!).OnTimer(null), this, _pollingIntervalInMilliseconds, _pollingIntervalInMilliseconds);
+                    _nextPollingTimeStamp = DateTime.UtcNow + new TimeSpan(0, 0, (int)pollingIntervalInSeconds);
+                    
+                    // Create the polling thread and init all the shared state if needed
+                    if (s_pollingThread == null)
+                    {
+                        s_pollingThreadSleepEvent = new AutoResetEvent(false);
+                        s_counterGroupEnabledList = new List<CounterGroup>();
+                        s_pollingThread = new Thread(PollForValues) { IsBackground = true };
+                        s_pollingThread.Start();
+                    }
+
+                    if (!s_counterGroupEnabledList!.Contains(this))
+                    {
+                        s_counterGroupEnabledList.Add(this);
+                    }
+
+                    // notify the polling thread that the polling interval may have changed and the sleep should
+                    // be recomputed
+                    s_pollingThreadSleepEvent!.Set();
                 }
                 finally
                 {
@@ -168,9 +174,15 @@ namespace System.Diagnostics.Tracing
             }
         }
 
+        private void DisableTimer()
+        {
+            _pollingIntervalInMilliseconds = 0;
+            s_counterGroupEnabledList?.Remove(this);
+        }
+
         private void ResetCounters()
         {
-            lock (this) // Lock the CounterGroup
+            lock (s_counterGroupLock) // Lock the CounterGroup
             {
                 foreach (var counter in _counters)
                 {
@@ -190,63 +202,65 @@ namespace System.Diagnostics.Tracing
             }
         }
 
-        private void OnTimer(object? state)
+        private void OnTimer()
         {
-            Debug.WriteLine("Timer fired at " + DateTime.UtcNow.ToString("mm.ss.ffffff"));
-            lock (this) // Lock the CounterGroup
+            Debug.Assert(Monitor.IsEntered(s_counterGroupLock));
+            if (_eventSource.IsEnabled())
             {
-                if (_eventSource.IsEnabled())
-                {
-                    DateTime now = DateTime.UtcNow;
-                    TimeSpan elapsed = now - _timeStampSinceCollectionStarted;
+                DateTime now = DateTime.UtcNow;
+                TimeSpan elapsed = now - _timeStampSinceCollectionStarted;
 
-                    foreach (var counter in _counters)
-                    {
-                        counter.WritePayload((float)elapsed.TotalSeconds, _pollingIntervalInMilliseconds);
-                    }
-                    _timeStampSinceCollectionStarted = now;
-                }
-                else
+                foreach (var counter in _counters)
                 {
-                    DisposeTimer();
+                    counter.WritePayload((float)elapsed.TotalSeconds, _pollingIntervalInMilliseconds);
                 }
+                _timeStampSinceCollectionStarted = now;
+
+                do
+                {
+                    _nextPollingTimeStamp += new TimeSpan(0, 0, 0, 0, _pollingIntervalInMilliseconds);
+                } while (_nextPollingTimeStamp <= now);
             }
         }
 
-        #region PCL timer hack
 
-#if ES_BUILD_PCL
-        internal delegate void TimerCallback(object state);
-
-        internal sealed class Timer : CancellationTokenSource, IDisposable
-        {
-            private int _period;
-            private TimerCallback _callback;
-            private object _state;
 
-            internal Timer(TimerCallback callback, object state, int dueTime, int period)
-            {
-                _callback = callback;
-                _state = state;
-                _period = period;
-                Schedule(dueTime);
-            }
+        private static Thread? s_pollingThread;
+        // Used for sleeping for a certain amount of time while allowing the thread to be woken up
+        private static AutoResetEvent? s_pollingThreadSleepEvent;
 
-            private void Schedule(int dueTime)
-            {
-                Task.Delay(dueTime, Token).ContinueWith(OnTimer, null, CancellationToken.None, TaskContinuationOptions.ExecuteSynchronously | TaskContinuationOptions.OnlyOnRanToCompletion, TaskScheduler.Default);
-            }
+        private static List<CounterGroup>? s_counterGroupEnabledList;
 
-            private void OnTimer(Task t, object s)
+        private static void PollForValues()
+        {
+            AutoResetEvent? sleepEvent = null;
+            while (true)
             {
-                Schedule(_period);
-                _callback(_state);
+                int sleepDurationInMilliseconds = Int32.MaxValue;
+                lock (s_counterGroupLock)
+                {
+                    sleepEvent = s_pollingThreadSleepEvent;
+                    foreach (CounterGroup counterGroup in s_counterGroupEnabledList!)
+                    {
+                        DateTime now = DateTime.UtcNow;
+                        if (counterGroup._nextPollingTimeStamp < now + new TimeSpan(0, 0, 0, 0, 1))
+                        {
+                            counterGroup.OnTimer();
+                        }
+
+                        int millisecondsTillNextPoll = (int)((counterGroup._nextPollingTimeStamp - now).TotalMilliseconds);
+                        millisecondsTillNextPoll = Math.Max(1, millisecondsTillNextPoll);
+                        sleepDurationInMilliseconds = Math.Min(sleepDurationInMilliseconds, millisecondsTillNextPoll);
+                    }
+                }
+                if (sleepDurationInMilliseconds == Int32.MaxValue)
+                {
+                    sleepDurationInMilliseconds = -1; // WaitOne uses -1 to mean infinite
+                }
+                sleepEvent?.WaitOne(sleepDurationInMilliseconds);
             }
-
-            public new void Dispose() { base.Cancel(); }
         }
-#endif
-        #endregion // PCL timer hack
+
 
         #endregion // Timer Processing
 
index 3d2f222..02b1158 100644 (file)
@@ -116,12 +116,14 @@ namespace System.Diagnostics.Tracing
 
         internal void ResetStatistics()
         {
-            Debug.Assert(Monitor.IsEntered(this));
-            _count = 0;
-            _sum = 0;
-            _sumSquared = 0;
-            _min = double.PositiveInfinity;
-            _max = double.NegativeInfinity;
+            lock(this)
+            {
+                _count = 0;
+                _sum = 0;
+                _sumSquared = 0;
+                _min = double.PositiveInfinity;
+                _max = double.NegativeInfinity;
+            }
         }
 
         #endregion // Statistics Calculation
index fffd1c8..de1a0f0 100644 (file)
@@ -76,6 +76,7 @@ namespace BasicEventSourceTests
                             if (payload.Key.Equals("Mean"))
                             {
                                 int mean = Int32.Parse(payload.Value.ToString());
+                                Console.WriteLine("Adding " + mean + " to known list of means");
                                 means.Add(mean);
                             }
                             else if (payload.Key.Equals("DisplayName"))
@@ -95,17 +96,12 @@ namespace BasicEventSourceTests
             public bool validateMean()
             {
                 // we expect to see 1 because we wrote only 1s
+                // we *might* also see 0 because there is a period of time we didn't write stuff and got callback
                 if (!means.Contains(1)) 
                 {
+                    Console.WriteLine("Mean doesn't have a 1");
                     return false;
                 }
-
-                // we also expect to see 0 because there is a period of time we didn't write stuff and got callback
-                if (!means.Contains(0)) 
-                {
-                    return false;
-                }
-
                 return true;
             }
         }
@@ -159,4 +155,4 @@ namespace BasicEventSourceTests
             }
         }
     }
-}
\ No newline at end of file
+}