Obtenir les timings du mini-profiler MVC dans les tâches asynchrones

Question

J'ai une requête SQL longuement exécutée dans une page que j'ai accélérée en utilisant une tâche asynchrone :

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;
}

(Notez que cette syntaxe sera beaucoup plus agréable lorsque C# 5 sortira avec la fonction async y await )

En utilisant MVC mini profiler, j'obtiens le timing pour "Wait for Async", mais je ne peux pas obtenir le timing pour l'étape "Async !

Existe-t-il un moyen d'intégrer ces résultats (peut-être uniquement les temps SQL) dans la trace de la page complétée ?

Mise à jour

J'ai trouvé un moyen d'intégrer les étapes du profileur dans la méthode asynchrone :

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

Cela fonctionne presque, en ce sens que l'étape "Async !" apparaît (de manière quelque peu aléatoire, en fonction de l'exécution, et avec certains temps apparaissant comme négatifs), mais ce n'est pas vraiment ce que je veux. Les temps et les instructions SQL sont toujours perdus, et dans ce cas, ce sont les informations les plus précieuses.

Idéalement, j'aimerais que l'étape "Wait for Async" soit liée aux temps (plutôt que l'étape de démarrage). Existe-t-il un moyen pour que stepWait pourrait être lié aux temps de profilage SQL pour le résultat ?

Des idées ?

Answer 1

J'ai trouvé un moyen de le faire, en ne conservant que les durées SQL, les étapes de la page principale s'additionnent toujours correctement :

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);

Il en résulte que les durées SQL de la requête longue sont associées à l'étape en cours lorsque le SQL se termine. Généralement, il s'agit de l'étape qui attend le résultat asynchrone, mais il peut s'agir d'une étape antérieure si la requête SQL se termine avant que je n'aie à l'attendre.

Je l'ai enveloppée dans une QueryAsync<T> (toujours en mémoire tampon et ne prenant pas en charge les transactions), bien qu'il puisse être bien nettoyé. Lorsque j'aurai plus de temps, j'envisagerai d'ajouter une méthode de type ProfiledTask<T> ou similaire qui permet de copier les résultats profilés à partir de la tâche achevée.

Mise à jour 1 (fonctionne dans la version 1.9)

Suite au commentaire de Sam (voir ci-dessous), il a tout à fait raison : AddSqlTiming n'est pas sûr pour les threads. Pour contourner ce problème, j'ai donc déplacé cette opération vers une continuation synchrone :

// 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;

Cela fonctionne dans MvcMiniProfiler 1.9, mais pas dans MiniProfiler 2...

Mise à jour 2 : MiniProfiler >=2

Les éléments EF ajoutés dans la version 2 cassent mon piratage ci-dessus (ils ajoutent une fonction IsActive ), ce qui signifie que j'avais besoin d'une nouvelle approche : une nouvelle implémentation de BaseProfilerProvider pour les tâches asynchrones :

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();
    }
}

Ainsi, pour utiliser ce fournisseur, il me suffit de le lancer au moment du démarrage de la tâche et d'accrocher la suite de manière synchrone (comme auparavant) :

// 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;

Désormais, les temps SQL apparaissent de manière cohérente par rapport à l'étape qui a initié l'action asynchrone. L'étape "% in sql" est supérieur à 100 %, ces 82,4 % supplémentaires correspondent au temps gagné en exécutant le code SQL en parallèle.

                   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

L'idéal serait d'avoir la requête SQL longuement exécutée dans l'étape d'attente plutôt que dans l'étape d'initialisation, mais je ne vois pas comment faire sans changer le type de retour des méthodes d'appel pour transmettre explicitement les temps (ce qui rendrait le profiler considérablement plus gênant).

Answer 2

Ce que vous pouvez faire, c'est créer un nouveau profileur et l'attacher au profileur web.

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();

Le nouveau profileur aura des heures erronées dans sa déclaration mais les étapes seront correctes.