Un problème intéressant ce matin sur un SQL Server 2014 SP1 (12.0.4457.0). Une simple requête pour remonter les 20 requêtes les plus consommatrices depuis le dernier restart de l’instance par utilisation CPU:
select top 20 S.text 'SQLtext', STAT.execution_count 'Plan reuse (total executions)', STAT.plan_generation_num 'Plans generations', STAT.creation_time 'Last compile time', STAT.last_execution_time 'Last execution time', STAT.total_worker_time/1000 'Total CPU time (ms)', STAT.total_worker_time/1000/STAT.execution_count 'CPU time/exec (ms)', STAT.total_elapsed_time/1000 'Total Elapsed (ms)', STAT.total_elapsed_time/1000/STAT.execution_count 'Total Elapsed/exec (ms)', STAT.total_logical_reads 'Total Logical Reads', STAT.total_logical_reads/STAT.execution_count 'Logical Reads/exec', STAT.total_physical_reads 'Total Physical Reads', STAT.total_physical_reads/STAT.execution_count 'Physical Reads/exec', STAT.total_logical_writes 'Total Logical Writes', STAT.total_logical_writes/STAT.execution_count 'Logical Writes/exec', P.query_plan 'Last query Plan' from sys.dm_exec_query_stats STAT with (NOLOCK) cross apply sys.dm_exec_sql_text(STAT.sql_handle) S cross apply sys.dm_exec_query_plan(STAT.plan_handle) P order by STAT.total_worker_time/1000 desc
Tout est en mémoire (DMV), le query memory grant de 1Mb est accordé immédiatement, au niveau des attentes, que du SOS_SCHEDULER_YIELD, et pourtant après 18 minutes d’exécution voilà où j’en suis:.
SELECT node_id, physical_operator_name, CAST(SUM(row_count)*100 AS float) / SUM(estimate_row_count) AS percent_complete, SUM(elapsed_time_ms) AS elapsed_time_ms, SUM(cpu_time_ms) AS cpu_time_ms, SUM(logical_read_count) AS logical_read_count, SUM(physical_read_count) AS physical_read_count, SUM(write_page_count) AS write_page_count, SUM(row_count) AS row_count, SUM(estimate_row_count) AS estimate_row_count FROM sys.dm_exec_query_profiles WHERE session_id = 435 GROUP BY node_id, physical_operator_name ORDER BY node_id;
14% seulement des lignes traitées remontées par sys.dm_exec_query_profiles (merci SQL 2014 au passage). Si on regarde le nombre de lignes qui remontent vers le tri par seconde, c’est affligeant:
if (OBJECT_ID('tempdb..#diffrowspersec1') is not null)
drop table #diffrowspersec1 ;
if (OBJECT_ID('tempdb..#diffrowspersec2') is not null)
drop table #diffrowspersec2 ;
create table #diffrowspersec1(node_id int, relop varchar(64), rows bigint);
create table #diffrowspersec2(node_id int, relop varchar(64), rows bigint);
insert into #diffrowspersec1 select node_id, physical_operator_name, SUM(row_count)
FROM sys.dm_exec_query_profiles WHERE session_id = 435 group by node_id, physical_operator_name;
waitfor delay '00:00:01' ;
insert into #diffrowspersec2 select node_id, physical_operator_name, SUM(row_count)
FROM sys.dm_exec_query_profiles WHERE session_id = 435 group by node_id, physical_operator_name;
select D1.node_id, D1.relop, D2.rows - D1.rows as 'rows per sec'
from #diffrowspersec1 D1 join #diffrowspersec2 D2 on D1.node_id = D2.node_id
order by D1.node_id;
Et le tri lui n’a pas commencé à produire des lignes plus haut, c’est un opérateur bloquant donc il doit consommer tout le jeu de données avant.
Au final , la requête aboutit au bout de 35 minutes. Le coût 235.7:
Le plan:
335Mb de données à trier quand même. Principalement à cause de ce que représentent le texte SQL d’une part, mais surtout les plans XML d’autre part. Ce qui est étonnant, c’est qu’aucun sort warning ne soit détecté lors de l’exécution, alors qu’on voit bien que la session a généré des Gb d’objets internes dans tempdb:
select session_id, internal_objects_alloc_page_count/128 as 'Internal Alloc Mb', internal_objects_dealloc_page_count/128 as 'Internal Dealloc Mb' from tempdb.sys.dm_db_session_space_usage where session_id=435 ;
A partir de là, pour minimiser l’impact de la taille des données sur le tri je décide de trier les 20 premières sql_handle / plan_handle seulement avec les données opérationnelles dans une CTE, puis ensuite concaténer les requêtes et les plans avec un CROSS APPLY:
WITH CTE AS (select top 20 STAT.sql_handle, STAT.plan_handle, STAT.execution_count 'Plan reuse (total executions)', STAT.plan_generation_num 'Plans generations', STAT.creation_time 'Last compile time', STAT.last_execution_time 'Last execution time', STAT.total_worker_time/1000 'Total CPU time (ms)', STAT.total_worker_time/1000/STAT.execution_count 'CPU time/exec (ms)', STAT.total_elapsed_time/1000 'Total Elapsed (ms)', STAT.total_elapsed_time/1000/STAT.execution_count 'Total Elapsed/exec (ms)', STAT.total_logical_reads 'Total Logical Reads', STAT.total_logical_reads/STAT.execution_count 'Logical Reads/exec', STAT.total_physical_reads 'Total Physical Reads', STAT.total_physical_reads/STAT.execution_count 'Physical Reads/exec', STAT.total_logical_writes 'Total Logical Writes', STAT.total_logical_writes/STAT.execution_count 'Logical Writes/exec' from sys.dm_exec_query_stats STAT with (NOLOCK) order by STAT.total_worker_time/1000 desc) select SQ.text, CTE.*, P.query_plan FROM CTE cross apply sys.dm_exec_sql_text(CTE.sql_handle) SQ cross apply sys.dm_exec_query_plan(CTE.plan_handle) P;
Le coût tombe à 11.43, la requête s’exécute instantanément:
Le plan:
Plus que 6Mb à trier. Et on voit les cross apply passer une fois le sort effectué dans sa totalité.
Donc conclusion, il faut bien faire attention à la logique de la requête lorsqu’un tri est impliqué. Et regarder la taille des données impliquées tout autant que le nombre de lignes. Dans le cas présent, particulièrement sur les DMV sys.dm_exec_sql_text et sys.dm_exec_query_plan.
En ce qui me concerne, je n’aurai pas le fin mot de l’histoire notamment le sort warning, mais j’ai modifié la requête de référence dans ma boite à outils pour tenir compte de cette dérive. Et je vous conseille de regarder si vous n’avez pas une requête similaire de votre côté 🙂 S’il y en a parmi vous qui observent le même comportement, faites-moi signe !
A+
Continuez votre lecture sur le blog :
- Parallélisme (David Baffaleuf) [SQL Server]
- Nouveautés pg_stat_statements avec PostgreSQL 15 (David Baffaleuf) [PostgreSQL]
- Vers un DIRECT_PATH_READ sur SQL Server ? (David Baffaleuf) [SQL Server]
- Sessions consommatrices dans tempdb (David Baffaleuf) [SQL ServerVintage]
- Modes de récupération et journal de transactions, épisode 2 (David Baffaleuf) [SQL ServerVintage]