Skip to content

Concurrency issue when there is no lock #4

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
alexsku wants to merge 5 commits into
base: v4
Choose a base branch
from
Open

Concurrency issue when there is no lock #4

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
e0861f5
concurrency problem
alexsku Dec 23, 2016
77bae41
concurrency issue reproduced
alexsku Dec 23, 2016
b7664a9
removed test that is not needed
alexsku Dec 24, 2016
b16c7bd
minor cleanup
alexsku Dec 24, 2016
e976125
made the service call more realistic (removed miniprofiler from the p…
alexsku Jan 3, 2017
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
31 changes: 31 additions & 0 deletions samples/Samples.Mvc5/Controllers/HomeController.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
{
Expand Down Expand Up @@ -131,6 +133,35 @@ public ActionResult About()
/// <returns>The <see cref="ActionResult"/>.</returns>
public ActionResult ResultsAuthorization() => View();

public async Task<ActionResult> CallAsync()
Copy link
Owner Author

@alexsku alexsku Dec 24, 2016 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this action simulates a typical async action that invokes an async service method (FooAsync). The service method might access some data sources (like redis, database etc) and measure the performance of individual calls.

The action also invokes multiple service calls and waits for completion all of them. This is also quite legitimate pattern, which parallelizes execution of the service methods to increase the action's response time

{
var profiler = MiniProfiler.Current;
var service = new FooService();
using (profiler.Step("action"))
{
var tasks = new List<Task>();
for (int i = 0; i < 10; i++)
{
tasks.Add(service.FooAsync());
}
await Task.WhenAll(tasks);
return Content("All good");
}
}

class FooService
{
public async Task FooAsync()
Copy link
Owner Author

@alexsku alexsku Jan 3, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the method simulates a typical service method. Following typical pattern the service implementation is using ConfigureAwait(false).

{
var profiler = MiniProfiler.Current;
Copy link
Owner Author

@alexsku alexsku Jan 3, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

MVC sample is using WebRequestProfilerProvider which relies on HttpContext to carry the miniprofiler instance. Since this is a continuation after ConfigureAwait(false) the synchronization context together with the HttpContext will be removed here. So if I don't use an explicit reference to profiler here the step would not be recorded at all.

DefaultProfilerProvider (and its possible future merge with WebRequestProfilerProvider) would fix this issue by using AsyncLocal to carry the mini profiler instance.

However the execution of the continuation is not synchronized with continuations from other 9 calls to FooAsync that are made from the same CallAsync call (and they all share the same instance of MiniProfiler). As a result Timing.AddChild might be invoked concurrently.

This is the exact problem that i'm trying to prevent.

await Task.Delay(10).ConfigureAwait(false);
Copy link
Owner Author

@alexsku alexsku Jan 4, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

continuations of this await will execute in parallel since await is using ConfigureAwait(false) and the calling method is using Task.WhenAll instead of awaiting individual executions.

using (profiler.Step("foo async"))
Copy link
Owner Author

@alexsku alexsku Dec 24, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

MVC sample is using WebRequestProfilerProvider which relies on HttpContext to carry the miniprofiler instance. Since this is a continuation after ConfigureAwait(false) the synchronization context together with the HttpContext will be removed here. So if I don't use an explicit reference to profiler here the step would not be recorded at all.

DefaultProfilerProvider (and its possible future merge with WebRequestProfilerProvider) would fix this issue by using AsyncLocal to carry the mini profiler instance.

However the execution of the continuation is not synchronized with continuations from other 9 calls to FooAsync that are made from the same CallAsync call (and they all share the same instance of MiniProfiler). As a result Timing.AddChild might be invoked concurrently.

This is the exact problem that i'm trying to prevent.

{
await Task.Delay(10).ConfigureAwait(false);
}
}
}

/// <summary>
/// fetch the route hits.
/// </summary>
Expand Down
1 change: 1 addition & 0 deletions samples/Samples.Mvc5/Views/Home/Index.cshtml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -65,6 +65,7 @@
<li><a href="/Home/MassiveNesting2">Massive Nesting 2</a></li>
<li><a href="/Home/ParameterizedSqlWithEnums">Parameterized SQL with Enums</a></li>
<li><a href="/Home/MinSaveMs">Test Min Save Ms</a></li>
<li><a href="/Home/CallAsync">Async call + Concurrency</a></li>
</ul>
</div>
</div>
Expand Down
48 changes: 39 additions & 9 deletions src/MiniProfiler.Shared/Timing.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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;

/// <summary>
/// Initialises a new instance of the <see cref="Timing"/> class.
/// Obsolete - used for serialization.
Expand Down Expand Up @@ -253,19 +258,44 @@ public void Stop()
/// </remarks>
public void AddChild(Timing timing)
{
if (Children == null)
if (Interlocked.Increment(ref _threadsAccessing) > 1)
throw new Exception("Concurrent access");
Copy link
Owner Author

@alexsku alexsku Dec 24, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this throws with almost every request to CallAsync


Task.Delay(10).Wait();
Copy link
Owner Author

@alexsku alexsku Dec 24, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this is an artificial delay added to increase the chance of concurrency

Copy link
Owner Author

@alexsku alexsku Dec 24, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thread.Sleep I guess is not available in .netcore (or perhaps i need to install a separate package).


try
{
if (Children == null)
Children = new List<Timing>();

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");

try
{
Children?.Remove(timing);
}
finally
{
Interlocked.Decrement(ref _threadsAccessing);
}
}

/// <summary>
/// Adds <paramref name="customTiming"/> to this <see cref="Timing"/> step's dictionary of
Expand Down