Discussion :

[Eskalix_]

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]

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_]

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_]

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_]

ç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]

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.

@++