Merge pull request #25 from chris-peterson/timers-api

Introduce API for timers

src/Spiffy.Monitoring/AutoTimer.cs

@@ -26,10 +26,21 @@ public void Resume()
             Start();
         }
 
+        public void StartOver()
+        {
+            _stopwatch.Reset();
+            Count = 0;
+            Start();
+        }
+
         void Start()
         {
+            if (_stopwatch.IsRunning)
+            {
+                return;
+            }
             Count++;
             _stopwatch.Start();
         }
     }
-}
+}

src/Spiffy.Monitoring/EventContext.cs

@@ -76,34 +76,20 @@ Assembly AssemblyFor<T>()
 
         readonly Dictionary<string, object> _values = new Dictionary<string, object>();
         readonly Dictionary<string, uint> _counts = new Dictionary<string, uint>();
-        readonly Dictionary<string, AutoTimer> _timers = new Dictionary<string, AutoTimer>();
 
         readonly object _valuesSyncObject = new object();
         readonly object _countsSyncObject = new object();
-        readonly object _timersSyncObject = new object();
 
         readonly DateTime _timestamp;
         readonly AutoTimer _timer = new AutoTimer();
 
         public IDisposable Time(string key)
         {
-            AutoTimer timer;
-            lock (_timersSyncObject)
-            {
-                if (_timers.ContainsKey(key))
-                {
-                    timer = _timers[key];
-                    timer.Resume();
-                }
-                else
-                {
-                    timer = _timers[key] = new AutoTimer();
-                }
-            }
-
-            return timer;
+            return Timers.Accumulate(key);
         }
 
