Paramétrage des évènements étendus pour identifier la source de 'délai de verrou dépassé'

**Eskalix_** · 14/03/2017, 17h39

Bonjour.

Après la création et la mise en route d'une nouvelle base de données sur un nouveau serveur je rencontre de façon aléatoire des 'délai de verrou dépassé'.

Je cherche aujourd'hui à en trouver l'origine. Pour ce faire j'ai effectuer les recherches suivantes :
- j'ai paramétré le LOCK TIMEOUT à -1, 0, 10000, rien à faire l'erreur de produit toujours plusieurs fois par jour.
- J'ai activé les traces et le profiler SQL mais le détail des informations n'est ni très lisible ni suffisant pour identifier me semble t il le problème
- Je me suis penché sur les évènements étendus qui permettent avec plus de finesse de récupérer des informations.

Sur ce dernier point j'arrive à mettre en place une session dans les évènements étendus qui capture les évènements 'lock_deadlock' et 'lock_timeout'. Je peux tracer les requêtes SQL, les procédures, etc. sur lesquelles le timeout se déclenche, mais je n'arrive pas à identifier le point commun à tous ces timeout. Les possibilités sont tellement nombreuses que trouver le bon paramétrage n'est pas simple. ça fais déjà plusieurs jours que je creuse (pour ne pas dire que je m'enlise)

Si quelqu'un avait quelques éléments à me donner sur la façon de paramétrer les évènements étendus (qui sont très nombreux) afin de pouvoir identifier la source du problème, cela me serait d'un grand secours.

Par avance merci à ceux et/ou celles qui auraient des pistes à me proposer

Bonne journée à tous dans tous les cas

**elsuket** · 14/03/2017, 19h53

Bonjour,

Positionnez l'option d'instance blocked process threshold a 5 : c'esdt la fréquence à laquelle le moniteur de processus bloqué va se réveiller.

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
9
10
11
12
13
14
EXEC sp_configure 'show advanced options', 1
GO
RECONFIGURE
GO
 
EXEC sp_configure 'blocked process threshold', 5
GO
RECONFIGURE
GO
 
EXEC sp_configure 'show advanced options', 0
GO
RECONFIGURE
GO

Une fois fait, la session XE suivante devrait vous aider à y voir plus clair :

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
9
10
11
12
13
CREATE	EVENT SESSION [LockTimeout] ON SERVER 
ADD	EVENT sqlserver.lock_timeout_greater_than_0
	(
		SET COLLECT_DATABASE_NAME=1, COLLECT_RESOURCE_DESCRIPTION = 1	
		ACTION(sqlserver.sql_text)
	),
ADD	EVENT sqlserver.blocked_process_report
ADD	TARGET package0.ring_buffer
WITH	(
		EVENT_RETENTION_MODE = ALLOW_MULTIPLE_EVENT_LOSS
		, MEMORY_PARTITION_MODE = PER_NODE
	)
GO

Vous pouvez bien spûr changer la cible pour mettre un fichier.
Attention à ne pas filtrer par une base de données particulière : j'ai déjà vu des lock timeout se produire dans TempDB, en conflit avec le processus ghost cleanup.

N'hésitez pas à partager le document XML qui décrit la situation de blocage.

Bon courage et @++

**Eskalix_** · 16/03/2017, 17h01

Bonjour, et merci.

J'ai mis en place ces éléments. Le temps d'avoir les premiers rapports et je reviens pour vous informer si j'ai pu identifier le problème. Sinon je m'efforcerai de compléter avec le xml et d'autres infos si nécessaire. Encore merci du coup de main

**Eskalix_** · 17/03/2017, 09h00

Bonjour. Je vois des lock_timeout dans les événements étendus que je surveille, mais pas de rapport de bloquage. L'événement blocked_process_report ne semble jamais se déclencher bizarrement.

D'après ce que je lis, blocked_process_report génère un rapport XML lorsque une tâche est bloquée, ce qui est en partie mon cas lorsqu'un verrou est posé trop longtemps sur un enregistrement ou un objet, et que la tâche ou l'application ne peut plus s'exécuter correctement. Les utilisateurs ont à ce moment là un message d'erreur. Bien entendu, maintenant que j'ai mis vos recommandations en place, je n'ai plus de délai de verrou dépassé

... pour le moment...

