sys.dm_exec_query_profiles : la DMV qui détaille les noeuds d’un plan d’exécution réel

La lecture du plan d’exécution réel peut s’avérer être une tâche laborieuse, surtout lorsque le plan contient de nombreux opérateurs ou nœuds.

Introduite avec SQL Server 2014, la vue de gestion dynamique sys.dm_exec_query_profiles nous permet de voir quel(s) nœud(s) d’un plan d’exécution réel consomme le plus de ressources et /ou de temps. C’est donc un formidable outil qui peut faire largement diminuer la recherche des points noueux d’une requête à l’étude.

La documentation de cette DMV montre qu’elle expose de nombreuses colonnes, qui nous renseignent de façon très précise sur la consommation de ressources physiques de chaque opérateur du plan de requête, notamment avec le nombre de millisecondes après lequel un opérateur s’est exécuté pour la première et la dernière fois. Pour simplifier l’analyse des requêtes, on peut s’en tenir à quelques unes d’entre-elles, comme dans la requête suivante :

1
2
3
4
5
6
7
8
9
10
11
12
SELECT  physical_operator_name
        , node_id
        , elapsed_time_ms
        , cpu_time_ms
        , row_count
        , estimate_row_count
        , logical_read_count
        , rewind_count
        , rebind_count
        , end_of_scan_count
        , scan_count
FROM    sys.dm_exec_query_profiles

La colonne node_id nous donne le numéro de l’opérateur dans le plan de requête. Il faut noter que l’opérateur racine de l’arbre de résolution qu’est le plan de requête, et qui se situe en haut et à gauche dans le plan d’exécution graphique, est le seul dans tout plan à ne pas porter de NodeID. L’opérateur qui le précède porte le NodeID 0, et celui qui précède ce dernier le NodeID 1, et ainsi de suite. Le plus grand numéro de NodeID est à l’opérateur qui est le plus à droite et en bas du plan d’exécution graphique.

La colonne session_id va nous permettre de spécifier sur quelle session porte notre étude : pour que cette vue expose des lignes, il est nécessaire que l’option de session SET STATISTICS XML soit positionnée à ON pour la requête à étudier. Ceci équivaut à l’activation de l’option d’inclusion du plan d’exécution réel dans la barre d’outil de SQL Server Management Studio (SSMS) avant l’exécution d’une requête. Ceci est normal, puisque comme pour toutes les tâches de monitoring, elle viennent avec un coût : celui-ci pourrait devenir trop élevé si toutes les requêtes étaient auditées à ce niveau de détail, d’autant que ce type d’information est utilisé par les DBAs, et pas par les applications qui interagissent avec la base de données.

Supposons que la requête (très simple) que l’on souhaite étudier est la suivante :

1
2
3
4
5
SELECT          *
FROM            Sales.SalesOrderDetail AS SOD
INNER JOIN      Production.Product AS P
                        ON SOD.ProductID = P.ProductID
WHERE           P.ListPrice > 1000

On peut récupérer le session_id de plusieurs manières :

  • Il est indiqué dans la barre d’état de toute fenêtre de requête sous SSMS, en bas à droite;
  • Si l’on a conservé les options par défaut de SSMS, il est aussi indiqué sur l’onglet de la fenêtre de requête;
  • On peut exécuter SELECT @@SPID dans la même fenêtre de requête que celle à étudier.

Ne soyez pas perturbé par l’option de session SET STATISTICS IO, TIME ON positionné juste avant la requête : je l’utilise toujours pour diagnostiquer une requête, car cela expose le temps CPU, la durée totale, et surtout, le nombre d’IOs produit par la requête pour chaque table participant à celle-ci. On peut adjoindre l’option XML à la liste IO, TIME si on le souhaite.

Les lecteurs aux yeux affûtés auront remarqué que dans la capture d’écran ci-dessus, il y a un deuxième onglet ouvert : en effet, on doit utiliser une fenêtre de requête pour celle à étudier, et une autre pour lire la sortie de la vue sys.dm_exec_query_profiles pour cette session. Pour cet exemple, on peut reprendre la première requête, et rajouter la clause WHERE adéquate : la session qui va exécuter la requête à l’étude porte le session_id 51 :

1
2
3
4
5
6
7
8
9
10
11
12
13
SELECT  physical_operator_name
        , node_id
        , elapsed_time_ms
        , cpu_time_ms
        , row_count
        , estimate_row_count
        , logical_read_count
        , rewind_count
        , rebind_count
        , end_of_scan_count
        , scan_count
FROM    sys.dm_exec_query_profiles
WHERE   session_id = 51 -- session_id de la requête à l'étude

L’exercice consiste donc à démarrer l’exécution de la requête à l’étude, puis à basculer vers la fenêtre de requête qui spécifie la vue sys.dm_exec_query_profiles avant la fin de l’exécution de la requête à l’étude. Pour la requête de cet exemple, cela nous donne :

On constate ainsi des écarts importants entre le nombre de lignes estimé et réel pour les opérateurs dont le NodeID est 0 et 4, mais il y a un problème : alors que la somme des valeurs de la colonne elapsed_time_ms nous donne 15, la sortie dans l’onglet Messages est la suivante (légèrement écourtée, notamment les IOs physiques et de LOBs, pour les besoins de l’article) :

(29382 row(s) affected)
Table ‘Workfile’. Scan count 0, logical reads 0
Table ‘Worktable’. Scan count 0, logical reads 0
Table ‘SalesOrderDetail’. Scan count 1, logical reads 1246
Table ‘Product’. Scan count 1, logical reads 15

SQL Server Execution Times:
CPU time = 156 ms, elapsed time = 1225 ms.