+        public TimerCollection Timers { get; } = new TimerCollection();
+
         public void Count(string key)
         {
             lock (_countsSyncObject)
@@ -397,15 +383,12 @@ private IEnumerable<KeyValuePair<string, string>> GetTimeValues()
         {
             var times = new Dictionary<string, string>();
 
-            lock (_timersSyncObject)
+            foreach (var kvp in Timers.ShallowClone())
             {
-                foreach (var kvp in _timers)
+                times[$"{TimeElapsedKey}_{kvp.Key}"] = GetTimeFor(kvp.Value.ElapsedMilliseconds);
+                if (kvp.Value.Count > 1)
                 {
-                    times[$"TimeElapsed_{kvp.Key}"] = GetTimeFor(kvp.Value.ElapsedMilliseconds);
-                    if (kvp.Value.Count > 1)
-                    {
-                        times[$"Count_{kvp.Key}"] = kvp.Value.Count.ToString();
-                    }
+                    times[$"Count_{kvp.Key}"] = kvp.Value.Count.ToString();
                 }
             }
 

src/Spiffy.Monitoring/Spiffy.Monitoring.csproj

@@ -26,7 +26,7 @@ New features:
     <PackageProjectUrl>http://github.com/chris-peterson/spiffy</PackageProjectUrl>
     <PackageLicense>http://opensource.org/licenses/MIT</PackageLicense>
     <GeneratePackageOnBuild>True</GeneratePackageOnBuild>
-    <Version>6.0.5</Version>
+    <Version>6.0.6</Version>
     <RootNamespace>Spiffy.Monitoring</RootNamespace>
   </PropertyGroup>
   <ItemGroup>

src/Spiffy.Monitoring/TimerCollection.cs

@@ -0,0 +1,32 @@
+using System;
+using System.Collections.Concurrent;
+using System.Collections.Generic;
+using System.Linq;
+
+namespace Spiffy.Monitoring
+{
+    public class TimerCollection
+    {
+        readonly ConcurrentDictionary<string, AutoTimer> _timers = new ConcurrentDictionary<string, AutoTimer>();
+
+        public ITimedContext TimeOnce(string key)
+        {
+            var timer = GetTimer(key);
+            timer.StartOver();
+            return timer;
+        }
+
+        public ITimedContext Accumulate(string key)
+        {
+            var timer = GetTimer(key);
+            timer.Resume();
+            return timer;
+        }
+        internal Dictionary<string, AutoTimer> ShallowClone() => new Dictionary<string, AutoTimer>(_timers);
+
+        AutoTimer GetTimer(string key)
+        {
+            return _timers.GetOrAdd(key, _ => new AutoTimer());
+        }
+    }
+}

tests/UnitTests/ConcurrencyTests.cs

@@ -0,0 +1,47 @@
+using System.Collections.Generic;
+using System.Threading;
+using System.Threading.Tasks;
+using Spiffy.Monitoring;
+using Xunit;
+
+namespace UnitTests
+{
+    public class ConcurrencyTests
+    {
+        [Fact]
+        public void TestTimers()
+        {
+            var eventContext = new EventContext();
+            var tasks = new List<Task>();
+            const int numTasks = 100;
+            for (int i = 0; i < numTasks; i++)
+            {
+                var task = new Task(StaggeredMeasurements, new object [] {i, eventContext});
+                task.Start();
+                tasks.Add(task);
+            }
+
+            Task.WaitAll(tasks.ToArray());
+
+            LogEvent logEvent = null;
+            Configuration.Initialize(c => c.Providers.Add(GetType().Name, le => logEvent = le ));
+            eventContext.Dispose();
+
+            Assert.InRange(int.Parse(logEvent.Properties["Count_accum"]), numTasks*.65, numTasks*.99);
+            Assert.DoesNotContain("Count_once", logEvent.Properties);
+            Assert.True(double.Parse(logEvent.Properties["TimeElapsed_accum"]) > double.Parse(logEvent.Properties["TimeElapsed_once"]));
+        }
+
+        static void StaggeredMeasurements(object state)
+        {
+            var param = (object[]) state;
+            var delay = (int) param[0];
+            var eventContext = (EventContext) param[1];
+            using (eventContext.Timers.Accumulate("accum"))
+            using (eventContext.Timers.TimeOnce("once"))
+            {
+                Thread.Sleep(delay);
+            }
+        }
+    }
+}

tests/UnitTests/TimerCollectionTests.cs

@@ -0,0 +1,74 @@
+using System.Threading;
+using Spiffy.Monitoring;
+using Kekiri.Xunit;
+using Xunit;
+
+namespace UnitTests
+{
+    public class TimerCollectionTests : Scenarios
+    {
+        [Scenario]
+        public void TimeOnceScenario()
+        {
+            Given(A_code_block_timed_once);
+            When(Event_is_logged);
+            Then(The_time_elapsed_field_should_be_near, 10)
+                .And(There_should_be_no_count_field);
+        }
+
+        [Scenario]
+        public void AccumulateScenario()
+        {
+            Given(A_code_block_timed_multiple_times);
+            When(Event_is_logged);
+            Then(The_time_elapsed_field_should_be_near, 20)
+                .And(There_should_be_a_count_field);
+        }
+
+        void A_code_block_timed_once()
+        {
+            using (EventContext.Timers.TimeOnce(TimerKey))
+            {
+                Thread.Sleep(10);
+            }
+        }
+
+        void A_code_block_timed_multiple_times()
+        {
+            for (int i = 0; i < 2; i++)
+            {
+                using (EventContext.Timers.Accumulate(TimerKey))
+                {
+                    Thread.Sleep(10);
+                }
+            }
+        }
+
+        void Event_is_logged()
+        {
+            Configuration.Initialize(c => c.Providers.Add(GetType().Name, logEvent => LoggedEvent = logEvent));
+            EventContext.Dispose();
+        }
+
+        void The_time_elapsed_field_should_be_near(int target)
+        {
+            Assert.InRange(double.Parse(LoggedEvent.Properties[$"TimeElapsed_{TimerKey}"]), target-5, target+5);
+        }
+
+        void There_should_be_no_count_field()
+        {
+            Assert.DoesNotContain($"Count_{TimerKey}", LoggedEvent.Properties);
+        }
+
+        void There_should_be_a_count_field()
+        {
+            var keyName = $"Count_{TimerKey}";
+            Assert.Contains(keyName, LoggedEvent.Properties);
+            Assert.Equal(2, int.Parse(LoggedEvent.Properties[keyName]));
+        }
+
+        EventContext EventContext { get; } = new EventContext();
+        LogEvent LoggedEvent { get; set; }
+        const string TimerKey = "abc";
+    }
+}