Cependant je vois que se produit régulièrement sur le serveur des lock_timeout, lié à des clés (KEY) ou des objets. J'aurai bien aimé pouvoir analyser d'où viennent ces lock_timeout. Existe-t-il un moyen de relever une information complète sur "qui bloque quoi" ? Aujourd'hui je n'ai accès qu'à ces infos :
associated_object_id 562949955649536
database_id 2
database_name
duration 0
lockspace_nest_id 1
lockspace_sub_id 1
lockspace_workspace_id 9571862240
mode X
object_id 0
owner_type Transaction
resource_0 34
resource_1 2292842498
resource_2 1270557162
resource_description
resource_type KEY
transaction_id 37274481

Du coup j'ai acheté un joli pavé de 1300 pages "SQL Server 2014" dont j'ai dévoré un peu plus de 200 pages pour comprendre comment tout ça s'articulait, mais le chemin vers la connaissance prends du temps...

Merci

**Eskalix_** · 17/03/2017, 10h48

ça y est, j'ai un des utilisateurs qui a eu un blocage, l'événement lock_timeout_greater_than_0 s'est déclenché, mais aucun rapport en vu sur l'événement blocked_process_report qui ne se manifeste pas du tout. Aurais-je raté une étape ?

Je poursuis mes recherches pour trouver la source.

Bonne journée

**elsuket** · 17/03/2017, 14h35

database_id 2

La base de données de database_id 2 est TempDB.
C'est une base de données système qui stocke les résultats intermédiaires des tris et regroupements, des spools, et supporte certaines jointures dans des cas particuliers, mais aussi les tables temporaires et les variables de type TABLE.
Il est donc possible que vous ayez de la contention d'accès aux pages qui tracent l'allocation des pages si un grand nombre d'objets sont crées puis supprimés fréquemment.

De combien de fichiers et de processeurs logiques dispose la machine qui exécute SQL Server ?

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

1
2
3
4
5
6
7
8
9
10
11
SELECT		COUNT(*) AS logical_core_count
		, T.data_file_count
FROM		sys.dm_os_schedulers AS S
CROSS APPLY	(
			SELECT	COUNT(*) AS data_file_count
			FROM	sys.master_files AS MF
			WHERE	MF.database_id = 2
			AND	MF.type_desc = 'ROWS'
		) AS T
WHERE		S.scheduler_id < 255
GROUP BY	T.data_file_count

Quels sont les principaux types d'attente de votre instance ?

Code :

Sélectionner tout - Visualiser dans une fenêtre à part

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
WITH
	WAIT AS
	(
		SELECT	wait_type
			, wait_time_ms / 1000.0 AS wait_s
			, (wait_time_ms - signal_wait_time_ms) / 1000.0 AS resource_wait_time_s
			, signal_wait_time_ms / 1000.0 AS signal_wait_time_s
			, waiting_tasks_count
			, 100.0 * wait_time_ms / SUM (wait_time_ms) OVER() AS percentage
			, ROW_NUMBER() OVER(ORDER BY wait_time_ms DESC) AS n
		FROM	sys.dm_os_wait_stats
		WHERE	wait_type NOT IN
			(
				N'BROKER_EVENTHANDLER', N'BROKER_RECEIVE_WAITFOR', N'BROKER_TASK_STOP', N'BROKER_TO_FLUSH',
				N'BROKER_TRANSMITTER', N'CHECKPOINT_QUEUE', N'CHKPT', N'CLR_AUTO_EVENT',
				N'CLR_MANUAL_EVENT', N'CLR_SEMAPHORE', N'DBMIRROR_DBM_EVENT', N'DBMIRROR_EVENTS_QUEUE',
				N'DBMIRROR_WORKER_QUEUE', N'DBMIRRORING_CMD', N'DIRTY_PAGE_POLL', N'DISPATCHER_QUEUE_SEMAPHORE',
				N'EXECSYNC', N'FSAGENT', N'FT_IFTS_SCHEDULER_IDLE_WAIT', N'FT_IFTSHC_MUTEX',
				N'HADR_CLUSAPI_CALL', N'HADR_FILESTREAM_IOMGR_IOCOMPLETION', N'HADR_LOGCAPTURE_WAIT', N'HADR_NOTIFICATION_DEQUEUE',
				N'HADR_TIMER_TASK', N'HADR_WORK_QUEUE', N'KSOURCE_WAKEUP', N'LAZYWRITER_SLEEP',
				N'LOGMGR_QUEUE', N'ONDEMAND_TASK_QUEUE', N'PWAIT_ALL_COMPONENTS_INITIALIZED',
				N'QDS_PERSIST_TASK_MAIN_LOOP_SLEEP', N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP',
				N'REQUEST_FOR_DEADLOCK_SEARCH', N'RESOURCE_QUEUE', N'SERVER_IDLE_CHECK', N'SLEEP_BPOOL_FLUSH',
				N'SLEEP_DBSTARTUP', N'SLEEP_DCOMSTARTUP', N'SLEEP_MASTERDBREADY', N'SLEEP_MASTERMDREADY',
				N'SLEEP_MASTERUPGRADED', N'SLEEP_MSDBSTARTUP', N'SLEEP_SYSTEMTASK', N'SLEEP_TASK',
				N'SLEEP_TEMPDBSTARTUP', N'SNI_HTTP_ACCEPT', N'SP_SERVER_DIAGNOSTICS_SLEEP', N'SQLTRACE_BUFFER_FLUSH',
				N'SQLTRACE_INCREMENTAL_FLUSH_SLEEP', N'SQLTRACE_WAIT_ENTRIES', N'WAIT_FOR_RESULTS',
				N'WAITFOR', N'WAITFOR_TASKSHUTDOWN', N'WAIT_XTP_HOST_WAIT', N'WAIT_XTP_OFFLINE_CKPT_NEW_LOG',
				N'WAIT_XTP_CKPT_CLOSE', N'XE_DISPATCHER_JOIN', N'XE_DISPATCHER_WAIT', N'XE_TIMER_EVENT', N'QDS_SHUTDOWN_QUEUE'
			)
		AND	waiting_tasks_count > 0
 )
