Monitoring opóźnień – Dlaczego to trwa tak długo? [Wait stats]

Kolejne zgłoszenia w sprawie wolnego działania aplikacji? Integracja kolejny raz trwa za długo? W tym wszystkim CPU śpi przy tak niskim zużyciu, a dołożenie pamięci ucieszyło tylko na moment?

Niestety możemy spotkać wiele podobnych sytuacji, spowodowanymi nieznanymi nam przyczynami, czas by zastanowić się czy być może nie stoi za tym wszystkim zbyt długi czas oczekiwania. Część z nas doskonale to zna, nie raz napotkała dręczące zdarzenia wywołane przez CXPACKET czy LATCH_EX. Ilość rodzajów jakie możemy tutaj wymienić jest na prawdę ogromna,wszystko to kryje się pod płaszczem wait stats, czyli statystykami oczekiwania.

Warto jest dodać do naszej listy monitorowanych rzeczy właśnie ten kolejny wskaźnik, bowiem może nam sporo wyjaśnić w błędach jakie popełniamy podczas pisania procedur czy zapytań wykonywanych przez aplikację. W sieci krąży sporo sposobów na to, jednakże czy każde z nich w pełni nas zadowoli? Walka z długimi oczekiwaniami może okazać się mało wydajna, jeżeli nasze obserwacje będą szerokim łukiem mijać się z stanem rzeczywistym. Nawiązuję tutaj do badania poziomu opóźnień wzorując się na stanie bieżącym, w danej konkretnej chwili, czyli w momencie wykonania zapytania zwracającego wartość waits. Z mojego doświadczenia wiem, że najlepiej sprawdzi się tutaj mierzenie wartości poprzez cykle bazujące na co najmniej 1 minutowej próbie.

Pomocny w tym, może okazać się poniższy kod:

DECLARE @wait_start BIGINT
DECLARE @wait_end BIGINT
DECLARE @waits DECIMAL(12,6)
DECLARE @secs SMALLINT = 120
DECLARE @time_delay VARCHAR(15) = (SELECT CAST((@secs / 3600) AS VARCHAR(2)) + ':' + CAST((@secs / 60) AS VARCHAR(2)) + ':' + CAST((@secs % 60) AS VARCHAR(2)))

SELECT 
	@wait_start = SUM(wait_time_ms) OVER()
FROM sys.dm_os_wait_stats
WHERE
	wait_type NOT IN (
		N'BROKER_EVENTHANDLER'
		, N'BROKER_INIT'
		, N'BROKER_MASTERSTART'
		, N'BROKER_RECEIVE_WAITFOR'
		, N'BROKER_REGISTERALLENDPOINTS'
		, N'BROKER_SERVICE'
		, N'BROKER_SHUTDOWN'
		, 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_MUTEX'
		, N'DBMIRROR_EVENTS_QUEUE'
		, N'DBMIRRORING_CMD'
		, N'DIRTY_PAGE_POLL'
		, N'DISPATCHER_QUEUE_SEMAPHORE'
		, N'FT_IFTS_SCHEDULER_IDLE_WAIT'
		, N'FT_IFTSHC_MUTEX'
		, N'HADR_FILESTREAM_IOMGR_IOCOMPLETION'
		, N'KSOURCE_WAKEUP'
		, N'LAZYWRITER_SLEEP'
		, N'LOGMGR_QUEUE'
		, N'MISCELLANEOUS'
		, N'OGMGR_QUEUE'
		, N'ONDEMAND_TASK_QUEUE'
		, N'PARALLEL_BACKUP_QUEUE'
		, N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP'
		, N'QDS_PERSIST_TASK_MAIN_LOOP_SLEEP'
		, N'REQUEST_DISPENSER_PAUSE'
		, N'REQUEST_FOR_DEADLOCK_SEARCH'
		, N'RESOURCE_QUEUE'
		, N'SLEEP_BPOOL_FLUSH'
		, N'SLEEP_DBSTARTUP'
		, N'SLEEP_DCOMSTARTUP'
		, N'SLEEP_MSDBSTARTUP'
		, N'SLEEP_SYSTEMTASK'
		, N'SLEEP_TASK'
		, N'SLEEP_TEMPDBSTARTUP'
		, N'SP_SERVER_DIAGNOSTICS_SLEEP'
		, N'SQLTRACE_BUFFER_FLUSH'
		, N'SQLTRACE_INCREMENTAL_FLUSH_SLEEP'
		, N'TRACEWRITE'
		, N'WAITFOR'
		, N'XE_DISPATCHER_JOI'
		, N'XE_DISPATCHER_WAIT'
		, N'XE_TIMER_EVENT'
		, N'HADR_WORK_QUEUE'
		, N'HADR_FILESTREAM_IOMGR_IOCOMPLETION'
		, N'LOGMGR_QUEUE'
		, N'HADR_TIMER_TASK'
		, N'HADR_CLUSAPI_CALL'
		, N'HADR_LOGCAPTURE_WAIT'
		, N'QDS_SHUTDOWN_QUEUE'
		, N'HADR_NOTIFICATION_DEQUEUE'
		, N'CXCONSUMER'
		, N'PARALLEL_REDO_WORKER_WAIT_WORK'
		, N'PARALLEL_REDO_DRAIN_WORKER'
		, N'PARALLEL_REDO_LOG_CACHE'
		, N'PARALLEL_REDO_TRAN_LIST'
		, N'PARALLEL_REDO_WORKER_SYNC'
		, N'SOS_WORK_DISPATCHER'
		, N'QDS_ASYNC_QUEUE'
		, N'VDI_CLIENT_OTHER'
		, N'WAIT_XTP_OFFLINE_CKPT_NEW_LOG'
		, N'RESOURCE_GOVERNOR_IDLE'
		, N'PVS_PREALLOCATE'
		, N'HADR_FABRIC_CALLBACK'
		, N'PWAIT_EXTENSIBILITY_CLEANUP_TASK'
	)
	AND wait_time_ms > 0 AND waiting_tasks_count > 0

