From 852155639650f38af07bd1a20704e05e7a4b4ae9 Mon Sep 17 00:00:00 2001 From: John Salem Date: Mon, 7 Jun 2021 13:48:41 -0700 Subject: [PATCH 1/5] Fix #53564 * default internal state to DateTime.MaxValue * re-check IsEnabled after not holding lock * add test for setting interval to 0 --- .../Diagnostics/Tracing/CounterGroup.cs | 15 ++- src/tests/tracing/eventcounter/gh53564.cs | 99 +++++++++++++++++++ src/tests/tracing/eventcounter/gh53564.csproj | 17 ++++ 3 files changed, 126 insertions(+), 5 deletions(-) create mode 100644 src/tests/tracing/eventcounter/gh53564.cs create mode 100644 src/tests/tracing/eventcounter/gh53564.csproj diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs index effc21fd61ad57..63f412155727f0 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs @@ -116,7 +116,7 @@ internal static CounterGroup GetCounterGroup(EventSource eventSource) private DateTime _timeStampSinceCollectionStarted; private int _pollingIntervalInMilliseconds; - private DateTime _nextPollingTimeStamp; + private DateTime _nextPollingTimeStamp = DateTime.MaxValue; private void EnableTimer(float pollingIntervalInSeconds) { @@ -124,6 +124,7 @@ private void EnableTimer(float pollingIntervalInSeconds) if (pollingIntervalInSeconds <= 0) { _pollingIntervalInMilliseconds = 0; + _nextPollingTimeStamp = DateTime.MaxValue; } else if (_pollingIntervalInMilliseconds == 0 || pollingIntervalInSeconds * 1000 < _pollingIntervalInMilliseconds) { @@ -173,6 +174,7 @@ private void EnableTimer(float pollingIntervalInSeconds) private void DisableTimer() { _pollingIntervalInMilliseconds = 0; + _nextPollingTimeStamp = DateTime.MaxValue; s_counterGroupEnabledList?.Remove(this); } @@ -235,11 +237,14 @@ private void OnTimer() lock (s_counterGroupLock) { - _timeStampSinceCollectionStarted = now; - do + if (_eventSource.IsEnabled()) { - _nextPollingTimeStamp += new TimeSpan(0, 0, 0, 0, _pollingIntervalInMilliseconds); - } while (_nextPollingTimeStamp <= now); + _timeStampSinceCollectionStarted = now; + do + { + _nextPollingTimeStamp += new TimeSpan(0, 0, 0, 0, _pollingIntervalInMilliseconds); + } while (_nextPollingTimeStamp <= now); + } } } } diff --git a/src/tests/tracing/eventcounter/gh53564.cs b/src/tests/tracing/eventcounter/gh53564.cs new file mode 100644 index 00000000000000..148c4856fec1b1 --- /dev/null +++ b/src/tests/tracing/eventcounter/gh53564.cs @@ -0,0 +1,99 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#if USE_MDT_EVENTSOURCE +using Microsoft.Diagnostics.Tracing; +#else +using System.Diagnostics.Tracing; +#endif +using System; +using System.Collections.Generic; +using System.Threading; +using System.Threading.Tasks; +using System.Diagnostics; + +namespace gh53564Tests +{ + public class RuntimeCounterListener : EventListener + { + public RuntimeCounterListener(){} + + private DateTime? setToZeroTimestamp = null; + private DateTime? mostRecentTimestamp = null; + public ManualResetEvent ReadyToVerify { get; } = new ManualResetEvent(initialState: false); + + protected override void OnEventSourceCreated(EventSource source) + { + if (source.Name.Equals("System.Runtime")) + { + Dictionary refreshInterval = new Dictionary(); + + Console.WriteLine($"[{DateTime.Now:hh:mm:ss.fff}] Setting interval to 1"); + // first set interval to 1 seconds + refreshInterval["EventCounterIntervalSec"] = "1"; + EnableEvents(source, EventLevel.Informational, (EventKeywords)(-1), refreshInterval); + + // wait a moment to get some events + Thread.Sleep(TimeSpan.FromSeconds(3)); + + // then set interval to 0 + Console.WriteLine($"[{DateTime.Now:hh:mm:ss.fff}] Setting interval to 0"); + refreshInterval["EventCounterIntervalSec"] = "0"; + EnableEvents(source, EventLevel.Informational, (EventKeywords)(-1), refreshInterval); + setToZeroTimestamp = DateTime.Now + TimeSpan.FromSeconds(1); // Stash timestamp 1 second after setting to 0 + + // then attempt to set interval back to 1 + Thread.Sleep(TimeSpan.FromSeconds(3)); + Console.WriteLine($"[{DateTime.Now:hh:mm:ss.fff}] Setting interval to 1"); + refreshInterval["EventCounterIntervalSec"] = "1"; + EnableEvents(source, EventLevel.Informational, (EventKeywords)(-1), refreshInterval); + Thread.Sleep(TimeSpan.FromSeconds(3)); + Console.WriteLine($"[{DateTime.Now:hh:mm:ss.fff}] Setting ReadyToVerify"); + ReadyToVerify.Set(); + } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + mostRecentTimestamp = eventData.TimeStamp; + } + + public bool Verify() + { + if (!ReadyToVerify.WaitOne(0)) + return false; + + return (setToZeroTimestamp is null || mostRecentTimestamp is null) ? false : setToZeroTimestamp < mostRecentTimestamp; + } + } + + public partial class TestRuntimeEventCounter + { + public static int Main(string[] args) + { + // Create an EventListener. + using (RuntimeCounterListener myListener = new RuntimeCounterListener()) + { + if (myListener.ReadyToVerify.WaitOne(TimeSpan.FromSeconds(15))) + { + Console.WriteLine($"[{DateTime.Now:hh:mm:ss.fff}] Ready to verify"); + if (myListener.Verify()) + { + Console.WriteLine("Test passed"); + return 100; + } + else + { + Console.WriteLine($"Test Failed - did not see one or more of the expected runtime counters."); + return 1; + } + } + else + { + Console.WriteLine("Test Failed - timed out waiting for reset"); + return 1; + } + } + } + } +} diff --git a/src/tests/tracing/eventcounter/gh53564.csproj b/src/tests/tracing/eventcounter/gh53564.csproj new file mode 100644 index 00000000000000..5c2b810ee7c115 --- /dev/null +++ b/src/tests/tracing/eventcounter/gh53564.csproj @@ -0,0 +1,17 @@ + + + Exe + BuildAndRun + true + 0 + true + + true + + true + + + + + + From c99e7fe8b23a13085e5501ba15cce45f7ad098b5 Mon Sep 17 00:00:00 2001 From: John Salem Date: Tue, 8 Jun 2021 11:50:45 -0700 Subject: [PATCH 2/5] simplify fix to just a for loop --- .../src/System/Diagnostics/Tracing/CounterGroup.cs | 12 ++++-------- 1 file changed, 4 insertions(+), 8 deletions(-) diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs index 63f412155727f0..e9b07e718c744d 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs @@ -116,7 +116,7 @@ internal static CounterGroup GetCounterGroup(EventSource eventSource) private DateTime _timeStampSinceCollectionStarted; private int _pollingIntervalInMilliseconds; - private DateTime _nextPollingTimeStamp = DateTime.MaxValue; + private DateTime _nextPollingTimeStamp; private void EnableTimer(float pollingIntervalInSeconds) { @@ -124,7 +124,6 @@ private void EnableTimer(float pollingIntervalInSeconds) if (pollingIntervalInSeconds <= 0) { _pollingIntervalInMilliseconds = 0; - _nextPollingTimeStamp = DateTime.MaxValue; } else if (_pollingIntervalInMilliseconds == 0 || pollingIntervalInSeconds * 1000 < _pollingIntervalInMilliseconds) { @@ -237,13 +236,10 @@ private void OnTimer() lock (s_counterGroupLock) { - if (_eventSource.IsEnabled()) + _timeStampSinceCollectionStarted = now; + for (int i = 0; i < 1000 && _nextPollingTimeStamp < now; i++) { - _timeStampSinceCollectionStarted = now; - do - { - _nextPollingTimeStamp += new TimeSpan(0, 0, 0, 0, _pollingIntervalInMilliseconds); - } while (_nextPollingTimeStamp <= now); + _nextPollingTimeStamp += new TimeSpan(0, 0, 0, 0, _pollingIntervalInMilliseconds); } } } From 0dc4b2b6807c11367da19a7797f0ad89ffe2c624 Mon Sep 17 00:00:00 2001 From: John Salem Date: Tue, 8 Jun 2021 11:52:04 -0700 Subject: [PATCH 3/5] remove one more line --- .../src/System/Diagnostics/Tracing/CounterGroup.cs | 1 - 1 file changed, 1 deletion(-) diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs index e9b07e718c744d..e811add9186df8 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs @@ -173,7 +173,6 @@ private void EnableTimer(float pollingIntervalInSeconds) private void DisableTimer() { _pollingIntervalInMilliseconds = 0; - _nextPollingTimeStamp = DateTime.MaxValue; s_counterGroupEnabledList?.Remove(this); } From 196421a10ad13ac5642da1e3f482d285883a9fd7 Mon Sep 17 00:00:00 2001 From: John Salem Date: Wed, 9 Jun 2021 15:04:57 -0700 Subject: [PATCH 4/5] Remove loop --- .../src/System/Diagnostics/Tracing/CounterGroup.cs | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs index e811add9186df8..dada54e1e9bc66 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs @@ -236,10 +236,9 @@ private void OnTimer() lock (s_counterGroupLock) { _timeStampSinceCollectionStarted = now; - for (int i = 0; i < 1000 && _nextPollingTimeStamp < now; i++) - { - _nextPollingTimeStamp += new TimeSpan(0, 0, 0, 0, _pollingIntervalInMilliseconds); - } + TimeSpan delta = now - _nextPollingTimeStamp; + if (delta > TimeSpan.Zero && _pollingIntervalInMilliseconds > 0) + _nextPollingTimeStamp += TimeSpan.FromMilliseconds(_pollingIntervalInMilliseconds * Math.Ceiling(delta.TotalMilliseconds / _pollingIntervalInMilliseconds)); } } } From 97b1193305a909c173361775a7a93c87f296000e Mon Sep 17 00:00:00 2001 From: John Salem Date: Fri, 11 Jun 2021 18:13:44 -0700 Subject: [PATCH 5/5] Update test to match #54081 --- src/tests/tracing/eventcounter/gh53564.cs | 30 +++++++++++++++-------- 1 file changed, 20 insertions(+), 10 deletions(-) diff --git a/src/tests/tracing/eventcounter/gh53564.cs b/src/tests/tracing/eventcounter/gh53564.cs index 148c4856fec1b1..4b2b5907abbe0c 100644 --- a/src/tests/tracing/eventcounter/gh53564.cs +++ b/src/tests/tracing/eventcounter/gh53564.cs @@ -20,6 +20,7 @@ public RuntimeCounterListener(){} private DateTime? setToZeroTimestamp = null; private DateTime? mostRecentTimestamp = null; + private ManualResetEvent setToZero = new ManualResetEvent(initialState: false); public ManualResetEvent ReadyToVerify { get; } = new ManualResetEvent(initialState: false); protected override void OnEventSourceCreated(EventSource source) @@ -28,7 +29,7 @@ protected override void OnEventSourceCreated(EventSource source) { Dictionary refreshInterval = new Dictionary(); - Console.WriteLine($"[{DateTime.Now:hh:mm:ss.fff}] Setting interval to 1"); + Console.WriteLine($"[{DateTime.UtcNow:hh:mm:ss.fff}] OnEventSourceCreated :: Setting interval to 1"); // first set interval to 1 seconds refreshInterval["EventCounterIntervalSec"] = "1"; EnableEvents(source, EventLevel.Informational, (EventKeywords)(-1), refreshInterval); @@ -37,25 +38,31 @@ protected override void OnEventSourceCreated(EventSource source) Thread.Sleep(TimeSpan.FromSeconds(3)); // then set interval to 0 - Console.WriteLine($"[{DateTime.Now:hh:mm:ss.fff}] Setting interval to 0"); + Console.WriteLine($"[{DateTime.UtcNow:hh:mm:ss.fff}] OnEventSourceCreated :: Setting interval to 0"); refreshInterval["EventCounterIntervalSec"] = "0"; EnableEvents(source, EventLevel.Informational, (EventKeywords)(-1), refreshInterval); - setToZeroTimestamp = DateTime.Now + TimeSpan.FromSeconds(1); // Stash timestamp 1 second after setting to 0 + setToZeroTimestamp = DateTime.UtcNow + TimeSpan.FromSeconds(1); // Stash timestamp 1 second after setting to 0 + setToZero.Set(); // then attempt to set interval back to 1 Thread.Sleep(TimeSpan.FromSeconds(3)); - Console.WriteLine($"[{DateTime.Now:hh:mm:ss.fff}] Setting interval to 1"); + Console.WriteLine($"[{DateTime.UtcNow:hh:mm:ss.fff}] OnEventSourceCreated :: Setting interval to 1"); refreshInterval["EventCounterIntervalSec"] = "1"; EnableEvents(source, EventLevel.Informational, (EventKeywords)(-1), refreshInterval); - Thread.Sleep(TimeSpan.FromSeconds(3)); - Console.WriteLine($"[{DateTime.Now:hh:mm:ss.fff}] Setting ReadyToVerify"); - ReadyToVerify.Set(); } } protected override void OnEventWritten(EventWrittenEventArgs eventData) { - mostRecentTimestamp = eventData.TimeStamp; + if (!ReadyToVerify.WaitOne(0)) + { + mostRecentTimestamp = eventData.TimeStamp; + if (setToZero.WaitOne(0) && mostRecentTimestamp > setToZeroTimestamp) + { + Console.WriteLine($"[{DateTime.UtcNow:hh:mm:ss.fff}] OnEventWritten :: Setting ReadyToVerify"); + ReadyToVerify.Set(); + } + } } public bool Verify() @@ -63,6 +70,10 @@ public bool Verify() if (!ReadyToVerify.WaitOne(0)) return false; + Console.WriteLine($"[{DateTime.UtcNow:hh:mm:ss.fff}] Verify :: Verifying"); + Console.WriteLine($"[{DateTime.UtcNow:hh:mm:ss.fff}] setToZeroTimestamp = {setToZeroTimestamp?.ToString("hh:mm:ss.fff") ?? "NULL"}"); + Console.WriteLine($"[{DateTime.UtcNow:hh:mm:ss.fff}] mostRecentTimestamp = {mostRecentTimestamp?.ToString("hh:mm:ss.fff") ?? "NULL"}"); + return (setToZeroTimestamp is null || mostRecentTimestamp is null) ? false : setToZeroTimestamp < mostRecentTimestamp; } } @@ -74,9 +85,8 @@ public static int Main(string[] args) // Create an EventListener. using (RuntimeCounterListener myListener = new RuntimeCounterListener()) { - if (myListener.ReadyToVerify.WaitOne(TimeSpan.FromSeconds(15))) + if (myListener.ReadyToVerify.WaitOne(TimeSpan.FromSeconds(30))) { - Console.WriteLine($"[{DateTime.Now:hh:mm:ss.fff}] Ready to verify"); if (myListener.Verify()) { Console.WriteLine("Test passed");