MiniProfiler / dotnet

A simple but effective mini-profiler for ASP.NET (and Core) websites
https://miniprofiler.com/dotnet/
MIT License
2.88k stars 594 forks source link

Profiler cannot reliably be stopped in async methods #623

Open Bouke opened 1 year ago

Bouke commented 1 year ago

I'm using DefaultProfilerProvider, which uses an AsyncLocal to store the current profiler. When I stop+discard the profiler from an async method for the first time, Stop(true) == true and MiniProfiler.Current == null. However on a subsequent call of this async method MiniProfiler.Current is no longer null. Stop(true) will return false as Stopwatch.IsRunning returns false. However due to MiniProfiler.Current not being null, timings will still be collected. I believe the issue is that the logical call context (as used by AsyncLocal) has copy-on-write behaviour. So when the profiler is stopped, the profiler instance's stopwatch will be stopped and trigger a copy of the logical call context. So now MiniProfiler.Current will only be null for this async method (the current logical context).

Due to the copy-on-write behaviour StopAsync(true) will not be able to set MiniProfiler.Current to null, as it'll only affect the copied local call context, not the call context of the continuation (the caller).

I currently employ the following workaround (you can observe MiniProfiler.Current != null after awaiting this method):

async Task MyMethod()
{
    MiniProfiler.Current.Stop(true);
    if (MiniProfiler.Current != null)
        MiniProfiler.DefaultOptions.ProfilerProvider.Stopped(MiniProfiler.Current, true);
    Debug.Assert(MiniProfiler.Current == null);
    ...
}
NickCraver commented 1 year ago

It's true that this is a limitation of AsyncLocal<T>, we'll collect some excess timings if you abort down in a child method of the overall. The .Stop(bool) wasn't really envisioned for use that way, more so some condition at the top of a method/route/entry point to not profile it at all. e.g. you know this admin route in an application is going to issue 4,000 queries and you don't want to profile it every time.

We could check .IsActive in .Step() for example, but that adds overhead to every profile for a very narrow use case. What I'd recommend if this is important for your case is to perhaps do that in your own extension method. For example:

[MethodImpl(MethodImplOptions.AggressiveInlining)]
public static Timing StepIfActive(this MiniProfiler profiler, string name) => profiler?.IsActive == true ? profiler.StepImpl(name) : default;