WAITFOR DELAY @time_delay

SELECT 
	@wait_end = SUM(wait_time_ms) OVER()
FROM sys.dm_os_wait_stats
WHERE
	wait_type NOT IN (
		N'BROKER_EVENTHANDLER'
		, N'BROKER_INIT'
		, N'BROKER_MASTERSTART'
		, N'BROKER_RECEIVE_WAITFOR'
		, N'BROKER_REGISTERALLENDPOINTS'
		, N'BROKER_SERVICE'
		, N'BROKER_SHUTDOWN'
		, 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_MUTEX'
		, N'DBMIRROR_EVENTS_QUEUE'
		, N'DBMIRRORING_CMD'
		, N'DIRTY_PAGE_POLL'
		, N'DISPATCHER_QUEUE_SEMAPHORE'
		, N'FT_IFTS_SCHEDULER_IDLE_WAIT'
		, N'FT_IFTSHC_MUTEX'
		, N'HADR_FILESTREAM_IOMGR_IOCOMPLETION'
		, N'KSOURCE_WAKEUP'
		, N'LAZYWRITER_SLEEP'
		, N'LOGMGR_QUEUE'
		, N'MISCELLANEOUS'
		, N'OGMGR_QUEUE'
		, N'ONDEMAND_TASK_QUEUE'
		, N'PARALLEL_BACKUP_QUEUE'
		, N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP'
		, N'QDS_PERSIST_TASK_MAIN_LOOP_SLEEP'
		, N'REQUEST_DISPENSER_PAUSE'
		, N'REQUEST_FOR_DEADLOCK_SEARCH'
		, N'RESOURCE_QUEUE'
		, N'SLEEP_BPOOL_FLUSH'
		, N'SLEEP_DBSTARTUP'
		, N'SLEEP_DCOMSTARTUP'
		, N'SLEEP_MSDBSTARTUP'
		, N'SLEEP_SYSTEMTASK'
		, N'SLEEP_TASK'
		, N'SLEEP_TEMPDBSTARTUP'
		, N'SP_SERVER_DIAGNOSTICS_SLEEP'
		, N'SQLTRACE_BUFFER_FLUSH'
		, N'SQLTRACE_INCREMENTAL_FLUSH_SLEEP'
		, N'TRACEWRITE'
		, N'WAITFOR'
		, N'XE_DISPATCHER_JOI'
		, N'XE_DISPATCHER_WAIT'
		, N'XE_TIMER_EVENT'
		, N'HADR_WORK_QUEUE'
		, N'HADR_FILESTREAM_IOMGR_IOCOMPLETION'
		, N'LOGMGR_QUEUE'
		, N'HADR_TIMER_TASK'
		, N'HADR_CLUSAPI_CALL'
		, N'HADR_LOGCAPTURE_WAIT'
		, N'QDS_SHUTDOWN_QUEUE'
		, N'HADR_NOTIFICATION_DEQUEUE'
		, N'CXCONSUMER'
		, N'PARALLEL_REDO_WORKER_WAIT_WORK'
		, N'PARALLEL_REDO_DRAIN_WORKER'
		, N'PARALLEL_REDO_LOG_CACHE'
		, N'PARALLEL_REDO_TRAN_LIST'
		, N'PARALLEL_REDO_WORKER_SYNC'
		, N'SOS_WORK_DISPATCHER'
		, N'QDS_ASYNC_QUEUE'
		, N'VDI_CLIENT_OTHER'
		, N'WAIT_XTP_OFFLINE_CKPT_NEW_LOG'
		, N'RESOURCE_GOVERNOR_IDLE'
		, N'PVS_PREALLOCATE'
		, N'HADR_FABRIC_CALLBACK'
		, N'PWAIT_EXTENSIBILITY_CLEANUP_TASK'
	)
	AND wait_time_ms > 0 AND waiting_tasks_count > 0
	
SELECT (@wait_end - @wait_start) / 1000.0 / @secs AS [WAITS_SEC_PER_SEC]

Uruchomienie skryptu i zbieranie danych w szerszej próbie czasowej przyniesie wyniki bliższe stanowi faktycznemu.