Getting MVC mini-profiler timings into async tasks

Question

I have a long running SQL query inside a page that I've sped up by using an async task:

using System.Threading.Tasks;
...

var asyncTask = new Task<ResultClass>(
    () =>
    {
        using (var stepAsync = MiniProfiler.Current.Step("Async!"))
        {
            // exec long running SQL
        }
    });

asyncTask.Start();

// do lots of other slow stuff

ResultClass result;
using (var stepWait = MiniProfiler.Current.Step("Wait for Async"))
{
    result = asyncTask.Result;
}

(Note that this syntax will be a lot nicer once C# 5 comes out with async and await)

When using MVC mini profiler I get the timing for "Wait for Async", but I can't get the timing for the "Async!" step.

Is there any way to get those results (maybe just the SQL timings) into the trace for the completed page?

Update

I've found a way to get the profiler steps into the async method:

var asyncTask = new Task<ResultClass>(
    profiler =>
    {
        using (var step = (profiler as MiniProfiler).Step("Async!"))
        {
            // exec long running SQL
        }
    }, MiniProfiler.Current);

That almost works, in that the "Async!" step appears (somewhat randomly, depending on the execution, and with some times appearing as negative) but isn't really what I want. The SQL timings and statements are still lost, and in this case they're the most valuable information.

Ideally I'd like the "Wait for Async" step to be linked to the timings (rather than the start step). Is there some way that stepWait could be linked to the SQL profiler times for the result?

Any ideas?

Answer 1

What you can do is to create a new profiler and attach it to the web one.

var newProfiler = new MiniProfiler("- Other task (discard this time)", ProfileLevel.Verbose);
MiniProfiler.Current.AddProfilerResults(newProfiler);

var asyncTask = new Task(() =>
{
    using (newProfiler.Step("Async!"))
    {
        Thread.Sleep(500);
        using (newProfiler.Step("Async 2!"))
        {
            Thread.Sleep(1000);
        }
    }
});

asyncTask.Start();

The new profiler will have wrong times in its declaration but the steps are gonna be ok.

Answer 2

I've found a way to do this, by only keeping the SQL timings the main page steps still add up right:

var asyncTask = new Task<T>(
    profiler =>
    {
        var currentProfiler = (profiler as MiniProfiler);

        // Create a new profiler just for this step, we're only going to use the SQL timings
        MiniProfiler newProfiler = null;
        if (currentProfiler != null)
        {
            newProfiler = new MiniProfiler("Async step", currentProfiler.Level);
        }

        using(var con = /* create new DB connection */)
        using(var profiledCon = new ProfiledDbConnection(con, newProfiler))
        {
            // ### Do long running SQL stuff ###
            profiledCon.Query...
        }

        // If we have a profiler and a current step
        if (currentProfiler != null && currentProfiler.Head != null)
        {
            // Add the SQL timings to the step that's active when the SQL completes
            var currentStep = currentProfiler.Head;
            foreach (var sqlTiming in newProfiler.GetSqlTimings())
            {
                currentStep.AddSqlTiming(sqlTiming);
            }
        }

        return result;
    }, MiniProfiler.Current);

This results in the SQL timings for the long running query being associated with the current step when the SQL completes. Typically this is the step waiting for the async result, but will be an earlier step if the SQL completes before I have to wait for this.

I've wrapped this in a dapper-style QueryAsync<T> extension method (always buffered and not supporting transactions) though it could do with a lot of tidy up. When I have more time I'll look into adding a ProfiledTask<T> or similar that allows the profiled results to be copied from the completed task.

Update 1 (works in 1.9)

Following Sam's comment (see below) he's quite right: AddSqlTiming is not thread safe. So to get around that I've moved that to a synchronous continuation:

// explicit result class for the first task
class ProfiledResult<T>
{
    internal List<SqlTiming> SqlTimings { get; set; }
    internal T Result { get; set; }
}

var currentStep = MiniProfiler.Current.Head;

// Create a task that has its own profiler
var asyncTask = new Task<ProfiledResult<T>>(
    () =>
    {
        // Create a new profiler just for this step, we're only going to use the SQL timings
        var newProfiler = new MiniProfiler("Async step");
        var result = new ProfiledResult<T>();

        result.Result = // ### Do long running SQL stuff ###

        // Get the SQL timing results
        result.SqlTimings = newProfiler.GetSqlTimings();
        return result;
    });

// When the task finishes continue on the main thread to add the SQL timings
var asyncWaiter = asyncTask.ContinueWith<T>(
    t =>
    {
        // Get the wrapped result and add the timings from SQL to the current step
        var completedResult = t.Result;
        foreach (var sqlTiming in completedResult.SqlTimings)
        {
            currentStep.AddSqlTiming(sqlTiming);
        }

        return completedResult.Result;
    }, TaskContinuationOptions.ExecuteSynchronously);


asyncTask.Start();

return asyncWaiter;

This works in MvcMiniProfiler 1.9, but doesn't work in MiniProfiler 2...

Update 2: MiniProfiler >=2

The EF stuff added in version 2 breaks my hack above (it adds an internal-only IsActive flag), meaning that I needed a new approach: a new implementation of BaseProfilerProvider for async tasks:

public class TaskProfilerProvider<T> :
    BaseProfilerProvider
{
    Timing step;
    MiniProfiler asyncProfiler;

    public TaskProfilerProvider(Timing parentStep)
    {
        this.step = parentStep;
    }

    internal T Result { get; set; }

    public override MiniProfiler GetCurrentProfiler()
    {
        return this.asyncProfiler;
    }

    public override MiniProfiler Start(ProfileLevel level)
    {
        var result = new MiniProfiler("TaskProfilerProvider<" + typeof(T).Name + ">", level);
        this.asyncProfiler = result;

        BaseProfilerProvider.SetProfilerActive(result);

        return result;
    }

    public override void Stop(bool discardResults)
    {
        if (this.asyncProfiler == null)
        {
            return;
        }

        if (!BaseProfilerProvider.StopProfiler(this.asyncProfiler))
        {
            return;
        }

        if (discardResults)
        {
            this.asyncProfiler = null;
            return;
        }

        BaseProfilerProvider.SaveProfiler(this.asyncProfiler);
    }

    public T SaveToParent()
    {
        // Add the timings from SQL to the current step
        var asyncProfiler = this.GetCurrentProfiler();
        foreach (var sqlTiming in asyncProfiler.GetSqlTimings())
        {
            this.step.AddSqlTiming(sqlTiming);
        }

        // Clear the results, they should have been copied to the main thread.
        this.Stop(true);

        return this.Result;
    }

    public static T SaveToParent(Task<TaskProfilerProvider<T>> continuedTask)
    {
        return continuedTask.Result.SaveToParent();
    }
}

So then to use this provider I just need to start it when starting the task, and hook up the continuation synchronously (as before):

// Create a task that has its own profiler
var asyncTask = new Task<TaskProfilerProvider<T>>(
    () =>
    {
        // Use the provider to start a new MiniProfiler
        var result = new TaskProfilerProvider<T>(currentStep);
        var asyncProfiler = result.Start(level);

        result.Result = // ### Do long running SQL stuff ###

        // Get the results
        return result;
    });

// When the task finishes continue on the main thread to add the SQL timings
var asyncWaiter = asyncTask.ContinueWith<T>(
    TaskProfilerProvider<T>.SaveToParent, 
    TaskContinuationOptions.ExecuteSynchronously);

asyncTask.Start();

return asyncWaiter;

Now the SQL timings appear consistently against the step that initiated the async action. The "% in sql" is more than 100% though, that extra 82.4% is the time saved by doing the SQL in parallel.

                   duration (ms)  from start (ms)  query time (ms)
Start ...Async     0.0            +19.0            1 sql    4533.0
Wait for ...Async  4132.3         +421.3
                                                    182.4 % in sql

Ideally I'd have the long running SQL query on the wait step rather than the init step, but I can't see a way to do that without changing the return type of the calling methods to explicitly pass around the timings (which would make the profiler considerably more obtrusive).