From 90b16414206285e799e8ba3a01122dc00efae366 Mon Sep 17 00:00:00 2001 From: Vance Morrison Date: Mon, 24 Jul 2017 14:44:50 -0700 Subject: [PATCH] Fixed races in EventCounters. Preped to add Dispose() method There were a number of races in EventCounters. Did an audit and fixed these. Also prepped to add a Dispose() method so that you can make counters for transient objects (e.g. files) Have actually made it public yet, pending API review. Also turned on and beefed up the testing. Fixed tests. --- .../System.Diagnostics.DiagnosticSource.sln | 13 +- .../src/System.Diagnostics.Tracing.csproj | 5 +- .../Diagnostics/Tracing/EventCounter.cs | 213 ++++++++++-------- .../Harness/EventTestHarness.cs | 1 + .../BasicEventSourceTest/Harness/Listeners.cs | 8 +- .../BasicEventSourceTest/TestEventCounter.cs | 152 ++++++++++--- 6 files changed, 257 insertions(+), 135 deletions(-) diff --git a/src/System.Diagnostics.DiagnosticSource/System.Diagnostics.DiagnosticSource.sln b/src/System.Diagnostics.DiagnosticSource/System.Diagnostics.DiagnosticSource.sln index 4307c7ae9087..1eb8ec92c865 100644 --- a/src/System.Diagnostics.DiagnosticSource/System.Diagnostics.DiagnosticSource.sln +++ b/src/System.Diagnostics.DiagnosticSource/System.Diagnostics.DiagnosticSource.sln @@ -1,6 +1,6 @@ Microsoft Visual Studio Solution File, Format Version 12.00 -# Visual Studio 14 -VisualStudioVersion = 14.0.25420.1 +# Visual Studio 15 +VisualStudioVersion = 15.0.26430.12 MinimumVisualStudioVersion = 10.0.40219.1 Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "System.Diagnostics.DiagnosticSource.Tests", "tests\System.Diagnostics.DiagnosticSource.Tests.csproj", "{A7922FA3-306A-41B9-B8DC-CC4DBE685A85}" ProjectSection(ProjectDependencies) = postProject @@ -20,6 +20,15 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "src", "src", "{E107E9C1-E89 EndProject Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "ref", "ref", "{2E666815-2EDB-464B-9DF6-380BF4789AD4}" EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "Solution Items", "Solution Items", "{33F18BCF-3CA9-4AF8-B78A-9A9042D60092}" + ProjectSection(SolutionItems) = preProject + src\ActivityUserGuide.md = src\ActivityUserGuide.md + src\DiagnosticSourceUsersGuide.md = src\DiagnosticSourceUsersGuide.md + src\FlatRequestId.md = src\FlatRequestId.md + src\HierarchicalRequestId.md = src\HierarchicalRequestId.md + src\HttpCorrelationProtocol.md = src\HttpCorrelationProtocol.md + EndProjectSection +EndProject Global GlobalSection(SolutionConfigurationPlatforms) = preSolution Debug|Any CPU = Debug|Any CPU diff --git a/src/System.Diagnostics.Tracing/src/System.Diagnostics.Tracing.csproj b/src/System.Diagnostics.Tracing/src/System.Diagnostics.Tracing.csproj index 4f8307d8d9d8..52c972d0282a 100644 --- a/src/System.Diagnostics.Tracing/src/System.Diagnostics.Tracing.csproj +++ b/src/System.Diagnostics.Tracing/src/System.Diagnostics.Tracing.csproj @@ -8,7 +8,7 @@ true - $(DefineConstants);SUPPORTS_EVENTCOMMANDEXECUTED + $(DefineConstants);NO_EVENTCOMMANDEXECUTED_SUPPORT @@ -30,6 +30,7 @@ + - \ No newline at end of file + diff --git a/src/System.Diagnostics.Tracing/src/System/Diagnostics/Tracing/EventCounter.cs b/src/System.Diagnostics.Tracing/src/System/Diagnostics/Tracing/EventCounter.cs index d29ab9772e49..760713770e20 100644 --- a/src/System.Diagnostics.Tracing/src/System/Diagnostics/Tracing/EventCounter.cs +++ b/src/System.Diagnostics.Tracing/src/System/Diagnostics/Tracing/EventCounter.cs @@ -40,11 +40,13 @@ public EventCounter(string name, EventSource eventSource) InitializeBuffer(); _name = name; - EventCounterGroup.AddEventCounter(eventSource, this); + _group = EventCounterGroup.GetEventCounterGroup(eventSource); + _group.Add(this); } /// - /// Writes the metric. + /// Writes 'value' to the stream of values tracked by the counter. This updates the sum and other statistics that will + /// be logged on the next timer interval. /// /// The value. public void WriteMetric(float value) @@ -52,9 +54,24 @@ public void WriteMetric(float value) Enqueue(value); } +#if EventCounterDispose + // TODO Go through API review and expose this. + /// + /// Removes the counter from set that the EventSource will report on. + /// + public void Dispose() + { + _group.Remove(this); + } +#endif + public override string ToString() + { + return "EventCounter '" + _name + "' Count " + _count + " Mean " + (((double)_sum) / _count).ToString("n3"); + } #region private implementation private readonly string _name; + private readonly EventCounterGroup _group; #region Buffer Management @@ -62,9 +79,12 @@ public void WriteMetric(float value) private const int BufferedSize = 10; private const float UnusedBufferSlotValue = float.NegativeInfinity; private const int UnsetIndex = -1; - private volatile float[] _bufferedValues; + private volatile float[] _bufferedValues; private volatile int _bufferedValuesIndex; + // arbitrarily we use _bufferfValues as the lock object. + private object MyLock { get { return _bufferedValues; } } + private void InitializeBuffer() { _bufferedValues = new float[BufferedSize]; @@ -86,10 +106,8 @@ private void Enqueue(float value) { // It is possible that two threads both think the buffer is full, but only one get to actually flush it, the other // will eventually enter this code path and potentially calling Flushing on a buffer that is not full, and that's okay too. - lock (_bufferedValues) - { + lock (MyLock) // Lock the counter Flush(); - } i = 0; } @@ -104,6 +122,7 @@ private void Enqueue(float value) private void Flush() { + Debug.Assert(Monitor.IsEntered(MyLock)); for (int i = 0; i < _bufferedValues.Length; i++) { var value = Interlocked.Exchange(ref _bufferedValues[i], UnusedBufferSlotValue); @@ -129,6 +148,7 @@ private void Flush() private void OnMetricWritten(float value) { + Debug.Assert(Monitor.IsEntered(MyLock)); _sum += value; _sumSquared += value * value; if (_count == 0 || value > _max) @@ -146,7 +166,7 @@ private void OnMetricWritten(float value) internal EventCounterPayload GetEventCounterPayload() { - lock (_bufferedValues) + lock (MyLock) // Lock the counter { Flush(); EventCounterPayload result = new EventCounterPayload(); @@ -163,6 +183,7 @@ internal EventCounterPayload GetEventCounterPayload() private void ResetStatistics() { + Debug.Assert(Monitor.IsEntered(MyLock)); _count = 0; _sum = 0; _sumSquared = 0; @@ -222,31 +243,49 @@ private IEnumerable> ForEnumeration #endregion // Implementation of the IEnumerable interface } - internal class EventCounterGroup : IDisposable + internal class EventCounterGroup { private readonly EventSource _eventSource; - private readonly int _eventSourceIndex; private readonly List _eventCounters; - internal EventCounterGroup(EventSource eventSource, int eventSourceIndex) + internal EventCounterGroup(EventSource eventSource) { _eventSource = eventSource; - _eventSourceIndex = eventSourceIndex; _eventCounters = new List(); RegisterCommandCallback(); } - private void Add(EventCounter eventCounter) + internal void Add(EventCounter eventCounter) + { + lock (this) // Lock the EventCounterGroup + _eventCounters.Add(eventCounter); + } + + internal void Remove(EventCounter eventCounter) { - _eventCounters.Add(eventCounter); + lock (this) // Lock the EventCounterGroup + _eventCounters.Remove(eventCounter); } #region EventSource Command Processing private void RegisterCommandCallback() { -#if SUPPORTS_EVENTCOMMANDEXECUTED + // Old destktop runtimes don't have this +#if !NO_EVENTCOMMANDEXECUTED_SUPPORT _eventSource.EventCommandExecuted += OnEventSourceCommand; +#else + // We could not build against the API that had the EventCommandExecuted but maybe it is there are runtime. + // use reflection to try to get it. + var method = typeof(EventSource).GetMethod("add_EventCommandExecuted"); + if (method != null) + method.Invoke(_eventSource, new object[] { (EventHandler)OnEventSourceCommand }); + else + { + var msg = "EventCounterError: Old Runtime that does not support EventSource.EventCommandExecuted. EventCounters not Supported"; + _eventSource.Write(msg); + Debug.WriteLine(msg); + } #endif } @@ -258,7 +297,13 @@ private void OnEventSourceCommand(object sender, EventCommandEventArgs e) float value; if (e.Arguments.TryGetValue("EventCounterIntervalSec", out valueStr) && float.TryParse(valueStr, out value)) { - EnableTimer(value); + // Recursion through EventSource callbacks possible. When we enable the timer + // we synchonously issue a EventSource.Write event, which in turn can call back + // to user code (in an EventListener) while holding this lock. This is dangerous + // because it mean this code might inadvertantly participate in a lock loop. + // The scenario seems very unlikely so we ignore that problem for now. + lock (this) // Lock the EventCounterGroup + EnableTimer(value); } } } @@ -267,42 +312,42 @@ private void OnEventSourceCommand(object sender, EventCommandEventArgs e) #region Global EventCounterGroup Array management - private static EventCounterGroup[] s_eventCounterGroups; - - internal static void AddEventCounter(EventSource eventSource, EventCounter eventCounter) - { - int eventSourceIndex = EventListenerHelper.EventSourceIndex(eventSource); - - EventCounterGroup.EnsureEventSourceIndexAvailable(eventSourceIndex); - EventCounterGroup eventCounterGroup = GetEventCounterGroup(eventSource); - eventCounterGroup.Add(eventCounter); - } + // We need eventCounters to 'attach' themselves to a particular EventSource. + // this table provides the mapping from EventSource -> EventCounterGroup + // which represents this 'attached' information. + private static WeakReference[] s_eventCounterGroups; + private static readonly object s_eventCounterGroupsLock = new object(); private static void EnsureEventSourceIndexAvailable(int eventSourceIndex) { + Debug.Assert(Monitor.IsEntered(s_eventCounterGroupsLock)); if (EventCounterGroup.s_eventCounterGroups == null) { - EventCounterGroup.s_eventCounterGroups = new EventCounterGroup[eventSourceIndex + 1]; + EventCounterGroup.s_eventCounterGroups = new WeakReference[eventSourceIndex + 1]; } else if (eventSourceIndex >= EventCounterGroup.s_eventCounterGroups.Length) { - EventCounterGroup[] newEventCounterGroups = new EventCounterGroup[eventSourceIndex + 1]; + WeakReference[] newEventCounterGroups = new WeakReference[eventSourceIndex + 1]; Array.Copy(EventCounterGroup.s_eventCounterGroups, 0, newEventCounterGroups, 0, EventCounterGroup.s_eventCounterGroups.Length); EventCounterGroup.s_eventCounterGroups = newEventCounterGroups; } } - private static EventCounterGroup GetEventCounterGroup(EventSource eventSource) + internal static EventCounterGroup GetEventCounterGroup(EventSource eventSource) { - int eventSourceIndex = EventListenerHelper.EventSourceIndex(eventSource); - EventCounterGroup result = EventCounterGroup.s_eventCounterGroups[eventSourceIndex]; - if (result == null) + lock (s_eventCounterGroupsLock) { - result = new EventCounterGroup(eventSource, eventSourceIndex); - EventCounterGroup.s_eventCounterGroups[eventSourceIndex] = result; + int eventSourceIndex = EventListenerHelper.EventSourceIndex(eventSource); + EnsureEventSourceIndexAvailable(eventSourceIndex); + WeakReference weakRef = EventCounterGroup.s_eventCounterGroups[eventSourceIndex]; + EventCounterGroup ret = null; + if (weakRef == null || !weakRef.TryGetTarget(out ret)) + { + ret = new EventCounterGroup(eventSource); + EventCounterGroup.s_eventCounterGroups[eventSourceIndex] = new WeakReference(ret); + } + return ret; } - - return result; } #endregion // Global EventCounterGroup Array management @@ -313,57 +358,67 @@ private static EventCounterGroup GetEventCounterGroup(EventSource eventSource) private int _pollingIntervalInMilliseconds; private Timer _pollingTimer; - private void EnableTimer(float pollingIntervalInSeconds) + private void DisposeTimer() { - if (pollingIntervalInSeconds == 0) + Debug.Assert(Monitor.IsEntered(this)); + if (_pollingTimer != null) { - if (_pollingTimer != null) - { - _pollingTimer.Dispose(); - _pollingTimer = null; - } + _pollingTimer.Dispose(); + _pollingTimer = null; + } + } + private void EnableTimer(float pollingIntervalInSeconds) + { + Debug.Assert(Monitor.IsEntered(this)); + if (pollingIntervalInSeconds <= 0) + { + DisposeTimer(); _pollingIntervalInMilliseconds = 0; } - else if (_pollingIntervalInMilliseconds == 0 || pollingIntervalInSeconds < _pollingIntervalInMilliseconds) + else if (_pollingIntervalInMilliseconds == 0 || pollingIntervalInSeconds * 1000 < _pollingIntervalInMilliseconds) { + Debug.WriteLine("Polling interval changed at " + DateTime.UtcNow.ToString("mm.ss.ffffff")); _pollingIntervalInMilliseconds = (int)(pollingIntervalInSeconds * 1000); - if (_pollingTimer != null) - { - _pollingTimer.Dispose(); - _pollingTimer = null; - } - - _timeStampSinceCollectionStarted = DateTime.Now; + DisposeTimer(); + _timeStampSinceCollectionStarted = DateTime.UtcNow; _pollingTimer = new Timer(OnTimer, null, _pollingIntervalInMilliseconds, _pollingIntervalInMilliseconds); } + // Always fire the timer event (so you see everything up to this time). + OnTimer(null); } private void OnTimer(object state) { - if (_eventSource.IsEnabled()) + Debug.WriteLine("Timer fired at " + DateTime.UtcNow.ToString("mm.ss.ffffff")); + lock (this) // Lock the EventCounterGroup { - DateTime now = DateTime.Now; - TimeSpan elapsed = now - _timeStampSinceCollectionStarted; - lock (_pollingTimer) + if (_eventSource.IsEnabled()) { + DateTime now = DateTime.UtcNow; + TimeSpan elapsed = now - _timeStampSinceCollectionStarted; + foreach (var eventCounter in _eventCounters) { EventCounterPayload payload = eventCounter.GetEventCounterPayload(); payload.IntervalSec = (float)elapsed.TotalSeconds; - _eventSource.Write("EventCounters", new EventSourceOptions() { Level = EventLevel.LogAlways }, new { Payload = payload }); + _eventSource.Write("EventCounters", new EventSourceOptions() { Level = EventLevel.LogAlways }, new PayloadType(payload)); } - - _timeStampSinceCollectionStarted = now; } + else + DisposeTimer(); } - else - { - _pollingTimer.Dispose(); - _pollingTimer = null; - EventCounterGroup.s_eventCounterGroups[_eventSourceIndex] = null; - } + } + + /// + /// This is the payload that is sent in the with EventSource.Write + /// + [EventData] + class PayloadType + { + public PayloadType(EventCounterPayload payload) { Payload = payload; } + public EventCounterPayload Payload { get; set; } } #region PCL timer hack @@ -403,41 +458,13 @@ private void OnTimer(Task t, object s) #endregion // Timer Processing - #region Implementation of the IDisposable interface - - private bool _disposed = false; - - public void Dispose() - { - Dispose(true); - } - - protected virtual void Dispose(bool disposing) - { - if (_disposed) - { - return; - } - - if (disposing) - { - if (_pollingTimer != null) - { - _pollingTimer.Dispose(); - _pollingTimer = null; - } - } - - _disposed = true; - } - - #endregion // Implementation of the IDisposable interface } // This class a work-around because .NET V4.6.2 did not make EventSourceIndex public (it was only protected) // We make this helper class to get around that protection. We want V4.6.3 to make this public at which // point this class is no longer needed and can be removed. - internal class EventListenerHelper : EventListener { + internal class EventListenerHelper : EventListener + { public new static int EventSourceIndex(EventSource eventSource) { return EventListener.EventSourceIndex(eventSource); } protected override void OnEventWritten(EventWrittenEventArgs eventData) { } // override abstact methods to keep compiler happy } diff --git a/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/Harness/EventTestHarness.cs b/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/Harness/EventTestHarness.cs index 07bc0c40c109..a59ea2901e2d 100644 --- a/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/Harness/EventTestHarness.cs +++ b/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/Harness/EventTestHarness.cs @@ -96,6 +96,7 @@ public static void RunTests(List tests, Listener listener, EventSource int testNumber = 0; foreach (var test in tests) { + Console.WriteLine("Starting Sub-Test {0}", test.Name); testHarnessEventSource.StartTest(test.Name, testNumber); test.EventGenerator(); testNumber++; diff --git a/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/Harness/Listeners.cs b/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/Harness/Listeners.cs index 4e39ffb21122..a1bdfffa7ece 100644 --- a/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/Harness/Listeners.cs +++ b/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/Harness/Listeners.cs @@ -42,7 +42,7 @@ public void WaitForEnable(EventSource logger) } } - internal void EnableTimer(EventSource eventSource, int pollingTime) + internal void EnableTimer(EventSource eventSource, double pollingTime) { FilteringOptions options = new FilteringOptions(); options.Args = new Dictionary(); @@ -86,7 +86,7 @@ public virtual string PayloadString(int propertyIndex, string propertyName) { return PayloadValue(propertyIndex, propertyName).ToString(); } - public abstract IEnumerable PayloadNames { get; } + public abstract IList PayloadNames { get; } #if DEBUG /// @@ -240,7 +240,7 @@ public override string PayloadString(int propertyIndex, string propertyName) return _data.PayloadString(propertyIndex); } public override int PayloadCount { get { return _data.PayloadNames.Length; } } - public override IEnumerable PayloadNames { get { return _data.PayloadNames; } } + public override IList PayloadNames { get { return _data.PayloadNames; } } #region private internal EtwEvent(TraceEvent data) { _data = data.Clone(); } @@ -391,7 +391,7 @@ internal class EventListenerEvent : Event public override string EventName { get { return _data.EventName; } } - public override IEnumerable PayloadNames { get { return _data.PayloadNames; } } + public override IList PayloadNames { get { return _data.PayloadNames; } } public override int PayloadCount { diff --git a/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestEventCounter.cs b/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestEventCounter.cs index fc9fb12492b9..489f4529fee0 100644 --- a/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestEventCounter.cs +++ b/src/System.Diagnostics.Tracing/tests/BasicEventSourceTest/TestEventCounter.cs @@ -3,7 +3,7 @@ // See the LICENSE file in the project root for more information. using System.Diagnostics.Tracing; -#if USE_ETW // TODO: Enable when TraceEvent is available on CoreCLR. GitHub issue #4864. +#if USE_ETW // TODO: Enable when TraceEvent is available on CoreCLR. GitHub issue https://github.com/dotnet/corefx/issues/4864 using Microsoft.Diagnostics.Tracing.Session; #endif using Xunit; @@ -18,7 +18,6 @@ namespace BasicEventSourceTests { -#if USE_ETW // TODO: Enable when TraceEvent is available on CoreCLR. GitHub issue #4864. public class TestEventCounter { private sealed class MyEventSource : EventSource @@ -52,14 +51,17 @@ public void Test_Write_Metric_EventListener() } } +#if USE_ETW [Fact] public void Test_Write_Metric_ETW() { + using (var listener = new EtwListener()) { Test_Write_Metric(listener); } } +#endif private void Test_Write_Metric(Listener listener) { @@ -72,84 +74,164 @@ private void Test_Write_Metric(Listener listener) tests.Add(new SubTest("Log 1 event", delegate () { - listener.EnableTimer(logger, 1); /* Poll every 1 s */ - logger.Request(37); - Thread.Sleep(1500); // Sleep for 1.5 seconds + listener.EnableTimer(logger, 0.2); /* Poll every 200 msec */ + logger.Request(5); + Sleep(280); // Sleep for 280 msec listener.EnableTimer(logger, 0); }, delegate (List evts) { - Assert.Equal(2, evts.Count); - ValidateSingleEventCounter(evts[0], "Request", 1, 37, 0, 37, 37); + // There will be two events (request and error) for time 0 and 2 more at 1 second and 2 more when we shut it off. + Assert.Equal(6, evts.Count); + ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[2], "Request", 1, 5, 0, 5, 5); + ValidateSingleEventCounter(evts[3], "Error", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[4], "Request", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[5], "Error", 0, 0, 0, 0, 0); })); /*************************************************************************/ tests.Add(new SubTest("Log 2 event in single period", delegate () { - listener.EnableTimer(logger, 1); /* Poll every 1 s */ - logger.Request(37); - logger.Request(25); - Thread.Sleep(1500); // Sleep for 1.5 seconds + listener.EnableTimer(logger, 0.2); /* Poll every .2 s */ + logger.Request(5); + logger.Request(10); + Sleep(280); // Sleep for .28 seconds listener.EnableTimer(logger, 0); }, delegate (List evts) { - Assert.Equal(2, evts.Count); - ValidateSingleEventCounter(evts[0], "Request", 2, 31, 6, 25, 37); + Assert.Equal(6, evts.Count); + ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[2], "Request", 2, 7.5f, 2.5f, 5, 10); + ValidateSingleEventCounter(evts[3], "Error", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[4], "Request", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[5], "Error", 0, 0, 0, 0, 0); })); /*************************************************************************/ tests.Add(new SubTest("Log 2 event in two periods", delegate () { - listener.EnableTimer(logger, 1); /* Poll every 1 s */ - logger.Request(37); - Thread.Sleep(1500); // Sleep for 1.5 seconds - logger.Request(25); - Thread.Sleep(1000); // Sleep for 1 seconds (at time = 2.5 second exactly two messages should be received) + listener.EnableTimer(logger, .2); /* Poll every .2 s */ + logger.Request(5); + Sleep(280); // Sleep for .28 seconds + logger.Request(10); + Sleep(220); // Sleep for .22 seconds (at time = .28 second exactly size messages should be received) listener.EnableTimer(logger, 0); }, delegate (List evts) { - Assert.Equal(4, evts.Count); - ValidateSingleEventCounter(evts[0], "Request", 1, 37, 0, 37, 37); - ValidateSingleEventCounter(evts[2], "Request", 1, 25, 0, 25, 25); + Assert.Equal(8, evts.Count); + ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[2], "Request", 1, 5, 0, 5, 5); + ValidateSingleEventCounter(evts[3], "Error", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[4], "Request", 1, 10, 0, 10, 10); + ValidateSingleEventCounter(evts[5], "Error", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[6], "Request", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[7], "Error", 0, 0, 0, 0, 0); })); /*************************************************************************/ tests.Add(new SubTest("Log 2 different events in a period", delegate () { - listener.EnableTimer(logger, 1); /* Poll every 1 s */ + listener.EnableTimer(logger, .2); /* Poll every .2 s */ logger.Request(25); logger.Error(); - Thread.Sleep(1500); // Sleep for 1.5 seconds + Sleep(280); // Sleep for .28 seconds listener.EnableTimer(logger, 0); }, delegate (List evts) { - Assert.Equal(2, evts.Count); - ValidateSingleEventCounter(evts[0], "Request", 1, 25, 0, 25, 25); - ValidateSingleEventCounter(evts[1], "Error", 1, 1, 0, 1, 1); + Assert.Equal(6, evts.Count); + ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[2], "Request", 1, 25, 0, 25, 25); + ValidateSingleEventCounter(evts[3], "Error", 1, 1, 0, 1, 1); + ValidateSingleEventCounter(evts[4], "Request", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[5], "Error", 0, 0, 0, 0, 0); + })); + + /*************************************************************************/ + tests.Add(new SubTest("Explicit polling ", + delegate () + { + listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */ + logger.Request(5); + logger.Request(10); + logger.Error(); + listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */ + logger.Request(8); + logger.Error(); + logger.Error(); + listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */ + }, + delegate (List evts) + { + Assert.Equal(6, evts.Count); + ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[2], "Request", 2, 7.5f, 2.5f, 5, 10); + ValidateSingleEventCounter(evts[3], "Error", 1, 1, 0, 1, 1); + ValidateSingleEventCounter(evts[4], "Request", 1, 8, 0, 8, 8); + ValidateSingleEventCounter(evts[5], "Error", 2, 1, 0, 1, 1); })); + + /*************************************************************************/ + // TODO expose Dispose() method and activate this test. +#if EventCounterDispose + tests.Add(new SubTest("EventCounter.Dispose()", + delegate () + { + // Creating and destroying + var myCounter = new EventCounter("counter for a transient object", logger); + myCounter.WriteMetric(10); + listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */ + myCounter.Dispose(); + listener.EnableTimer(logger, 0); /* Turn off (but also poll once) */ + }, + delegate (List evts) + { + Assert.Equal(5, evts.Count); + ValidateSingleEventCounter(evts[0], "Request", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[1], "Error", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[2], "counter for a transient object", 1, 10, 0, 10, 10); + ValidateSingleEventCounter(evts[3], "Request", 0, 0, 0, 0, 0); + ValidateSingleEventCounter(evts[4], "Error", 0, 0, 0, 0, 0); + })); +#endif /*************************************************************************/ EventTestHarness.RunTests(tests, listener, logger); } TestUtilities.CheckNoEventSourcesRunning("Stop"); } - private static void ValidateSingleEventCounter(Event evt, string counterName, int count, float sum, float sumSquared, float min, float max) + // THread.Sleep has proven unreliable, sometime sleeping much shorter than it should. + // This makes sure it at least sleeps 'msec' at a miniumum. + private static void Sleep(int minMSec) + { + var startTime = DateTime.UtcNow; + while ((DateTime.UtcNow - startTime).TotalMilliseconds < minMSec) + Thread.Sleep(1); + } + + private static void ValidateSingleEventCounter(Event evt, string counterName, int count, float mean, float standardDeviation, float min, float max) { object payload = ValidateEventHeaderAndGetPayload(evt); var payloadContent = payload as IDictionary; Assert.NotNull(payloadContent); - ValidateEventCounter(counterName, count, sum, sumSquared, min, max, payloadContent); + ValidateEventCounter(counterName, count, mean, standardDeviation, min, max, payloadContent); } private static object ValidateEventHeaderAndGetPayload(Event evt) { Assert.Equal("EventCounters", evt.EventName); - List payloadNames = evt.PayloadNames.ToList(); - Assert.Equal(1, payloadNames.Count); - Assert.Equal("Payload", payloadNames[0]); + Assert.Equal(1, evt.PayloadCount); + Assert.NotNull(evt.PayloadNames); + Assert.Equal(1, evt.PayloadNames.Count); + Assert.Equal("Payload", evt.PayloadNames[0]); object rawPayload = evt.PayloadValue(0, "Payload"); return rawPayload; } @@ -164,8 +246,11 @@ private static void ValidateEventCounter(string counterName, int count, float me Assert.Equal(7, payloadContentValue.Count); ValidatePayloadEntry("Name", counterName, payloadContentValue[0]); - ValidatePayloadEntry("Mean", mean, payloadContentValue[1]); - ValidatePayloadEntry("StandardDeviation", standardDeviation, payloadContentValue[2]); + if (count != 0) + { + ValidatePayloadEntry("Mean", mean, payloadContentValue[1]); + ValidatePayloadEntry("StandardDeviation", standardDeviation, payloadContentValue[2]); + } ValidatePayloadEntry("Count", count, payloadContentValue[3]); ValidatePayloadEntry("Min", min, payloadContentValue[4]); ValidatePayloadEntry("Max", max, payloadContentValue[5]); @@ -177,5 +262,4 @@ private static void ValidatePayloadEntry(string name, object value, KeyValuePair Assert.Equal(value, payloadEntry.Value); } } -#endif //USE_ETW }