jeudi 14 mai 2009

SQL Server Monitoring Performance - Wait Stats

Une question pertinente

Dans le cadre de mon travail, nous avons nos DB de productions stockées sur un iSCSI vault.
La question que je me suis déjà posé: C'est qu'arrive t'il si la DB n'est pas accessible (délai, latence, etc)?
Même plus précisément, qu'arrivera t'il si Sql Server s'il n'est pas capable d'écrire facilement dans son log file (voir pas du tout)?
Personnellement , je soupçonne même que la DB de devenir non opérationelle (time-out lors que l'insertion d'enregistrement). Cependant, en informatiques, les soupçons ne me suffisant pas! Je vais donc m'efforcer de prouver les propos. 


Pour tester ce cas de figure, je vais utiliser trois outils:
  1. Un disque dur externe USB .
  2. IOMeter, un outil OpenSource d'Intel. A l'aide de ce dernier il sera possible de stresser les access disques et de voir comment SQL server se comportera.
  3. Les WaitStats stored procedures (décrites plus loin).
WaitStats procedures 
Voici deux stored procedures issus de l'article SQL Server Wait Events repris dans les réferences.
Ces dernières permettent d'analyser les waits times SQL depuis "dynamic management views".
La première procédure Begin_WaitStats prend une première image de référence des statistiques. Cette opération précède généralement l'évènement à monitorer.
La seconde procédure End_WaitStats prend une seconde image des statisitiques (après l'événement à monitorer) et effectuer une analyse comparative des informations.
La lecture de l'article permettra de faire une analyse correcte des résultats produits par End_WaitStats.
Ressources:
IOMeter
IOMeter est un outil open source d'intel. Ce dernier permet de tester les capacités de périphériques comme des disques durs ou des cartes réseaux.
Dans notre cas, nous allons utiliser IOMeter pour charger les access sur le disque dur externe.
 
La configuration utilisée est disponible ici (fichier icf)


Configuration du test

Dans l'exemple qui me concerne, je vais placer mon Transaction Log sur un lecteur USB. Ce qui me permettra de stresser l'accès au transaction Log tout en maintenant un débit normal sur le disque dur local.
Le moteur SQL pourra ainsi accéder librement à ses données.
Le lecteur USB sera chargé en utilisant IOMeter. Et durant cette période de stress, le script suivant sera utilisé pour monitorer les WaitStats lors de la solicitation du Transaction Log.
Script Ajoutant des données dans le transaction log
The script that is used to modify the data (insert 25000 audit trail records).

set nocount ON
EXECUTE begin_waitstats
go

 BEGIN TRANSACTION
 DECLARE @rows INT
 DECLARE @row INT
 DECLARE @count INT

 SELECT @rows = 2500
 SELECT @row = 0
 SELECT @count = 0
 WHILE @row < @rows
 BEGIN
        INSERT INTO tblSSAudit
                (
                ID_ObjectType,
                ID_ObjectInstance,
                ID_Person,
                Audit_Date,
                FieldsValue,
                Audit_Comment
                )
                VALUES
                        (
                        -1,
                        @count,
                        -999,
                        getDate(),
                        'StressTest',
                        REPLICATE('a',100)
                        )
        SELECT @row = @row + 1
        IF @count > 100
     BEGIN
         COMMIT WORK
         BEGIN TRANSACTION
         SELECT @count=0
     END
     SELECT @count=@count+1
 END
 COMMIT WORK
go
EXECUTE end_waitstats
go
Exécution du test
Test 1 - Sans stresser l'access au Transaction Log (stocké sur le drive USB)
The transaction log est accessible librement sur le lecteur USB.
Aucun processus externe ne vient entraver l'access au transaction log.
wait_type                                                    waits                wait_time            signal_wait_time     elapsed_time

------------------------------------------------------------ -------------------- -------------------- -------------------- -----------------------
PAGEIOLATCH_SH                                                                  4                   79                    0 1900-01-01 00:00:03.483
PAGEIOLATCH_UP                                                                  2                   32                    0 1900-01-01 00:00:03.483
PAGEIOLATCH_EX                                                                330                 2657                    0 1900-01-01 00:00:03.483
SLEEP_BPOOL_FLUSH                                                             230                 1437                    0 1900-01-01 00:00:03.483
WRITELOG                                                                       10                   47                   15 1900-01-01 00:00:03.483
session_id cpu_time             tot_sched_time elapsed_time PIO                  writes               LIO
---------- -------------------- -------------- ------------ -------------------- -------------------- --------------------
        51                  735            782         3565                  335                  457                    0
Le test s'est ici executé en 3.5 secondes.
L'écriture dans le log (WRITELOG) à créé un delai d'attente de 47 ms.
La plupart du temps étant perdu dans les accès disques (PAGEIO).
Plusieurs tests consécutifs on démontrés que le temps d'exécution du script (elapsed_time) variait entre 2.1 et 6 secondes.

Test 2 - Test stressant le libre accès au transaction log (stocké sur le Drive USB)
Utiliser le logiciel IOMeter (fichier de config ici) pour stresser les access disques du lecteur USB (le lecteur stockant le transaction log).
Pour les conditions du test, le lecteur USB est chargé avec1700 accès à la seconds (et une charge ridicule de 1 à 16 Mb/S car le débit n'est pas le facteur bloquant).
wait_type                                                    waits                wait_time            signal_wait_time     elapsed_time
------------------------------------------------------------ -------------------- -------------------- -------------------- -----------------------
LATCH_EX                                                                        3               843532                    0 1900-01-01 00:19:06.707
PAGEIOLATCH_SH                                                                  1                  218                    0 1900-01-01 00:19:06.707
PAGEIOLATCH_UP                                                                  3                92172                    0 1900-01-01 00:19:06.707
PAGEIOLATCH_EX                                                                  2                   16                    0 1900-01-01 00:19:06.707
IO_COMPLETION                                                                   9               358938                    0 1900-01-01 00:19:06.707
SLEEP_BPOOL_FLUSH                                                            1800                 9766                    0 1900-01-01 00:19:06.707
SOS_SCHEDULER_YIELD                                                            44                   16                   16 1900-01-01 00:19:06.707
WRITELOG                                                                        6                73625                   16 1900-01-01 00:19:06.707
LOGBUFFER                                                                       5               505203                    0 1900-01-01 00:19:06.707
LOGMGR_RESERVE_APPEND                                                           2                 2000                    0 1900-01-01 00:19:06.707
session_id cpu_time             tot_sched_time elapsed_time PIO                  writes               LIO
---------- -------------------- -------------- ------------ -------------------- -------------------- --------------------
        51                  172         404720      1146889                    7                  133                    0
Dans le de ce test, le temps d'execution est de 1146889 ms (soit 19 minutes).
La plupart du temps est perdu dans des LATCH_EX (14 min), IO_COMPLETION (14 min) et LOGBUFFER (8 min 30 sec).

ces tests démontrent bien l'importance des temps d'accès et de la disponibilité du disque dur stockant le transaction log. Toute opérations entravant l'accès au Transaction Log a une répercusion importante sur le temps de réponse SQL.

Note 1: Blocage en cascade et blocage de "select"
A une exception général près, toutes les opérations de lecture dans les tables de la DB ne sont pas affectées par ce "blocage" du transaction log.
L'exception apparaissant comme suit: si l'opération de lecture (select count(*) from myUsers) couvre une mise-à-jour en attente dans le transaction log (update myUser set Active=0 where idUser=125), dans ce, l'opération de lecture sera elle aussi mise "en attente". Cette "attente" sera résolue lorsque l'operation "update" sera enregistrée dans le transaction log.

Mise en place d'un monitoring des WaitStats
L'exemple précédent démontre que les Wait Time (Wait Statistics) sont des informations de premier plan pour déterminer la cause de problèmes.
Lorsque la situation critique peut être causée sur demande, l'utisation de scripts ou des stored procedure ne cause évidemment aucun problème.
Cependant, si le problème apparait de manière sporadique et sans signe annociateurs, il convient alors de collecter régulièrement ces statistiques de façon automatique et de les stocker de façon permanente (dans une DB).


Utilisation d'une machine de monitoring séparée
Dans les précédents exemple, il a été démontré que certains problèmes particulier (entre autre le libre accès aux ressources/disques) peut représenter une entrave majeure au bon fonctionnement de SQL serveur.
Dans de tel cas de figure, il ne serait pas opportun d'utiliser une DB sur le même serveur pour monitorer et stoquer les WaitStats.
Dans ce cas de figure l'utilisation d'un second serveur SQL avec un Profiler et le service SQLAgent est tout a fait approprié.


Créer la DB "MonitorWaits"
Créer la DB "MonitorWaits" sur la machine de monitoring.
Cette DB ne collectera par énorment d'information (en terme de quantité), cette DB n'a donc pas besoin d'être très grosse (quelques MB suffisent amplement).
--- Wait Monitor Toolbox -----------------------------------------
--
-- This SQL will create the needed table to store the monitoring
--   records
--
use MonitorWaits
go
create table WaitSessionMonitor ( SessionID int identity, CaptureTime DateTime not null )
go
Create table WaitCapture( SessionID int not null, Wait_Type varchar(60), Waiting_tasks_count bigint not null, Wait_time_ms bigint not null, max_wait_time_ms bigint not null, signal_wait_time_ms bigint not null)
go

Créer les tables nécessaires
use MonitorWaits go create table WaitSessionMonitor ( SessionID int identity, CaptureTime DateTime not null ) go Create table WaitCapture( SessionID int not null, Wait_Type varchar(60), Waiting_tasks_count bigint not null, Wait_time_ms bigint not null, max_wait_time_ms bigint not null, signal_wait_time_ms bigint not null) go

Lier le server de monitoring au server de production:
Cela permettra au script (ci-dessous) d'effectuer les requêtes SQL dans la table Sys.dm_os_wait_stats du serveur de production.
A l'aide du management console, créer un "Linked Server" vers le serveur de production.
 
Préparer et configurer le script de capture tel que celui-ci:
declare @ID int
insert into monitorwaits..WaitSessionMonitor ( CaptureTime ) 
  values ( getdate() )
select @ID = SCOPE_IDENTITY()

insert WaitCapture 
SELECT @id, wait_type, waiting_tasks_count, wait_time_ms, 
  max_wait_time_ms, signal_wait_time_ms 
FROM DBPRODUCTION.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%'
Ce script sera éxécuté par un Job Sql depuis la machine de monitoring toutes les minutes.
Afin d'éviter les surprises, une date de fin sera programmée sur le job (afin que celui-ci ne fonctionne pas des années durant s'il est oublié). 

Analyse des informations
Le script WaitMonitorCompute.sql suivant permet de d'extraire des information pertinentes depuis les statistiques collectées.
Ce script manipulera les statistiques et stockera les résultats dans la table ComputedWaits. 
Les variables  @SessionStart et @SessionEnd permettent de restreindre le champs de l'analyse des statistiques collectées. Ces variables recoivent les valeurs de SessionID qui peuvent être retrouvée dans la table WaitSessionMonitor.
--- Wait Monitor Toolbox -----------------------------------------
--
-- This SQL will compute the content of the WaitCapture table and
--   produce the results into the table ComputedWaits
--
use MonitorWaits
go

DECLARE @SessionStart int
DECLARE @SessionEnd int

SELECT @SessionStart = -1 -- Use -1 to start to very first entry
SELECT @SessionEnd = -1 -- use -1 to end at very last entry

if not exists (select 1 
               from sys.objects 
               where object_id = object_id ( N'[dbo].[waitSessionMonitor]') and 
               OBJECTPROPERTY(object_id, N'IsUserTable') = 1)
begin
  raiserror ('Missing [waitSessionMonitor] table. Execute script WaitMonitorCreateTables.sql!',16,1) with nowait    
end

if not exists (select 1 
               from sys.objects 
               where object_id = object_id ( N'[dbo].[WaitCapture]') and 
               OBJECTPROPERTY(object_id, N'IsUserTable') = 1)
begin
  raiserror ('Missing [WaitCapture] Table. Execute script WaitMonitorCreateTables.sql!',16,1) with nowait    
end

if exists (select 1 
           from sys.objects 
           where object_id = object_id ( N'[dbo].[ComputedWait]') and 
           OBJECTPROPERTY(object_id, N'IsUserTable') = 1)
  EXEC( 'drop table [dbo].[ComputedWait]' )

CREATE TABLE [dbo].[ComputedWait] (
  SessionID bigint not null,
  CaptureTime datetime not null,
  Wait_Type varchar(60) not null,
  Waits bigint not null,
  Wait_time_ms bigint not null,
  TimePerWait_ms decimal(7,3) default 0
)

if @SessionStart < 0 
  select @SessionStart = min( SessionID ) from WaitSessionMonitor
if @SessionEnd < 0
select @SessionEnd = max( SessionID ) from WaitSessionMonitor

declare @CurrentID int
select @CurrentID = @SessionStart
while ( @CurrentId < @SessionEnd ) -- Cannot process the last entry 
begin
  print 'Processing SessionID '+ cast( @CurrentID as Varchar(15) )
  insert [dbo].[ComputedWait] ( SessionID, CaptureTime, Wait_Type, Waits, Wait_time_ms )
  select 
    v1.SessionID, 
    sess.CaptureTime, 
    v1.Wait_Type, 
    v2.Waiting_Tasks_count - v1.Waiting_Tasks_Count as Waits,
    v2.Wait_Time_ms - v1.Wait_Time_ms as WaitTime
  from WaitCapture v2
    left join WaitCapture v1 on v1.SessionID=@CurrentID and v1.Wait_type = v2.Wait_Type
    left join WaitSessionMonitor sess on sess.SessionID = @CurrentID
  where V2.SessionID = @CurrentId+1

  select @CurrentID = @CurrentID + 1
end

update [dbo].[ComputedWait]
set TimePerWait_ms = Wait_time_ms / Waits 
where waits > 0

--
-- Display informations about the computed range
--
select SessionID as SessionID_Range, min(CaptureTime) as CaptureTime_Range
from [dbo].[ComputedWait] 
where SessionID in (
  select min(SessionID) from [dbo].[ComputedWait] 
  UNION
  select max(SessionID) from [dbo].[ComputedWait]
)
group by SessionID

-- 
--  Display statisitical information about the computed range
--
select Wait_Type, count(*) as NumberOfCaptures, sum( Waits ) as TotalOfWaits, sum(Wait_time_ms) / 1000 as TotalWaitTimeInSec  
from ComputedWait
where TimePerWait_ms > 0 
group by Wait_Type 

Exemple de résultat

Voici un exemple de résultat produit par le script WaitMonitorCompute.sql, le tout extrait d'un récent monitoring.
Dans ce dernier exemple, il apparait que SQL server à attendu un total de 21 secondes pour des PAGEIOLATCH_SH. Il semblerait donc évident qu'il existe, dans ce cas, un problème d'accès disque.

Par la suite, une requête sur la table ComputedWait permet de mettre en lumière (dans le temps) le phénomène de congestion d'accès disques.
SELECT * FROM ComputedWait 
where Wait_Type like 'PAGEIOLATCH%'
Qui produira le résultat suivant:
SessionID CaptureTime              WaitType       Waits Wait_Time_ms TimePerWait_ms 
4193    2009-05-11 16:57:02.810    PAGEIOLATCH_NL    0         0     0.000
4193    2009-05-11 16:57:02.810    PAGEIOLATCH_KP    0         0     0.000
4193    2009-05-11 16:57:02.810    PAGEIOLATCH_SH    275    3844     13.000
4193    2009-05-11 16:57:02.810    PAGEIOLATCH_UP    0         0     0.000
4193    2009-05-11 16:57:02.810    PAGEIOLATCH_EX    0         0     0.000
4193    2009-05-11 16:57:02.810    PAGEIOLATCH_DT    0         0     0.000
4194    2009-05-11 16:58:01.780    PAGEIOLATCH_NL    0         0     0.000
4194    2009-05-11 16:58:01.780    PAGEIOLATCH_KP    0         0     0.000
4194    2009-05-11 16:58:01.780    PAGEIOLATCH_SH    297    5359     18.000
4194    2009-05-11 16:58:01.780    PAGEIOLATCH_UP    0         0     0.000
4194    2009-05-11 16:58:01.780    PAGEIOLATCH_EX    37      234     6.000
4194    2009-05-11 16:58:01.780    PAGEIOLATCH_DT    0         0     0.000
4195    2009-05-11 16:59:01.780    PAGEIOLATCH_NL    0         0     0.000
4195    2009-05-11 16:59:01.780    PAGEIOLATCH_KP    0         0     0.000
4195    2009-05-11 16:59:01.780    PAGEIOLATCH_SH    234   12235     52.000
4195    2009-05-11 16:59:01.780    PAGEIOLATCH_UP    0         0     0.000
4195    2009-05-11 16:59:01.780    PAGEIOLATCH_EX    34      219     6.000
4195    2009-05-11 16:59:01.780    PAGEIOLATCH_DT    0         0     0.000

Reset des WaitStats
Le contenu de ce point n'a pas encore été vérifié.
Certaines Wait statistiques ne sont pas forcement resetée (par exemple, si elle font parties d'une queue de traitement).
Executer la commande suivante puis attendre 5 secondes.

DBCC sqlperf ('sys.dm_os_wait_stats', clear)

Ressources et Références

Aucun commentaire: