Skip to content
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.

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

Profiler cannot reliably be stopped in async methods #623

Open
Bouke opened this issue Oct 6, 2022 · 1 comment
Open

Profiler cannot reliably be stopped in async methods #623

Bouke opened this issue Oct 6, 2022 · 1 comment

Comments

@Bouke
Copy link
Contributor

Bouke commented Oct 6, 2022

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
Copy link
Member

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;

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants