From e0861f5d0bc37362b6407ab0f7c543b42d3891bc Mon Sep 17 00:00:00 2001 From: Alex Skurikhin Date: Fri, 23 Dec 2016 14:00:25 -0800 Subject: [PATCH 1/5] concurrency problem --- .../Controllers/HomeController.cs | 30 ++++++++++++ samples/Samples.Mvc5/Views/Home/Index.cshtml | 1 + src/MiniProfiler.Shared/Timing.cs | 47 +++++++++++++++---- 3 files changed, 69 insertions(+), 9 deletions(-) diff --git a/samples/Samples.Mvc5/Controllers/HomeController.cs b/samples/Samples.Mvc5/Controllers/HomeController.cs index a176a204a..bb6a45224 100644 --- a/samples/Samples.Mvc5/Controllers/HomeController.cs +++ b/samples/Samples.Mvc5/Controllers/HomeController.cs @@ -10,6 +10,8 @@ using Samples.Mvc5.EfModelFirst; using Samples.Mvc5.EFCodeFirst; using Samples.Mvc5.Helpers; +using System.Threading.Tasks; +using System.Collections.Generic; namespace Samples.Mvc5.Controllers { @@ -131,6 +133,34 @@ public ActionResult About() /// The . public ActionResult ResultsAuthorization() => View(); + public async Task CallAsync() + { + var profiler = MiniProfiler.Current; + var service = new FooService(); + using (profiler.Step("action")) + { + var head = profiler.Head; + var tasks = new List(); + for (int i = 0; i < 10; i++) + { + tasks.Add(service.FooAsync(head)); + } + await Task.WhenAll(tasks); + return Content("All good"); + } + } + + class FooService + { + public async Task FooAsync(Timing head) + { + using (new Timing(MiniProfiler.Current, head, "foo async", minSaveMs: 100000)) + { + await Task.Delay(100).ConfigureAwait(false); + } + } + } + /// /// fetch the route hits. /// diff --git a/samples/Samples.Mvc5/Views/Home/Index.cshtml b/samples/Samples.Mvc5/Views/Home/Index.cshtml index 3eb0a9b5e..b40fea6f6 100644 --- a/samples/Samples.Mvc5/Views/Home/Index.cshtml +++ b/samples/Samples.Mvc5/Views/Home/Index.cshtml @@ -65,6 +65,7 @@
  • Massive Nesting 2
  • Parameterized SQL with Enums
  • Test Min Save Ms
    • +
  • Async call + Concurrency
    • diff --git a/src/MiniProfiler.Shared/Timing.cs b/src/MiniProfiler.Shared/Timing.cs index e3aa9839f..64d8c6a48 100644 --- a/src/MiniProfiler.Shared/Timing.cs +++ b/src/MiniProfiler.Shared/Timing.cs @@ -3,6 +3,8 @@ using System.Linq; using System.Runtime.Serialization; using StackExchange.Profiling.Helpers; +using System.Threading; +using System.Threading.Tasks; #if NET45 using System.Web.Script.Serialization; #endif @@ -22,6 +24,9 @@ public class Timing : IDisposable private readonly decimal? _minSaveMs; private readonly bool _includeChildrenWithMinSave; + // used for concurrent access detection + private int _threadsAccessing = 0; + /// /// Initialises a new instance of the class. /// Obsolete - used for serialization. @@ -253,19 +258,43 @@ public void Stop() /// public void AddChild(Timing timing) { - if (Children == null) + if (Interlocked.Increment(ref _threadsAccessing) > 1) + throw new Exception("Concurrent access"); + + try + { + if (Children == null) Children = new List(); - Children.Add(timing); - if(timing.Profiler == null) - timing.Profiler = Profiler; - timing.ParentTiming = this; - timing.ParentTimingId = Id; - if (Profiler != null) - timing.MiniProfilerId = Profiler.Id; + Children.Add(timing); + if(timing.Profiler == null) + timing.Profiler = Profiler; + timing.ParentTiming = this; + timing.ParentTimingId = Id; + if (Profiler != null) + timing.MiniProfilerId = Profiler.Id; + } + finally + { + Interlocked.Decrement(ref _threadsAccessing); + } } - internal void RemoveChild(Timing timing) => Children?.Remove(timing); + internal void RemoveChild(Timing timing) + { + if (Interlocked.Increment(ref _threadsAccessing) > 1) + throw new Exception("Concurrent access"); + + Task.Delay(10).Wait(); + try + { + Children?.Remove(timing); + } + finally + { + Interlocked.Decrement(ref _threadsAccessing); + } + } /// /// Adds to this step's dictionary of From 77bae41aea75398c0ab44043d9e292a29303c92b Mon Sep 17 00:00:00 2001 From: Alex Skurikhin Date: Fri, 23 Dec 2016 15:51:05 -0800 Subject: [PATCH 2/5] concurrency issue reproduced --- .../Controllers/HomeController.cs | 9 +++--- src/MiniProfiler.Shared/Timing.cs | 3 +- tests/MiniProfiler.Tests/MiniProfilerTest.cs | 32 +++++++++++++++++++ 3 files changed, 39 insertions(+), 5 deletions(-) diff --git a/samples/Samples.Mvc5/Controllers/HomeController.cs b/samples/Samples.Mvc5/Controllers/HomeController.cs index bb6a45224..d145c6e29 100644 --- a/samples/Samples.Mvc5/Controllers/HomeController.cs +++ b/samples/Samples.Mvc5/Controllers/HomeController.cs @@ -143,7 +143,7 @@ public async Task CallAsync() var tasks = new List(); for (int i = 0; i < 10; i++) { - tasks.Add(service.FooAsync(head)); + tasks.Add(service.FooAsync(profiler)); } await Task.WhenAll(tasks); return Content("All good"); @@ -152,11 +152,12 @@ public async Task CallAsync() class FooService { - public async Task FooAsync(Timing head) + public async Task FooAsync(MiniProfiler profiler) { - using (new Timing(MiniProfiler.Current, head, "foo async", minSaveMs: 100000)) + await Task.Delay(10).ConfigureAwait(false); + using (profiler.Step("foo async")) { - await Task.Delay(100).ConfigureAwait(false); + await Task.Delay(10).ConfigureAwait(false); } } } diff --git a/src/MiniProfiler.Shared/Timing.cs b/src/MiniProfiler.Shared/Timing.cs index 64d8c6a48..732c4a91a 100644 --- a/src/MiniProfiler.Shared/Timing.cs +++ b/src/MiniProfiler.Shared/Timing.cs @@ -261,6 +261,8 @@ public void AddChild(Timing timing) if (Interlocked.Increment(ref _threadsAccessing) > 1) throw new Exception("Concurrent access"); + Task.Delay(10).Wait(); + try { if (Children == null) @@ -285,7 +287,6 @@ internal void RemoveChild(Timing timing) if (Interlocked.Increment(ref _threadsAccessing) > 1) throw new Exception("Concurrent access"); - Task.Delay(10).Wait(); try { Children?.Remove(timing); diff --git a/tests/MiniProfiler.Tests/MiniProfilerTest.cs b/tests/MiniProfiler.Tests/MiniProfilerTest.cs index adf57841d..b3446b27a 100644 --- a/tests/MiniProfiler.Tests/MiniProfilerTest.cs +++ b/tests/MiniProfiler.Tests/MiniProfilerTest.cs @@ -1,4 +1,6 @@ using System; +using System.Collections.Generic; +using System.Threading.Tasks; using Xunit; namespace StackExchange.Profiling.Tests @@ -102,6 +104,36 @@ public void StepIf_IncludeChildren() } } + [Fact] + public async Task ConcurrencyTest() + { + MiniProfiler.Settings.ProfilerProvider = new DefaultProfilerProvider(); + + MiniProfiler.Settings.ProfilerProvider.Start("test"); + var profiler = MiniProfiler.Current; + var service = new FooService(); + using (profiler.Step("action")) + { + var tasks = new List(); + for (int i = 0; i < 100; i++) + { + tasks.Add(service.FooAsync()); + } + await Task.WhenAll(tasks); + } + } + + class FooService + { + public async Task FooAsync() + { + using (MiniProfiler.Current.Step("foo async")) + { + await Task.Delay(10).ConfigureAwait(false); + } + } + } + [Fact] public void CustomTimingIf_Basic() { From b7664a926bf97a875df2bd6b3752f4f318ee82b7 Mon Sep 17 00:00:00 2001 From: Alex Skurikhin Date: Fri, 23 Dec 2016 16:43:38 -0800 Subject: [PATCH 3/5] removed test that is not needed --- tests/MiniProfiler.Tests/MiniProfilerTest.cs | 32 -------------------- 1 file changed, 32 deletions(-) diff --git a/tests/MiniProfiler.Tests/MiniProfilerTest.cs b/tests/MiniProfiler.Tests/MiniProfilerTest.cs index b3446b27a..adf57841d 100644 --- a/tests/MiniProfiler.Tests/MiniProfilerTest.cs +++ b/tests/MiniProfiler.Tests/MiniProfilerTest.cs @@ -1,6 +1,4 @@ using System; -using System.Collections.Generic; -using System.Threading.Tasks; using Xunit; namespace StackExchange.Profiling.Tests @@ -104,36 +102,6 @@ public void StepIf_IncludeChildren() } } - [Fact] - public async Task ConcurrencyTest() - { - MiniProfiler.Settings.ProfilerProvider = new DefaultProfilerProvider(); - - MiniProfiler.Settings.ProfilerProvider.Start("test"); - var profiler = MiniProfiler.Current; - var service = new FooService(); - using (profiler.Step("action")) - { - var tasks = new List(); - for (int i = 0; i < 100; i++) - { - tasks.Add(service.FooAsync()); - } - await Task.WhenAll(tasks); - } - } - - class FooService - { - public async Task FooAsync() - { - using (MiniProfiler.Current.Step("foo async")) - { - await Task.Delay(10).ConfigureAwait(false); - } - } - } - [Fact] public void CustomTimingIf_Basic() { From b16c7bda004c86bd7b67bfc41354e27702a1f4f4 Mon Sep 17 00:00:00 2001 From: Alex Skurikhin Date: Fri, 23 Dec 2016 16:46:10 -0800 Subject: [PATCH 4/5] minor cleanup --- samples/Samples.Mvc5/Controllers/HomeController.cs | 1 - 1 file changed, 1 deletion(-) diff --git a/samples/Samples.Mvc5/Controllers/HomeController.cs b/samples/Samples.Mvc5/Controllers/HomeController.cs index d145c6e29..fcd18930e 100644 --- a/samples/Samples.Mvc5/Controllers/HomeController.cs +++ b/samples/Samples.Mvc5/Controllers/HomeController.cs @@ -139,7 +139,6 @@ public async Task CallAsync() var service = new FooService(); using (profiler.Step("action")) { - var head = profiler.Head; var tasks = new List(); for (int i = 0; i < 10; i++) { From e976125c2793588ddd61224bd5451cef0d7efbf2 Mon Sep 17 00:00:00 2001 From: Alex Skurikhin Date: Tue, 3 Jan 2017 15:34:19 -0800 Subject: [PATCH 5/5] made the service call more realistic (removed miniprofiler from the parameters) --- samples/Samples.Mvc5/Controllers/HomeController.cs | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/samples/Samples.Mvc5/Controllers/HomeController.cs b/samples/Samples.Mvc5/Controllers/HomeController.cs index fcd18930e..7fababefa 100644 --- a/samples/Samples.Mvc5/Controllers/HomeController.cs +++ b/samples/Samples.Mvc5/Controllers/HomeController.cs @@ -142,7 +142,7 @@ public async Task CallAsync() var tasks = new List(); for (int i = 0; i < 10; i++) { - tasks.Add(service.FooAsync(profiler)); + tasks.Add(service.FooAsync()); } await Task.WhenAll(tasks); return Content("All good"); @@ -151,8 +151,9 @@ public async Task CallAsync() class FooService { - public async Task FooAsync(MiniProfiler profiler) + public async Task FooAsync() { + var profiler = MiniProfiler.Current; await Task.Delay(10).ConfigureAwait(false); using (profiler.Step("foo async")) {