Timing.Children is not threadsafe.

[yellis]

See related thread on the community site.

Want to make interactions with Timing.Children threadsafe.

[yellis]

@dixon do you have any problems with the locking solution offered in the thread on the community site? We could also potentially use ConcurrentBag instead of List as the type for Timing.Children, but I would rather not rewrite all of the code related to Children to use ConcurrentBag (or even if rewriting is not needed, might introduce regression and performance issues).

[dixon]

While the proposed fix will prevent certain exceptions, it will also introduce bugs, due to interaction between a new Timing and the profiling session's Head.

After adding the per-Timing locking as suggested in the original thread, here's some sample output (from (this commit) that illustrates the problem:

C:\Code\github\MiniProfiler\dotnet\Sample.Console\bin\Debug>Sample.Console.exe
DIXON-DESKTOP at 2/20/2014 12:00:25 AM
 Locking = ms
> outer = 57.8ms
>> step 0 = 7.1ms
>> step 3 = 7.3ms
>> step 4 = 7.1ms
>> step 2 = 7.1ms
>> step 1 = 7.3ms
>>> sub-step3 = 5ms
>>>> sub-step1 = 5ms
>>>>> sub-step2 = 4.7ms
>>>> sub-step4 = 4.8ms
>>>>> sub-step0 = 4.7ms

C:\Code\github\MiniProfiler\dotnet\Sample.Console\bin\Debug>Sample.Console.exe
DIXON-DESKTOP at 2/20/2014 12:00:26 AM
 Locking = ms
> outer = 86.2ms
>> step 0 = 57.3ms
>> step 3 = 57.3ms
>> step 4 = 57.3ms
>> step 1 = 57.3ms
>> step 2 = 57.3ms
>>> sub-step3 = 18.9ms
>>> sub-step4 = 18.9ms
>>> sub-step0 = 18.9ms
>>> sub-step1 = 18.9ms
>>> sub-step2 = 18.8ms

C:\Code\github\MiniProfiler\dotnet\Sample.Console\bin\Debug>Sample.Console.exe
DIXON-DESKTOP at 2/20/2014 12:00:26 AM
 Locking = ms
> outer = 8.8ms
>> step 2 = 5.6ms
>> step 3 = 5.6ms
>> step 4 = 5.6ms
>> step 0 = 5.7ms
>> step 1 = 5.6ms
>>> sub-step4 = 3.4ms
>>> sub-step3 = 3.4ms
>>>> sub-step0 = 3.8ms
>>>>> sub-step2 = 3.4ms
>>> sub-step1 = 3.4ms

C:\Code\github\MiniProfiler\dotnet\Sample.Console\bin\Debug>Sample.Console.exe
DIXON-DESKTOP at 2/20/2014 12:00:27 AM
 Locking = ms
> outer = 94ms
>> step 0 = 77.2ms
>>> step 4 = 77.3ms
>>>> sub-step1 = 45ms
>>>> sub-step0 = 44.9ms
>>>> sub-step3 = 45ms
>>>> sub-step2 = 44.9ms
>>>> sub-step4 = 44.9ms
>> step 3 = 77.5ms
>> step 2 = 77.3ms
>> step 1 = 77.5ms

@mjibson and I had talked about making multi-threaded profiling more explicit - each task/thread must get their own Timing step, which the thread will use in any of its Step calls, creating a per-thread Timing tree. We obviously didn't get farther than initial brain-storming :)

[alexsku]

I think I've run into the Children concurrency issue using MiniProfiler V4. This is a PR illustrating the issue (based on V4 MVC sample): alexsku#4

In my case I have multiple async tasks executing and awaited by the calling thread all together (using Task.WhenAll). Each task is using await with ConfigureAwait(false) (a typical pattern for a service layer in a web application). Because of the ConfigureAwait(false) the continuations for the tasks will be executed in parallel causing the concurrency issue.

I think using lock is a good way to solve the concurrency issue. Here is my PR that is addressing it (among other things): #147 (the PR is for V4 of MiniProfiler).

I think lock's performance is pretty good when there is low contention (which i think is the case with MiniProfiler usages, otherwise this issue would be very high priority). Here is a small test where lock is measured against other synchronization primitives: alexsku#5 when the lock is not contended.

Btw, I think V4 fixes the issue described by @dixon above by using AsyncLocal

[NickCraver]

Fixed by 9ec58fa