Les performances des requêtes Entity Framework diffèrent considérablement de l'exécution SQL brute

J’ai une question concernant les performances d’exécution des requêtes Entity Framework.

Schéma :

J’ai une structure de table comme ceci :

CREATE TABLE [dbo].[DataLogger]
(
    [ID] [bigint] IDENTITY(1,1) NOT NULL,
    [ProjectID] [bigint] NULL,
    CONSTRAINT [PrimaryKey1] PRIMARY KEY CLUSTERED ( [ID] ASC )
)

CREATE TABLE [dbo].[DCDistributionBox]
(
    [ID] [bigint] IDENTITY(1,1) NOT NULL,
    [DataLoggerID] [bigint] NOT NULL,
    CONSTRAINT [PrimaryKey2] PRIMARY KEY CLUSTERED ( [ID] ASC )
)

ALTER TABLE [dbo].[DCDistributionBox]
    ADD CONSTRAINT [FK_DCDistributionBox_DataLogger]
    FOREIGN KEY([DataLoggerID]) REFERENCES [dbo].[DataLogger] ([ID])

CREATE TABLE [dbo].[DCString]
(
    [ID] [bigint] IDENTITY(1,1) NOT NULL,
    [DCDistributionBoxID] [bigint] NOT NULL,
    [CurrentMPP] [decimal](18, 2) NULL,
    CONSTRAINT [PrimaryKey3] PRIMARY KEY CLUSTERED ( [ID] ASC )
)

ALTER TABLE [dbo].[DCString]
    ADD CONSTRAINT [FK_DCString_DCDistributionBox]
    FOREIGN KEY([DCDistributionBoxID]) REFERENCES [dbo].[DCDistributionBox] ([ID])

CREATE TABLE [dbo].[StringData]
(
    [DCStringID] [bigint] NOT NULL,
    [TimeStamp] [datetime] NOT NULL,
    [DCCurrent] [decimal](18, 2) NULL,
    CONSTRAINT [PrimaryKey4] PRIMARY KEY CLUSTERED ( [TimeStamp] DESC, [DCStringID] ASC)
)

CREATE NONCLUSTERED INDEX [TimeStamp_DCCurrent-NonClusteredIndex]
ON [dbo].[StringData] ([DCStringID] ASC, [TimeStamp] ASC)
INCLUDE ([DCCurrent])

Des index standard sur les clés étrangères existent également (je ne veux pas tous les lister pour des raisons d’espace).

La table [StringData] a les statistiques de stockage suivantes :

  • Espace de données : 26 901,86 Mo

  • Nombre de lignes : 131 827 749

  • Partitionnée : oui

  • Nombre de partitions : 62

Utilisation :

Je souhaite maintenant regrouper les données de la table [StringData] et effectuer des agrégations.

J’ai créé une requête Entity Framework (les détails de la requête se trouvent ici) :

var compareData = model.StringDatas
    .AsNoTracking()
    .Where(p => p.DCString.DCDistributionBox.DataLogger.ProjectID == projectID && p.TimeStamp >= fromDate && p.TimeStamp < tillDate)
    .Select(d => new
    {
        TimeStamp = d.TimeStamp,
        DCCurrentMpp = d.DCCurrent / d.DCString.CurrentMPP
    })
    .GroupBy(d => DbFunctions.AddMinutes(DateTime.MinValue, DbFunctions.DiffMinutes(DateTime.MinValue, d.TimeStamp) / minuteInterval * minuteInterval))
    .Select(d => new
    {
        TimeStamp = d.Key,
        DCCurrentMppMin = d.Min(v => v.DCCurrentMpp),
        DCCurrentMppMax = d.Max(v => v.DCCurrentMpp),
        DCCurrentMppAvg = d.Average(v => v.DCCurrentMpp),
        DCCurrentMppStDev = DbFunctions.StandardDeviationP(d.Select(v => v.DCCurrentMpp))
    })
    .ToList();

Le temps d’exécution est exceptionnellement long !?

  • Résultat d’exécution : 92 lignes

  • Temps d’exécution : ~16000ms

Tentatives :

J’ai ensuite examiné la requête SQL générée par Entity Framework qui ressemble à ceci :

DECLARE @p__linq__4 DATETIME = 0;
DECLARE @p__linq__3 DATETIME = 0;
DECLARE @p__linq__5 INT = 15;
DECLARE @p__linq__6 INT = 15;
DECLARE @p__linq__0 BIGINT = 20827;
DECLARE @p__linq__1 DATETIME = '06.02.2016 00:00:00';
DECLARE @p__linq__2 DATETIME = '07.02.2016 00:00:00';

SELECT
1 AS [C1],
[GroupBy1].[K1] AS [C2],
[GroupBy1].[A1] AS [C3],
[GroupBy1].[A2] AS [C4],
[GroupBy1].[A3] AS [C5],
[GroupBy1].[A4] AS [C6]
FROM ( SELECT
    [Project1].[K1] AS [K1],
    MIN([Project1].[A1]) AS [A1],
    MAX([Project1].[A2]) AS [A2],
    AVG([Project1].[A3]) AS [A3],
    STDEVP([Project1].[A4]) AS [A4]
    FROM ( SELECT
        DATEADD (minute, ((DATEDIFF (minute, @p__linq__4, [Project1].[TimeStamp])) / @p__linq__5) * @p__linq__6, @p__linq__3) AS [K1],
        [Project1].[C1] AS [A1],
        [Project1].[C1] AS [A2],
        [Project1].[C1] AS [A3],
        [Project1].[C1] AS [A4]
        FROM ( SELECT
            [Extent1].[TimeStamp] AS [TimeStamp],
            [Extent1].[DCCurrent] / [Extent2].[CurrentMPP] AS [C1]
            FROM    [dbo].[StringData] AS [Extent1]
            INNER JOIN [dbo].[DCString] AS [Extent2] ON [Extent1].[DCStringID] = [Extent2].[ID]
            INNER JOIN [dbo].[DCDistributionBox] AS [Extent3] ON [Extent2].[DCDistributionBoxID] = [Extent3].[ID]
            INNER JOIN [dbo].[DataLogger] AS [Extent4] ON [Extent3].[DataLoggerID] = [Extent4].[ID]
            WHERE (([Extent4].[ProjectID] = @p__linq__0) OR (([Extent4].[ProjectID] IS NULL) AND (@p__linq__0 IS NULL))) AND ([Extent1].[TimeStamp] >= @p__linq__1) AND ([Extent1].[TimeStamp] < @p__linq__2)
        )  AS [Project1]
    )  AS [Project1]
    GROUP BY [K1]
)  AS [GroupBy1]

J’ai copié cette requête SQL dans SSMS sur la même machine, connecté avec la même chaîne de connexion qu’Entity Framework.

Le résultat est une performance très nettement améliorée :

  • Résultat d’exécution : 92 lignes

  • Temps d’exécution : 517ms

J’ai également effectué un test en boucle et le résultat est étrange. Le test ressemble à ceci :

for (int i = 0; i < 50; i++)
{
    DateTime begin = DateTime.UtcNow;

    [...query...]

    TimeSpan excecutionTimeSpan = DateTime.UtcNow - begin;
    Debug.WriteLine("{0}th run: {1}", i, excecutionTimeSpan.ToString());
}

Le résultat est très différent et semble aléatoire (?) :

0th run: 00:00:11.0618580
1th run: 00:00:11.3339467
2th run: 00:00:10.0000676
3th run: 00:00:10.1508140
4th run: 00:00:09.2041939
5th run: 00:00:07.6710321
6th run: 00:00:10.3386312
7th run: 00:00:17.3422765
8th run: 00:00:13.8620557
9th run: 00:00:14.9041528
10th run: 00:00:12.7772906
11th run: 00:00:17.0170235
12th run: 00:00:14.7773750

Question :

Pourquoi l’exécution des requêtes Entity Framework est-elle si lente ? Le nombre de lignes résultantes est vraiment faible et la requête SQL brute montre des performances très rapides.

Mise à jour 1 :

Je m’assure que ce n’est pas un délai lié à la création du MetaContext ou du modèle. Quelques autres requêtes sont exécutées sur la même instance de modèle juste avant avec de bonnes performances.

Mise à jour 2 (en rapport avec la réponse de @x0007me) :

