Getting minimal MVC profiles in asynchronous tasks

Question

I have a long SQL query on a page that I accelerated using the 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 much better if C # 5 comes out with async and await )

When using the MVC mini profiler, I get synchronization for "Waiting for Async", but I can not get the time for "Async!" step.

Is there a way to get these results (maybe only SQL timings) into the trace for the completed page?

Update

I found a way to get the profiling steps in the async method:

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

It almost works, in that "Async!" (somewhat randomly, depending on the execution, and with some points appears as negative), but in fact I do not want this. SQL timings and instructions are still lost, in which case they are the most valuable information.

Ideally, I would like the “Wait while Async” step to be associated with timings (rather than the starting step). Is there a way in which stepWait can be associated with the SQL profiler time for the result?

Any ideas?

Answer 1

I found a way to do this, only saving SQL timeouts, the main page steps still stack correctly:

 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 active when the SQL completes var currentStep = currentProfiler.Head; foreach (var sqlTiming in newProfiler.GetSqlTimings()) { currentStep.AddSqlTiming(sqlTiming); } } return result; }, MiniProfiler.Current); 

As a result, the SQL timings for a long query are related to the current step at the end of SQL. This is usually a step that expects an async result, but will be an earlier step if SQL completes before I have to wait for it.

I wrapped this in a QueryAsync<T> -style QueryAsync<T> extension method (always buffered and transactionless), although it could have done with a lot of accuracy. When I have more time, I will consider adding ProfiledTask<T> or the like, which allows you to copy profiled results from a completed task.

Update 1 (works in version 1.9)

After Sam's comment (see below), he is completely right: AddSqlTiming not thread safe. Therefore, to get around this, I moved this 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 does not work in MiniProfiler 2 ...

Update 2: MiniProfiler> = 2

The EF element added in version 2 breaks my hack above (it adds the internal IsActive flag), which means that I need 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, to use this provider, I just need to run it when the task starts and connect 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; 

SQL timings are now displayed sequentially in the step that triggered the async action. "% In sql" is over 100%, although an additional 82.4% is the time that can be saved by running 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 will have a long SQL query at the wait step, and not at the init step, but I see no way to do this without changing the return type of the calling methods to explicitly pass the timings (which would make the profiler much more intrusive).

Answer 2

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

 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 the wrong times in its ad, but the steps will be fine.