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:
- Un disque dur externe USB .
- 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.
- Les WaitStats stored procedures (décrites plus loin).
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 testTest 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 0Le 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 0Dans 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) goCréer les tables nécessairesuse 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.
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
- Les différents script de capture décrits dans cet article sont accessibles dans l'archive DomeuWaitMonitor.zip.
- Les scripts relatifs à la session de test du blocage du fichier Transaction Log sont disponibles ici: Begin_WaitStats.sql et End_WaitStats.sql
- Article "SQL Server Wait Events: Taking the Guesswork out of Performance Profiling" (copie ici).
- IOMeter est un outils OpenSource d'Intel permettant de mesurer et stresser les périhpériques.
- Article de l'équipe SQLOS de Microsoft relatif à l'extraction des WaitStats par sessions (SQL 2008).
- Article de Microsoft: Trouble Shooting Performances in SQL2005.
Aucun commentaire:
Enregistrer un commentaire