Merci pour l’indication mais cela peut être éliminé en changeant les paramètres du modèle comme ceci :

modelContext.Configuration.UseDatabaseNullSemantics = true;

Le SQL généré par EF est maintenant :

SELECT
1 AS [C1],
[GroupBy1].[K1] AS [C2],
[GroupBy1].[A1] AS [C3],
[GroupBy1].[A2] AS [C4],
[GroupBy1].[A3] AS [C5],
[GroupBy1].[A4] AS [C6]
FROM ( SELECT
    [Project1].[K1] AS [K1],
    MIN([Project1].[A1]) AS [A1],
    MAX([Project1].[A2]) AS [A2],
    AVG([Project1].[A3]) AS [A3],
    STDEVP([Project1].[A4]) AS [A4]
    FROM ( SELECT
        DATEADD (minute, ((DATEDIFF (minute, @p__linq__4, [Project1].[TimeStamp])) / @p__linq__5) * @p__linq__6, @p__linq__3) AS [K1],
        [Project1].[C1] AS [A1],
        [Project1].[C1] AS [A2],
        [Project1].[C1] AS [A3],
        [Project1].[C1] AS [A4]
        FROM ( SELECT
            [Extent1].[TimeStamp] AS [TimeStamp],
            [Extent1].[DCCurrent] / [Extent2].[CurrentMPP] AS [C1]
            FROM    [dbo].[StringData] AS [Extent1]
            INNER JOIN [dbo].[DCString] AS [Extent2] ON [Extent1].[DCStringID] = [Extent2].[ID]
            INNER JOIN [dbo].[DCDistributionBox] AS [Extent3] ON [Extent2].[DCDistributionBoxID] = [Extent3].[ID]
            INNER JOIN [dbo].[DataLogger] AS [Extent4] ON [Extent3].[DataLoggerID] = [Extent4].[ID]
            WHERE ([Extent4].[ProjectID] = @p__linq__0) AND ([Extent1].[TimeStamp] >= @p__linq__1) AND ([Extent1].[TimeStamp] < @p__linq__2)
        )  AS [Project1]
    )  AS [Project1]
    GROUP BY [K1]
)  AS [GroupBy1]

Comme vous pouvez le voir, le problème que vous avez décrit est maintenant résolu, mais le temps d’exécution ne change pas.

De plus, comme vous pouvez le voir dans le schéma et le temps d’exécution brut, j’ai utilisé une structure optimisée avec des index hautement optimisés.

Mise à jour 3 (en rapport avec la réponse de @Vladimir Baranov) :

Je ne vois pas en quoi cela peut être lié à la mise en cache du plan de requête. Parce que dans la MSDN, il est clairement décrit qu’EF6 utilise la mise en cache du plan de requête.

Un simple test prouve que l’énorme différence de temps d’exécution n’est pas liée à la mise en cache du plan de requête (pseudo-code) :

using(var modelContext = new ModelContext())
{
    modelContext.Query(); //1th run activates caching

    modelContext.Query(); //2th used cached plan
}

En résultat, les deux requêtes s’exécutent avec le même temps.

Mise à jour 4 (en rapport avec la réponse de @bubi) :

J’ai essayé d’exécuter la requête générée par EF comme vous l’avez décrit :

int result = model.Database.ExecuteSqlCommand(@"SELECT
    1 AS [C1],
    [GroupBy1].[K1] AS [C2],
    [GroupBy1].[A1] AS [C3],
    [GroupBy1].[A2] AS [C4],
    [GroupBy1].[A3] AS [C5],
    [GroupBy1].[A4] AS [C6]
    FROM ( SELECT
        [Project1].[K1] AS [K1],
        MIN([Project1].[A1]) AS [A1],
        MAX([Project1].[A2]) AS [A2],
        AVG([Project1].[A3]) AS [A3],
        STDEVP([Project1].[A4]) AS [A4]
        FROM ( SELECT
            DATEADD (minute, ((DATEDIFF (minute, 0, [Project1].[TimeStamp])) / @p__linq__5) * @p__linq__6, 0) AS [K1],
            [Project1].[C1] AS [A1],
            [Project1].[C1] AS [A2],
            [Project1].[C1] AS [A3],
            [Project1].[C1] AS [A4]
            FROM ( SELECT
                [Extent1].[TimeStamp] AS [TimeStamp],
                [Extent1].[DCCurrent] / [Extent2].[CurrentMPP] AS [C1]
                FROM    [dbo].[StringData] AS [Extent1]
                INNER JOIN [dbo].[DCString] AS [Extent2] ON [Extent1].[DCStringID] = [Extent2].[ID]
                INNER JOIN [dbo].[DCDistributionBox] AS [Extent3] ON [Extent2].[DCDistributionBoxID] = [Extent3].[ID]
                INNER JOIN [dbo].[DataLogger] AS [Extent4] ON [Extent3].[DataLoggerID] = [Extent4].[ID]
                WHERE ([Extent4].[ProjectID] = @p__linq__0) AND ([Extent1].[TimeStamp] >= @p__linq__1) AND ([Extent1].[TimeStamp] < @p__linq__2)
            )  AS [Project1]
        )  AS [Project1]
        GROUP BY [K1]
    )  AS [GroupBy1]",
    new SqlParameter("p__linq__0", 20827),
    new SqlParameter("p__linq__1", fromDate),
    new SqlParameter("p__linq__2", tillDate),
    new SqlParameter("p__linq__5", 15),
    new SqlParameter("p__linq__6", 15));

  • Résultat d’exécution : 92

  • Temps d’exécution : ~16000ms

Cela a pris exactement aussi longtemps que la requête EF normale !?

Mise à jour 5 (en rapport avec la réponse de @vittore) :

J’ai créé un arbre d’appels tracé, peut-être que cela aidera :

Mise à jour 6 (en rapport avec la réponse de @usr) :

J’ai créé deux XML de plan d’exécution via SQL Server Profiler.

Exécution rapide (SSMS).SQLPlan

Exécution lente (EF).SQLPlan

Mise à jour 7 (en rapport avec les commentaires de @VladimirBaranov) :

J’ai maintenant effectué d’autres cas de test en rapport avec vos commentaires.

D’abord j’ai éliminé les opérations d’ordonnancement coûteuses en utilisant une nouvelle colonne calculée et un INDEX correspondant. Cela réduit le décalage de performance lié à DATEADD(MINUTE, DATEDIFF(MINUTE, 0, [TimeStamp] ) / 15* 15, 0). Les détails sur comment et pourquoi se trouvent ici.

Le résultat ressemble à ceci :

Requête Entity Framework pure :

for (int i = 0; i < 3; i++)
{
    DateTime begin = DateTime.UtcNow;
    var result = model.StringDatas
        .AsNoTracking()
        .Where(p => p.DCString.DCDistributionBox.DataLogger.ProjectID == projectID && p.TimeStamp15Minutes >= fromDate && p.TimeStamp15Minutes < tillDate)
        .Select(d => new
        {
            TimeStamp = d.TimeStamp15Minutes,
            DCCurrentMpp = d.DCCurrent / d.DCString.CurrentMPP
        })
        .GroupBy(d => d.TimeStamp)
        .Select(d => new
        {
            TimeStamp = d.Key,
            DCCurrentMppMin = d.Min(v => v.DCCurrentMpp),
            DCCurrentMppMax = d.Max(v => v.DCCurrentMpp),
            DCCurrentMppAvg = d.Average(v => v.DCCurrentMpp),
            DCCurrentMppStDev = DbFunctions.StandardDeviationP(d.Select(v => v.DCCurrentMpp))
        })
        .ToList();

        TimeSpan excecutionTimeSpan = DateTime.UtcNow - begin;
        Debug.WriteLine("{0}th run pure EF: {1}", i, excecutionTimeSpan.ToString());
}

0th run pure EF: 00:00:12.6460624

1th run pure EF: 00:00:11.0258393

2th run pure EF: 00:00:08.4171044

J’ai ensuite utilisé le SQL généré par EF comme requête SQL :

for (int i = 0; i < 3; i++)
{
    DateTime begin = DateTime.UtcNow;
    int result = model.Database.ExecuteSqlCommand(@"SELECT
        1 AS [C1],
        [GroupBy1].[K1] AS [TimeStamp15Minutes],
        [GroupBy1].[A1] AS [C2],
        [GroupBy1].[A2] AS [C3],
        [GroupBy1].[A3] AS [C4],
        [GroupBy1].[A4] AS [C5]
        FROM ( SELECT
            [Project1].[TimeStamp15Minutes] AS [K1],
            MIN([Project1].[C1]) AS [A1],
            MAX([Project1].[C1]) AS [A2],
            AVG([Project1].[C1]) AS [A3],
            STDEVP([Project1].[C1]) AS [A4]
            FROM ( SELECT
                [Extent1].[TimeStamp15Minutes] AS [TimeStamp15Minutes],
                [Extent1].[DCCurrent] / [Extent2].[CurrentMPP] AS [C1]
                FROM    [dbo].[StringData] AS [Extent1]
                INNER JOIN [dbo].[DCString] AS [Extent2] ON [Extent1].[DCStringID] = [Extent2].[ID]
                INNER JOIN [dbo].[DCDistributionBox] AS [Extent3] ON [Extent2].[DCDistributionBoxID] = [Extent3].[ID]
                INNER JOIN [dbo].[DataLogger] AS [Extent4] ON [Extent3].[DataLoggerID] = [Extent4].[ID]
                WHERE ([Extent4].[ProjectID] = @p__linq__0) AND ([Extent1].[TimeStamp15Minutes] >= @p__linq__1) AND ([Extent1].[TimeStamp15Minutes] < @p__linq__2)
            )  AS [Project1]
            GROUP BY [Project1].[TimeStamp15Minutes]
        )  AS [GroupBy1];",
    new SqlParameter("p__linq__0", 20827),
    new SqlParameter("p__linq__1", fromDate),
    new SqlParameter("p__linq__2", tillDate));

    TimeSpan excecutionTimeSpan = DateTime.UtcNow - begin;
    Debug.WriteLine("{0}th run: {1}", i, excecutionTimeSpan.ToString());
}

0th run: 00:00:00.8381200

1th run: 00:00:00.6920736

2th run: 00:00:00.7081006

et avec OPTION(RECOMPILE) :

for (int i = 0; i < 3; i++)
{
    DateTime begin = DateTime.UtcNow;
    int result = model.Database.ExecuteSqlCommand(@"SELECT
        1 AS [C1],
        [GroupBy1].[K1] AS [TimeStamp15Minutes],
        [GroupBy1].[A1] AS [C2],
        [GroupBy1].[A2] AS [C3],
        [GroupBy1].[A3] AS [C4],
        [GroupBy1].[A4] AS [C5]
        FROM ( SELECT
            [Project1].[TimeStamp15Minutes] AS [K1],
            MIN([Project1].[C1]) AS [A1],
            MAX([Project1].[C1]) AS [A2],
            AVG([Project1].[C1]) AS [A3],
            STDEVP([Project1].[C1]) AS [A4]
            FROM ( SELECT
                [Extent1].[TimeStamp15Minutes] AS [TimeStamp15Minutes],
                [Extent1].[DCCurrent] / [Extent2].[CurrentMPP] AS [C1]
                FROM    [dbo].[StringData] AS [Extent1]
                INNER JOIN [dbo].[DCString] AS [Extent2] ON [Extent1].[DCStringID] = [Extent2].[ID]
                INNER JOIN [dbo].[DCDistributionBox] AS [Extent3] ON [Extent2].[DCDistributionBoxID] = [Extent3].[ID]
                INNER JOIN [dbo].[DataLogger] AS [Extent4] ON [Extent3].[DataLoggerID] = [Extent4].[ID]
                WHERE ([Extent4].[ProjectID] = @p__linq__0) AND ([Extent1].[TimeStamp15Minutes] >= @p__linq__1) AND ([Extent1].[TimeStamp15Minutes] < @p__linq__2)
            )  AS [Project1]
            GROUP BY [Project1].[TimeStamp15Minutes]
        )  AS [GroupBy1]
        OPTION(RECOMPILE);",
    new SqlParameter("p__linq__0", 20827),
    new SqlParameter("p__linq__1", fromDate),
    new SqlParameter("p__linq__2", tillDate));

    TimeSpan excecutionTimeSpan = DateTime.UtcNow - begin;
    Debug.WriteLine("{0}th run: {1}", i, excecutionTimeSpan.ToString());
}