SELECT		MAX (W1.wait_type) AS WaitType
		, CAST (MAX (W1.wait_s) AS decimal (16,2)) AS wait_s
		, CAST (MAX (W1.resource_wait_time_s) AS decimal (16,2)) AS resource_wait_time_s
		, CAST (MAX (W1.signal_wait_time_s) AS decimal (16,2)) AS signal_wait_time_s
		, MAX (W1.waiting_tasks_count) AS waiting_tasks_count
		, CAST (MAX (W1.percentage) AS decimal (5,2)) AS percentage
		, CAST ((MAX (W1.wait_s) / MAX (W1.waiting_tasks_count)) AS decimal (16,4)) AS avg_wait_time_s
		, CAST ((MAX (W1.resource_wait_time_s) / MAX (W1.waiting_tasks_count)) AS decimal (16,4)) AS avg_resource_wait_time_s
		, CAST ((MAX (W1.signal_wait_time_s) / MAX (W1.waiting_tasks_count)) AS decimal (16,4)) AS avg_signal_wait_time_s
FROM		WAIT AS W1
INNER JOIN	WAIT AS W2
			ON W2.n <= W1.n
GROUP BY	W1.n
HAVING		SUM (W2.Percentage) - MAX (W1.Percentage) < 95; -- percentage threshold
GO

Si vous venez à partager le résultat de cette requête, faites une capture d'écran du résultat SVP : un copier-coller des valeurs est illisible.

@++

**Eskalix_** · 17/03/2017, 15h08

La base de données de database_id 2 est TempDB.
C'est une base de données système qui stocke les résultats intermédiaires des tris et regroupements, des spools, et supporte certaines jointures dans des cas particuliers, mais aussi les tables temporaires et les variables de type TABLE.
Il est donc possible que vous ayez de la contention d'accès aux pages qui tracent l'allocation des pages si un grand nombre d'objets sont crées puis supprimés fréquemment.

WAHOU !!! ça c'est ce qu'on appelle "envoyer du bois" en terme d'explications, mais ok, j'ai compris :p

Voici les résultats des 2 requêtes.

R1 : 4 et 4

R2 :
WaitType : ASYNC_NETWORK_IO
wait_s : 6116984.03
resource_wait_time_s : 6115188.57
signal_wait_time_s : 1795.46
waiting_tasks_count : 3798587
percentage : 99.07
avg_wait_time_s : 1.6103
avg_resource_wait_time_s : 1.6099
avg_signal_wait_time_s : 0.0005

et la copie d'écran de la dernière requête :
Nom : Screen Shot 03-17-17 at 03.13_PM.PNG
Affichages : 334
Taille : 10,1 Ko