Il y a bien sûr le temps de consommation du jeu de lignes de résultat par SSMS. On peut le confirmer en éliminant le résultat une fois la requête exécutée : pour ce faire, il suffit de faire un clic-droit dans un zone vierge de la requête > Query options … > Results / Grid > et de cocher la case Discard results after execution.

La question qui vient maintenant est : comment faire pour les requêtes dont l’exécution est bien plus longue ? Et dans tous les cas, la durée d’exécution des requêtes n’étant pas précisément prédictible même après une ou deux exécutions, comment capturer les valeurs qu’expose cette DMV en s’approchant le plus possible de la fin de la requête ? On peut pour cela écrire une boucle qui va stocker le contenu de la DMV à intervalles réguliers et fréquents, et qui vérifie à chaque tour que la requête est toujours en cours d’exécution :

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
SET NOCOUNT ON
GO

DECLARE @session_id int = 51
        , @delay varchar(8) = '00:00:00.010'
        , @i int = 1

IF OBJECT_ID('TempDB.dbo.#query_profile_global') IS NOT NULL
        DROP TABLE #query_profile_global

CREATE TABLE #query_profile_global
(
        physical_operator_name nvarchar(256) NULL
        , node_id int NULL
        , elapsed_time_ms bigint NULL
        , cpu_time_ms bigint NULL
        , row_count bigint NULL
        , estimate_row_count bigint NULL
        , logical_read_count bigint NULL
        , rewind_count bigint NULL
        , rebind_count bigint NULL
        , end_of_scan_count bigint NULL
        , object_name sysname NULL
        , index_name sysname NULL
        , scan_count bigint NULL
        , time_stamp datetime NULL
)

DECLARE @query_profile TABLE
(
        physical_operator_name nvarchar(256) NULL
        , node_id int NULL
        , elapsed_time_ms bigint NULL
        , cpu_time_ms bigint NULL
        , row_count bigint NULL
        , estimate_row_count bigint NULL
        , logical_read_count bigint NULL
        , rewind_count bigint NULL
        , rebind_count bigint NULL
        , end_of_scan_count bigint NULL
        , object_name sysname NULL
        , index_name sysname NULL
        , scan_count bigint NULL
        , time_stamp datetime NULL
)

WHILE EXISTS
(
        SELECT  *
        FROM    sys.dm_exec_requests
        WHERE   session_id = @session_id
)
BEGIN
        INSERT          INTO @query_profile
        SELECT          QP.physical_operator_name
                        , QP.node_id
                        , QP.elapsed_time_ms
                        , QP.cpu_time_ms
                        , QP.row_count
                        , QP.estimate_row_count
                        , QP.logical_read_count
                        , QP.rewind_count
                        , QP.rebind_count
                        , QP.end_of_scan_count
                        , O.name AS object_name
                        , I.name AS index_name
                        , QP.scan_count
                        , GETDATE() AS time_stamp
        FROM            sys.dm_exec_query_profiles AS QP
        LEFT JOIN       sys.objects AS O
                                ON QP.object_id = O.object_id
        LEFT JOIN       sys.indexes AS I
                                ON QP.index_id = I.index_id
                                AND QP.object_id = I.object_id
        WHERE           QP.session_id = @session_id -- spid running query

        IF @i = 1
        BEGIN
                INSERT  INTO #query_profile_global
                SELECT  *
                FROM    @query_profile
        END
        ELSE
        BEGIN
                UPDATE          #query_profile_global
                SET             physical_operator_name = QP.physical_operator_name
                                , node_id = QP.node_id
                                , elapsed_time_ms = QP.elapsed_time_ms
                                , cpu_time_ms = QP.cpu_time_ms
                                , row_count = QP.row_count
                                , estimate_row_count = QP.estimate_row_count
                                , logical_read_count = QP.logical_read_count
                                , rewind_count = QP.rewind_count
                                , rebind_count = QP.rebind_count
                                , end_of_scan_count = QP.end_of_scan_count
                                , object_name = QP.object_name
                                , index_name = QP.index_name
                                , scan_count = QP.scan_count
                                , time_stamp = QP.time_stamp
                FROM            @query_profile AS QP
                INNER JOIN      #query_profile_global AS QFG
                                        ON QFG.node_id = QP.node_id
        END

        WAITFOR DELAY @delay

        DELETE FROM @query_profile

        SET @i += 1
END

SELECT  DISTINCT *
FROM    #query_profile_global
ORDER   BY node_id
--ORDER BY elapsed_time_ms DESC

Ici on stocke le contenu de la DMV toutes les 10 ms. Le délai entre chaque boucle peut être adapté : si l’on sait que la requête dure environ quart d’heure, une récupération du contenu de la vue toutes les secondes est suffisante. Cette valeur peut donc être adaptée suivant la durée d’exécution globale de la requête. Il faut aussi veiller à exécuter ce lot de requêtes dans le même contexte de base de données que celui sous lequel on exécute la requête à étudier. En effet, cela permet d’obtenir le nom de l’objet de base de données accédé :

On constate dans la sortie du lot de requêtes interrogeant la DMV que, par exemple, l’opérateur de NodeID 4 est l’accès à l’index cluster de la table SalesOrderDetail, et qu’il a traité 121317 lignes. Voyons si cela est reflété par le plan d’exécution réel graphique de la requête :

Le numéro de NodeID 4 est bien l’opérateur exposé par la DMV, et si l’on lit la ligne de la bulle dont le libellé est Actual number of rows, on a bien 121317.

Pour l’étude des requêtes plus lourdes, la DMV sys.dm_exec_query_profiles nous permettra de repérer immédiatement les opérateurs les plus consommateurs de ressources, et donc de travailler directement sur ceux-ci en se reportant au plan de requête, puis à la requête elle-même pour en revoir l’écriture et éventuellement l’indexation.

Bonne optimisation !

Laisser un commentaire