0th run avec RECOMPILE: 00:00:00.8260932

1th run avec RECOMPILE: 00:00:00.9139730

2th run avec RECOMPILE: 00:00:01.0680665

Même requête SQL exécutée dans SSMS (sans RECOMPILE) :

00:00:01.105

Même requête SQL exécutée dans SSMS (avec RECOMPILE) :

00:00:00.902

J’espère que ce sont toutes les valeurs dont vous aviez besoin.

Dans cette réponse, je me concentre sur l’observation initiale : la requête générée par EF est lente, mais lorsque la même requête est exécutée dans SSMS, elle est rapide.

Une explication possible de ce comportement est le Parameter sniffing.

SQL Server utilise un processus appelé parameter sniffing lorsqu’il exécute des procédures stockées qui ont des paramètres. Lorsque la procédure est compilée ou recompilée, la valeur passée au paramètre est évaluée et utilisée pour créer un plan d’exécution. Cette valeur est ensuite stockée avec le plan d’exécution dans le cache de plans. Lors des exécutions suivantes, cette même valeur – et le même plan – est utilisé.

Ainsi, EF génère une requête avec quelques paramètres. La première fois que vous exécutez cette requête, le serveur crée un plan d’exécution pour cette requête en utilisant les valeurs des paramètres qui étaient en vigueur lors de la première exécution. Ce plan est généralement assez bon. Mais plus tard, vous exécutez la même requête EF avec d’autres valeurs pour les paramètres. Il est possible que pour les nouvelles valeurs de paramètres, le plan précédemment généré ne soit pas optimal et que la requête devienne lente. Le serveur continue d’utiliser le plan précédent, car c’est toujours la même requête, seules les valeurs des paramètres sont différentes.

Si à ce moment-là vous prenez le texte de la requête et essayez de l’exécuter directement dans SSMS, le serveur créera un nouveau plan d’exécution, car techniquement ce n’est pas la même requête que celle émise par l’application EF. Même une différence d’un seul caractère suffit, tout changement dans les paramètres de session suffit également pour que le serveur traite la requête comme nouvelle. En conséquence, le serveur a deux plans pour la requête apparemment identique dans son cache. Le premier plan “lent” est lent pour les nouvelles valeurs de paramètres, car il a été initialement construit pour des valeurs de paramètres différentes. Le second plan “rapide” est construit pour les valeurs de paramètres actuelles, il est donc rapide.

L’article Lent dans l’application, rapide dans SSMS par Erland Sommarskog explique ceci et d’autres domaines connexes de manière beaucoup plus détaillée.

Il existe plusieurs façons de supprimer les plans mis en cache et de forcer le serveur à les régénérer. Modifier la table ou modifier les index de la table devrait le faire – cela devrait supprimer tous les plans liés à cette table, tant “lents” que “rapides”. Ensuite, vous exécutez la requête dans l’application EF avec de nouvelles valeurs de paramètres et obtenez un nouveau plan “rapide”. Vous exécutez la requête dans SSMS et obtenez un deuxième plan “rapide” avec les nouvelles valeurs de paramètres. Le serveur génère toujours deux plans, mais les deux sont rapides maintenant.

Une autre variante est d’ajouter OPTION(RECOMPILE) à la requête. Avec cette option, le serveur ne stockerait pas le plan généré dans son cache. Ainsi, chaque fois que la requête s’exécute, le serveur utiliserait les valeurs réelles des paramètres pour générer le plan qu’il pense optimal pour les valeurs de paramètres données. L’inconvénient est la surcharge ajoutée de la génération du plan.

Notez bien que le serveur pourrait tout de même choisir un “mauvais” plan avec cette option en raison de statistiques obsolètes, par exemple. Mais au moins, le parameter sniffing ne serait pas un problème.

Pour ceux qui se demandent comment ajouter l’indication OPTION (RECOMPILE) à la requête générée par EF, consultez cette réponse :

https://stackoverflow.com/a/26762756/4116017