Nom : Screen Shot 03-17-17 at 03.13_PM.PNG
Affichages : 334
Taille : 10,1 Ko

Encore merci de votre aide

**Eskalix_** · 21/03/2017, 14h56

Bonjour. Je poursuis mes recherches. J'ai tenté de modifier le LOCK_TIMEOUT en l'augmentant mais rien à faire, l'application devient inutilisable. Les délais de verrous se multiplie. J'ai pensé à changer le mode d'isolation de la base pour résoudre le problème, mais ça me semble plus une solution de contournement qu'une véritable réponse à ma problématique de fond. Par avance merci si vous juste un axe de recherche pour m'orienter dans mes investigations

.

**SQLpro** · 22/03/2017, 14h33

Un problème aussi proéminent d'ASYNC_NETWORK_IO montre que votre réseau est incapable d'absorber la charge du résultat des requêtes qu'envoie le serveur SQL. En d'autres termes, le réseau est hyper lent...
Il n'y a donc rien à faire du côté de SQL Server mais plusieurs solutions à envisager :
1) identifier le coupable dans votre réseau. Cela peut être la carte réseau du serveur, un équipement intermédiaire (hub ou switch), les cartes réseaux des postes de travail.
2) diminuer la volumétrie des résultats. Au lieu d'envoyer toutes les données n'envoyer que quelques lignes et quelques colonnes.

A +

**Eskalix_** · 22/03/2017, 14h36

Bonjour, et merci. Je vois que vous êtes un des auteurs du livre que j'ai acheté "SQL Server 2014", c'est assez marrant. Ok je vais regarder de ce côté merci. Je vous tiens au courant pour info si je trouve d'où ça vient.

**SQLpro** · 22/03/2017, 14h50

Envoyé par Eskalix_

.... c'est assez marrant. ...

Comment ça c'est marrant !!!

SQL Server c'est du sérieux ! On ne plaisante pas !!! Non de Zeus !!!
http://bigbrowser.blog.lemonde.fr/fi...09/retour2.jpg

A +

**janlouk** · 22/03/2017, 14h55

Envoyé par Eskalix_

c'est assez marrant

Attention, sur le forum, il faut être gentil avec Frédéric car il peut vite s'énerver.

Mais dans la vraie vie, il est tout le contraire

**elsuket** · 24/03/2017, 00h54

Effectivement vous avez 1.6 secondes d'attente réseau en moyenne : 6 116 984.03 / 3 798 587. C'est assez catastrophique.
Pourriez-vous nous dire depuis quand l'instance SQL Server est démarrée svp ? SELECT sqlserver_start_time FROM sys.dm_os_sys_info
Que donne la session d'événements étendus ?

@++

**Eskalix_** · 24/03/2017, 07h31

Malheureusement le serveur a été redémarré le 19 de ce mois, je ne peux donc pas vous dire au moment des précédentes infos fournies, depuis combien de temps le serveur était up. Nous consultons aujourd'hui un dba qui va tenter de trouver la source de notre problème. Malgré mes efforts, impossible d'identifier avec certitude la source du problème.

**SQLpro** · 24/03/2017, 09h51

Envoyé par Eskalix_

Malheureusement le serveur a été redémarré le 19 de ce mois, je ne peux donc pas vous dire au moment des précédentes infos fournies, depuis combien de temps le serveur était up. Nous consultons aujourd'hui un dba qui va tenter de trouver la source de notre problème. Malgré mes efforts, impossible d'identifier avec certitude la source du problème.

Comme déjà dit, c'est visiblement le réseau qui pose problème et cela n'est pas du tout du ressort de SQL Server.

Votre DBA ne servira donc à rien.

Faite venir un spécialiste système et réseau afin de procéder à une analyse des trames !

A +

**elsuket** · 24/03/2017, 14h32

Malheureusement le serveur a été redémarré le 19 de ce mois, je ne peux donc pas vous dire au moment des précédentes infos fournies, depuis combien de temps le serveur était up

Pas de problème. Dans ce cas, ré-exécutez la 2e requête de mon post du 17 Mars, et voyez comment cela a évolué.
Si le serveur a redémarré le 19, c'est certainement pour l'application des patchs Windows : avec un peu de chance, le pilote des cartes (virtuelles ?) réseau a été mis à jour et est plus performant

@++

Paramétrage des évènements étendus pour identifier la source de 'délai de verrou dépassé'

Administration SQL Server

Discussions similaires

Partager

Partager