From fe139940e7211be4f631a3a35ede45e350a1d7b9 Mon Sep 17 00:00:00 2001 From: Sung Yoon Whang Date: Wed, 7 Aug 2019 09:14:38 -0700 Subject: [PATCH] Make counters use dedicated thread instead of timer (#25864) (#25978) * 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 --- .../System/Diagnostics/Tracing/CounterGroup.cs | 148 +++++++++++---------- .../System/Diagnostics/Tracing/EventCounter.cs | 14 +- tests/src/tracing/eventcounter/eventcounter.cs | 12 +- 3 files changed, 93 insertions(+), 81 deletions(-) diff --git a/src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/CounterGroup.cs b/src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/CounterGroup.cs index 2b4dd1b..d8b285b 100644 --- a/src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/CounterGroup.cs +++ b/src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/CounterGroup.cs @@ -21,6 +21,7 @@ namespace System.Diagnostics.Tracing { private readonly EventSource _eventSource; private readonly List _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[]? 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[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(); + 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? 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 diff --git a/src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/EventCounter.cs b/src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/EventCounter.cs index 3d2f222..02b1158 100644 --- a/src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/EventCounter.cs +++ b/src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/EventCounter.cs @@ -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 diff --git a/tests/src/tracing/eventcounter/eventcounter.cs b/tests/src/tracing/eventcounter/eventcounter.cs index fffd1c8..de1a0f0 100644 --- a/tests/src/tracing/eventcounter/eventcounter.cs +++ b/tests/src/tracing/eventcounter/eventcounter.cs @@ -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 +} -- 2.7.4