[3.0 port] Fix first value of counter payload being skewed (#25799)
authorSung Yoon Whang <suwhang@microsoft.com>
Tue, 23 Jul 2019 04:32:01 +0000 (21:32 -0700)
committerGitHub <noreply@github.com>
Tue, 23 Jul 2019 04:32:01 +0000 (21:32 -0700)
* Fix issue 25709

* rename

* Fix regression test

* cleanup

* Code review feedback

* set maxincrement to 3

* test fix

src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/CounterGroup.cs
src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/EventCounter.cs
src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/IncrementingEventCounter.cs
src/System.Private.CoreLib/shared/System/Diagnostics/Tracing/IncrementingPollingCounter.cs
tests/src/tracing/eventcounter/regression-25709.cs [new file with mode: 0644]
tests/src/tracing/eventcounter/regression-25709.csproj [new file with mode: 0644]

index 0879f9d..2b4dd1b 100644 (file)
@@ -145,6 +145,7 @@ namespace System.Diagnostics.Tracing
                 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;
@@ -165,8 +166,28 @@ namespace System.Diagnostics.Tracing
                         ExecutionContext.RestoreFlow();
                 }
             }
-            // Always fire the timer event (so you see everything up to this time).  
-            OnTimer(null);
+        }
+
+        private void ResetCounters()
+        {
+            lock (this) // Lock the CounterGroup
+            {
+                foreach (var counter in _counters)
+                {
+                    if (counter is IncrementingEventCounter ieCounter)
+                    {
+                        ieCounter.UpdateMetric();
+                    }
+                    else if (counter is IncrementingPollingCounter ipCounter)
+                    {
+                        ipCounter.UpdateMetric();
+                    }
+                    else if (counter is EventCounter eCounter)
+                    {
+                        eCounter.ResetStatistics();
+                    }
+                }
+            }
         }
 
         private void OnTimer(object? state)
index 5a6509b..3d2f222 100644 (file)
@@ -114,7 +114,7 @@ namespace System.Diagnostics.Tracing
             }
         }
 
-        private void ResetStatistics()
+        internal void ResetStatistics()
         {
             Debug.Assert(Monitor.IsEntered(this));
             _count = 0;
index 3bfdb7b..11af024 100644 (file)
@@ -73,6 +73,15 @@ namespace System.Diagnostics.Tracing
                 EventSource.Write("EventCounters", new EventSourceOptions() { Level = EventLevel.LogAlways }, new IncrementingEventCounterPayloadType(payload));
             }
         }
+
+        // Updates the value.
+        internal void UpdateMetric()
+        {
+            lock (this)
+            {
+                _prevIncrement = _increment;
+            }
+        }
     }
 
 
index 5c52460..2e470bf 100644 (file)
@@ -52,12 +52,13 @@ namespace System.Diagnostics.Tracing
         /// <summary>
         /// Calls "_totalValueProvider" to enqueue the counter value to the queue. 
         /// </summary>
-        private void UpdateMetric()
+        internal void UpdateMetric()
         {
             try
             {
                 lock (this)
                 {
+                    _prevIncrement = _increment;
                     _increment = _totalValueProvider();
                 }
             }
@@ -82,7 +83,6 @@ namespace System.Diagnostics.Tracing
                 payload.Metadata = GetMetadataString();
                 payload.Increment = _increment - _prevIncrement;
                 payload.DisplayUnits = DisplayUnits ?? "";
-                _prevIncrement = _increment;
                 EventSource.Write("EventCounters", new EventSourceOptions() { Level = EventLevel.LogAlways }, new IncrementingPollingCounterPayloadType(payload));
             }
         }
diff --git a/tests/src/tracing/eventcounter/regression-25709.cs b/tests/src/tracing/eventcounter/regression-25709.cs
new file mode 100644 (file)
index 0000000..b18565b
--- /dev/null
@@ -0,0 +1,117 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+// See the LICENSE file in the project root for more information.
+
+#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 EventCounterRegressionTests
+{
+
+    public class SimpleEventListener : EventListener
+    {        
+        private readonly EventLevel _level = EventLevel.Verbose;
+
+        public int MaxIncrement { get; private set; } = 0;
+
+        public SimpleEventListener()
+        {
+        }
+
+
+        protected override void OnEventSourceCreated(EventSource source)
+        {
+            if (source.Name.Equals("System.Runtime"))
+            {
+                Dictionary<string, string> refreshInterval = new Dictionary<string, string>();
+                refreshInterval.Add("EventCounterIntervalSec", "1");
+                EnableEvents(source, _level, (EventKeywords)(-1), refreshInterval);
+            }
+        }
+
+        protected override void OnEventWritten(EventWrittenEventArgs eventData)
+        {
+            int increment = 0;
+            bool isExceptionCounter = false;
+
+            for (int i = 0; i < eventData.Payload.Count; i++)
+            {
+                IDictionary<string, object> eventPayload = eventData.Payload[i] as IDictionary<string, object>;
+                if (eventPayload != null)
+                {
+                    foreach (KeyValuePair<string, object> payload in eventPayload)
+                    {
+                        if (payload.Key.Equals("Name") && payload.Value.ToString().Equals("exception-count"))
+                            isExceptionCounter = true;
+                        if (payload.Key.Equals("Increment"))
+                        {
+                            increment = Int32.Parse(payload.Value.ToString());
+                        }
+                    }
+                    if (isExceptionCounter)
+                    {
+                        if (MaxIncrement < increment)
+                        {
+                            MaxIncrement = increment;
+                        }
+                    }
+                }
+            }
+        }
+    }
+
+    public partial class TestEventCounter
+    {
+
+        public static void ThrowExceptionTask()
+        {
+            // This will throw an exception every 1000 ms
+            while (true)
+            {
+                Thread.Sleep(1000);
+                try
+                {
+                    Debug.WriteLine("Exception thrown at " + DateTime.UtcNow.ToString("mm.ss.ffffff"));
+                    throw new Exception("an exception");
+                }
+                catch
+                {}
+            }
+        }
+
+        public static int Main(string[] args)
+        {
+            Task exceptionTask = Task.Run(ThrowExceptionTask);
+            Thread.Sleep(5000);
+
+            // Create an EventListener.
+            using (SimpleEventListener myListener = new SimpleEventListener())
+            {
+                Thread.Sleep(5000);
+
+                // The number below is supposed to be 2 at maximum, but in debug builds, the calls to 
+                // EventSource.Write() takes a lot longer than we thought(~1s), and the reflection in 
+                // workingset counter also adds a huge amount of time (> 1s), which makes the test fail in 
+                // debug CIs. Setting the check to 4 to compensate for these.
+                if (myListener.MaxIncrement > 4)
+                {
+                    Console.WriteLine($"Test Failed - Saw more than 3 exceptions / sec {myListener.MaxIncrement}");
+                    return 1;
+                }
+                else
+                {
+                    Console.WriteLine("Test passed");
+                    return 100;
+                }
+            }
+        }
+    }
+}
\ No newline at end of file
diff --git a/tests/src/tracing/eventcounter/regression-25709.csproj b/tests/src/tracing/eventcounter/regression-25709.csproj
new file mode 100644 (file)
index 0000000..c39d10e
--- /dev/null
@@ -0,0 +1,30 @@
+<?xml version="1.0" encoding="utf-8"?>
+<Project ToolsVersion="12.0" DefaultTargets="Build" xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
+  <Import Project="$([MSBuild]::GetDirectoryNameOfFileAbove($(MSBuildThisFileDirectory), dir.props))\dir.props" />
+  <PropertyGroup>
+    <Configuration Condition=" '$(Configuration)' == '' ">Debug</Configuration>
+    <Platform Condition=" '$(Platform)' == '' ">AnyCPU</Platform>
+    <SchemaVersion>2.0</SchemaVersion>
+    <ProjectGuid>{8E3244CB-407F-4142-BAAB-E7A55901A5FA}</ProjectGuid>
+    <OutputType>Exe</OutputType>
+    <ProjectTypeGuids>{786C830F-07A1-408B-BD7F-6EE04809D6DB};{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}</ProjectTypeGuids>
+    <SolutionDir Condition="$(SolutionDir) == '' Or $(SolutionDir) == '*Undefined*'">..\..\</SolutionDir>
+    <CLRTestKind>BuildAndRun</CLRTestKind>
+    <DefineConstants>$(DefineConstants);STATIC</DefineConstants>
+    <AllowUnsafeBlocks>true</AllowUnsafeBlocks>
+    <CLRTestPriority>0</CLRTestPriority>
+    <GCStressIncompatible>true</GCStressIncompatible>
+    <!-- This test has a secondary thread with an infinite loop -->
+    <UnloadabilityIncompatible>true</UnloadabilityIncompatible>
+  </PropertyGroup>
+  <!-- Default configurations to help VS understand the configurations -->
+  <PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'Debug|x64'">
+  </PropertyGroup>
+  <PropertyGroup Condition="'$(Configuration)|$(Platform)' == 'Release|x64'">
+  </PropertyGroup>
+  <ItemGroup>
+    <Compile Include="regression-25709.cs" />
+    <ProjectReference Include="../common/common.csproj" />
+  </ItemGroup>
+  <Import Project="$([MSBuild]::GetDirectoryNameOfFileAbove($(MSBuildThisFileDirectory), dir.targets))\dir.targets" />
+</Project>