Notes complémentaires faisant suite aux articles "
SQL Server Monitoring Performance - Wait Stats" et "
Utiliser le SQL Profiler pour optimiser une base de donnée" précédemment publiés.
Cet article visera principalement la définition de certains Wait Times et la présentation d'une autre méthode de capture des Wait Stats.
Commencé mi-mai, il m'aura fallut presque 3 mois pour organiser une synthèse correcte de mes recherches.
Définition des Wait Times
Sql Serveur peut encourir différents délais d'attentes sur des processus internes.
Ces délais d'attentes sont généralement les indicateurs de problèmes de performances.
En analysant de plus près les statistiques de Wait Types, il est possible d'identifier la ou les sources causant les dégradations de performances sur SQL serveur.
Les Wait Times peuvent être consultés depuis la Dynamic Management View
Sys.dm_os_wait_stats.
Ces statistiques étant maintenue au niveau du serveur SQL (cumulant l'information au fur et à mesure) il est nécessaire d'effectuer plusieurs requêtes (dans le temps) et quelques opérations de soustractions pour obtenir des informations exploitables.
L'article "
SQL Server Monitoring Performance - Wait Stats" écrit précédemment met en place une méthode de capture systématique des wait times toutes les minutes. Quelques scripts sql permettent également d'exploiter l'information au mieux.
Cas Pratique
Dans un cas récent, des délais importants sur le Wait Time "WRITELOG" (plusieurs secondes par minutes) nous indiquait un problème de "libre" accès au fichier de transaction sql sur les disques SAN.
Ce problème d'accès causant des temps de réponses vraiment importants (jusqu'à 30 secondes) pour les applications clientes.
Capture des Wait Types
SELECT wait_type, waiting_tasks_count, wait_time_ms,
max_wait_time_ms, signal_wait_time_ms
FROM master.Sys.dm_os_wait_stats
where wait_type like 'LogBuffer' or
Wait_Type like 'LOGMGR%' or
wait_type like 'WRITE%' or
wait_type like 'latch_%' or
wait_Type like 'IO_COMPLETION' or
Wait_type like 'SOS_SCH%' or
wait_type like 'PAGEIOLATCH%'
Reset des statistiques
DBCC SQLPERF('sys.dm_os_wait_stats', CLEAR);
Signification de "signal_wait_time_ms"
Le champs signal wait time de
sys.dm_os_wait_stats nécessite quelques explications complémentaire.
Ce temps représente le délai d'attente entre le moment où la ressource est signalée (ressource disponible) et le moment ou le thread de traitement ait été reschédulé pour l'execution.
Autrement dit le délai nécessaire pour que la tâche soit reprogrammée par le scheduler (le scheduler organise au mieux la distribution des ressources CPU aux différents processus Sql).
Sur les systèmes/schedulers chargés, le "signal_wait_time_ms" est une indication de pression sur le CPU (ressource CPU disponible de façon trop limitée pour les tâches).
Ce temps est déjà inclus dans "wait_time_ms" (
ref).
This time represents the time that the actual wait event finished, and the time the task is scheduled to run on the scheduler again. On busy schedulers this signal wait time can be an indication of CPU pressure.
Monitoring de WaitStats selon Microsoft
Le SQL suivant originaire des laboratoires de Microsoft est extrait du forum de Sql Serveur Magazine. Il permet de tracker les wait stats pour Sql Serveur 2000.
if exists (select 1 from sysobjects where name = 'track_waitstats')
drop proc track_waitstats
go
CREATE proc track_waitstats (@num_samples int=10,@delaynum int=1,@delaytype nvarchar(10)='minutes')
as
--
-- This stored procedure is provided "AS IS" with no warranties, and confers no rights.
-- Use of included script samples are subject to the terms specified at http://www.microsoft.com/info/cpyright.htm
--
-- T. Davidson
-- @num_samples is the number of times to capture waitstats, default is 10 times
-- default delay interval is 1 minute
-- delaynum is the delay interval - can be minutes or seconds
-- delaytype specifies whether the delay interval is minutes or seconds
-- create waitstats table if it doesn't exist, otherwise truncate
--
set nocount on
if not exists (select 1 from sysobjects where name = 'waitstats')
create table waitstats ([wait type] varchar(80),
requests numeric(20,1),
[wait time] numeric (20,1),
[signal wait time] numeric(20,1),
now datetime default getdate())
else truncate table waitstats
dbcc sqlperf (waitstats,clear) -- clear out waitstats
declare @i int,@delay varchar(8),@dt varchar(3), @now datetime, @totalwait numeric(20,1)
,@endtime datetime,@begintime datetime
,@hr int, @min int, @sec int
select @i = 1
select @dt = case lower(@delaytype)
when 'minutes' then 'm'
when 'minute' then 'm'
when 'min' then 'm'
when 'mm' then 'm'
when 'mi' then 'm'
when 'm' then 'm'
when 'seconds' then 's'
when 'second' then 's'
when 'sec' then 's'
when 'ss' then 's'
when 's' then 's'
else @delaytype
end
if @dt not in ('s','m')
begin
print 'please supply delay type e.g. seconds or minutes'
return
end
if @dt = 's'
begin
select @sec = @delaynum % 60
select @min = cast((@delaynum / 60) as int)
select @hr = cast((@min / 60) as int)
select @min = @min % 60
end
if @dt = 'm'
begin
select @sec = 0
select @min = @delaynum % 60
select @hr = cast((@delaynum / 60) as int)
end
select @delay= right('0'+ convert(varchar(2),@hr),2) + ':' +
+ right('0'+convert(varchar(2),@min),2) + ':' +
+ right('0'+convert(varchar(2),@sec),2)
if @hr > 23 or @min > 59 or @sec > 59
begin
select 'hh:mm:ss delay time cannot > 23:59:59'
select 'delay interval and type: ' + convert (varchar(10),@delaynum) + ',' + @delaytype + ' converts to ' + @delay
return
end
while (@i <= @num_samples)
begin
insert into waitstats ([wait type], requests, [wait time],[signal wait time])
exec ('dbcc sqlperf(waitstats)')
select @i = @i + 1
waitfor delay @delay
end
select @now=max(now),@begintime=min(now),@endtime=max(now)
from waitstats where [wait type] = 'TOTAL'
--- subtract waitfor, sleep, and resource_queue from Total
select @totalwait = sum([wait time]) + 1 from waitstats
where [wait type] not in ('WAITFOR','SLEEP','RESOURCE_QUEUE','TOTAL', '***total***') and now = @now
-- insert adjusted totals, rank by percentage descending
insert into waitstats select '***total***',0,@totalwait,@totalwait,@now
select 'start, end, duration'='start: ' + convert(varchar(20),@begintime,20) + ' end: ' + convert(varchar(20),@endtime,20) + ' duration (minutes): ' + convert(varchar(10), datediff(mi,@begintime,@endtime))
select 'waitstats samples'=@num_samples, 'delay, type'= convert (varchar(10),@delaynum) + ',' + @delaytype,'waitfor delay interval'=@delay
select [wait type],[wait time],percentage=cast (100*[wait time]/@totalwait as numeric(20,1))
from waitstats
where [wait type] not in ('WAITFOR','SLEEP','RESOURCE_QUEUE','TOTAL')
and now = @now
order by percentage desc
go
exec track_waitstats 20,15,'seconds'
Voici quelques exemples d'utilisation et informations diverses
Pour executer une journée entière...
exec track_waitstats 20,15,'seconds'
Une capture toutes les 15 secondes pendant deux heures.
@num_samples = 7200
@delaynum - 15
@delaytype = 'seconds'
Le query suivant est relatif à l'activation de traces spécifiques permet avant l'execution de trackwaits.
Permet certainement d'activer des traces bien précises (non testé)
DBCC TRACEON(818,-1)
DBCC TRACEON(806,-1)
DBCC TRACEON(3605,-1)
Revue de quelques Wait Types
Une liste des différents wait_type est disponible sur le site MSDN de Microsoft (
sys.dm_os_wait_stats).
Bien qu'en français, il est néanmoins regrettable que les définition ne soient pas plus précises.
LATCH_EX, PAGEIOLATCH_SH (CXPacket)
Les entrées LATCH_EX, PAGEIOLATCH_SH (CXPacket) identifie de faibles performances IO.
Plus de reférence pour cet article :-( .
IO_COMPLETION
Indique généralement un problème de performance disque.
Indique qu'un processus SPID (requête) attend que les opérations IO soient terminées.
Ces requêtes IO ne sont pas liées aux pages (Data Pages) de données des DB mais plutôt aux processus internes de SqlServer.
Information complémentaire:
Une valeur de "disk seconds/read" (perfmon) supérieure à 15 ms de façon prolongée indique un étranglement au niveau des disques (même si Microsoft applique déjà une valeur critique plus élevée de 20 ms).
Les écritures disques doivent être aussi rapide que possible pour le Transaction Log (1 ms ou moins est idéal pour un système OLTP).
Plus d'info ici sur SqlCat (cet article analysant/diagnostiquant les différents types de bottleneck).
PAGEIOLATCH_*
Indique un problème de performance IO pour accéder aux données de la DB.
Les IO relatif aux chargement des pages de données (Data Pages) des DB.
Les PAGEIOLATCH_SH surviennent quand une tâche attend un latch sur un buffer exécutant/attendant la fin d'exécution d'une requête I/O.
Les PAGEIOLACTH_SH sont des "latch requests" en mode partagé (Shared mode) et _EX en mode exclusif (exclusive). Les attentes sur PAGEIOLATCH_SH sont très bref puisqu'il sont uniquement maintenu sur les pages le temps nécessaire à l'achèvement de l'operation I/O.
Le manque de ressource I/O (I/O bottleneck) peuvent être identifiés en examinant les temps d'attente des LATCHs.
Une grande quantité de PAGEIOLATCH_* et/ou CXPACKET peut également indiquer une forte fragmentation des indexes. Vérifiez donc cette fragmentation ainsi que l'update des statistiques.
Pour apporter une solution à ce type de problème, lire le document "
Troubleshooting Performance Problems in SQL Server 2005" de Microsoft en recherchant les sections relatives à "I/O Bottleneck".
Considérer les options suivantes:
- Réviser/modifier la configuration hardware pour améliorer les IO (part importante de l'article).
- Considérer l'utilisation d' execution plan pour les requête SQL en vue de minimiser le nombre d'opérations IO nécessaires.
- Vérifier si les indexes sont correctements définis (Utilisation de "Sql Tuning Advisor")
Plus d'info ici sur MSDN.
PageIOLatch_* occurs when a task is waiting on a latch for a buffer that is in an I/O request. PAGEIOLATCH_SH waits is very brief as they are only held on a page during IO operations.
These latch waits account for the physical I/O waits when a page is accessed for reading or writing and the page is not available in the buffer pool. When the page is not found in the buffer pool, an asynchronous I/O is posted and then the status of the I/O is checked. If I/O has already completed, the worker proceeds normally. Otherwise, it waits on PAGEIOLATCH_EX or PAGEIOLATCH_SH, depending upon the type of request.
More information here on the Rickie Lee's blog.
CXPACKET
CXPACKET démontre que plusieurs querys sont exécutés en parallele et que un ou plusieurs d'entre deux attendent la fin de l'exécution d'autres threads (
sans doute des autres querys)
1*.
C'est une indication de mauvaise indexation, de possible table scan et/ou mauvaise performances disques. En général, une re-indexation ou forcer l'utilisation de plan d'exécution non-parallele pour ces querys (à faible performance) corrige ce problème.
Plus d'info ici sur le forum de Sql Serveur Magazine.
1*: one or more of the ecids is waiting on the other threads to complete.
Losrque CXPACKET and PAGEIOLATCH sont les deux plus important Wait Times, cela indique que les threads s'attendent l'un l'autre dans le UMS. Cela est causé par de mauvaises statistiques (causant l'utilisation de mauvais plan d'exécution).
Solution: Reindexer les tables (défragmenter les indexes, mettre les statistiques à jour).
Plus d'info ici sur le forum de Sql Serveur Magazine. Contient une excellente requête pour faire du monitoring de wait stats.
LATCH_EX
Si l'analyse des waits indique un grand pourentage de LATCH_EX, cela pourrait indiquer une contention (étranglement) des objets résidents en mémoire (
rememory-resident objects)
Par exemple, la surcharge peut être causée les utilisateurs essayent tous de mettre à jour les (mêmes pages) de données critiques fréquemments utilisées (
hot pages). Dans ce cas, ils essayent tous de prendre un latch exclusif sur le même ensemble de pages... et par conséquent... ils s'attendent tous les uns les autres.
Dans ce cas de figure la quantité de mémoire disponible (ou mis à disposition) n'est pas un facteur permettant de régler la situation.
Plus d'info ici sur le site My Database Support
SOS_SCHEDULER_YIELD
Une grande quantité de SOS_SCHEDULER_YIELD dans les Wait stats est un excellent indicateur de manque de ressource CPU (
CPU pressure).
Ils surviennent lorsque la ressource CPU d'une tâche est volontairement cédée au scheduler pour d'autres tâches à executer.
Durant ce laps d'attente, la tâche est mise en suspend en attendant le renouvellement de son unité d'exécution.
SQLOS gère le threading avec une approche coopérative, les threads ne sont pas gérés pas le système d'exploitation.
Quand un processus Sql require trop de ressources pour être achevé, il va céder son temps de processing (au lieu de consommer toutes les ressources jusqu'a l'accomplissement de sa tâche).
Cette approche coopérative évite aux autres processus Sql d'être ralentis ou bloqués. Une fois qu'il a abandonné son unité de temps processing, le processus Sql va sagement attendre une nouvelle occasion de se voir octroyer des unités de processing complémentaires par scheduler de SQLOS.
Si vous constatez une valeur élevée de SOS_SCHEDULER_YIELD, utilisez l'outil PerfMon et vérifiez si les compteurs "
% Processor Time" et "
Processor Queue Length" sont maintenu à des valeurs élevées.
Il est également possible de valider le fait que Sql Serveur puisse être le responsable de la pression CPU; Pour ce faire, utilisez le compteur "
% Processor Time" sur l'instance de SQL Server (ou tout autre processus/programme suspect).
Vous aurez aussi besoin de vérifier le nombre de "workers" en cours d'exécution en verifiant les vues
sys.dm_os_workers et
sys.dm_os_schedulers. Cela indiquera si un nombre significatif de tâches/processus Sql sont dans la queue d'attente pour obtenir une unité d'exécution de la part du scheduler.
Plus d'info sur les liens suivants
Vérifier la pression CPU via une DMV
Il est possible de lancer une requête sur les "Dynamic Management View" pour vérifier l'état des Schedulers et s'assurer qu'ils n'attendent pas la libération de ressources CPU.
SELECT scheduler_id, current_tasks_count, runnable_tasks_count
FROM sys.dm_os_schedulers
WHERE scheduler_id < 255
Inquiétez-vous si vous constatez des runnable_tasks_count au dessus de zéro. Et si durant une période quelconque vous constatez que runnable_tasks_count contient deux digits, alors dans ce cas, vous devriez être extrêmement inquiet!
Vérifier la pression CPU via le Signal_Wait_Time
Il est également possible de constater un manque de ressource CPU (CPU pressure) en analysant les Signal_Wait_Time.
Les "signal waits" mesure le temps perdu par un process en cours d'exécution (mais suspendu et entassé dans une queue) à attendre des ressources CPU pour continuer son exécution.
Consultez
sys.dm_os_wait_stats pour obtenir le Signal waits et le total des waits.
Une grande valeur de "signal waits" indique un goulot d'étranglement au niveau CPU.
Info: Signal waits > 25% of total waits.
WRITELOG
WRITELOG indique que SQL serveur attend que les operations IO relatives au transaction log soient terminées. Cela indique généralement un problème de performance disque (soit les disques eux mêmes, soit le controleur ou tout système apparenté).
Tiré d'un cas réel, 400 ms pour un WriteLog est bien trop long et un symptôme clair d'engorgement des performances disques. Le temps d'accès au log file ne devrait pas excéder quelques milli-secondes, l'idéal est un temps inférieur ou égal à la milli-seconde (ce qui est possible avec certain SAN, ex: voir par exemple les produits NET App).
Pour l'accès aux fichiers de données, un temps d'accès de 15 ms (de façon soutenu) est déjà considéré comme un problème de performances disques.
Selon la documentation de Microsoft (
ici), voici un tableau récapitulatif d'évaluation des performances des temps d'accès en lecture (via Performance counter: Avg.Disk Sec/Read).
Less than 10 ms - very good
Between 10 - 20 ms - okay
Between 20 - 50 ms - slow, needs attention
Greater than 50 ms – Serious I/O bottleneck
D'un autre côté, se concentrer sur les FileStats
sys.dm_io_virtual_file_stats() en même temps que les Wait Stats démontrera (1) combien de tentative d'écriture seront faite sur le Log file, (2) le nombre de bytes écrits, (3) combien de temps a été nécessaire.
Il est ainsi possible de mettre en relation une augmentation des waits avec une chute des opérations disques (bytes écrits) ou encore une brusque augmentation des IO_Stall (opérations IO retardée)
N'importe laquelle des actions suivantes réduira le temps d'attente du système I/O:
- Augmentation de la bande passante I/O.
- Load Balancing des I/O sur plusieurs disques.
- Placer le transaction Log sur son propre disque.
Plus d'informations ici:
Pour rappel, voici l'extraction des files stats:
select DB_NAME(database_id) DB_NAME, file_id,io_stall_read_ms ,num_of_reads
,cast(io_stall_read_ms/(1.0+num_of_reads) as numeric(10,1)) as 'avg_read_stall_ms'
,io_stall_write_ms,num_of_writes
,cast(io_stall_write_ms/(1.0+num_of_writes) as numeric(10,1)) as 'avg_write_stall_ms'
,io_stall_read_ms + io_stall_write_ms as io_stalls
,num_of_reads + num_of_writes as total_io
,cast((io_stall_read_ms+io_stall_write_ms)/(1.0+num_of_reads + num_of_writes) as numeric(10,1)) as 'avg_io_stall_ms'
from sys.dm_io_virtual_file_stats(null,null)
order by avg_io_stall_ms desc
