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 15SQL 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 !