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 }