SQLServer
Collecting and Analyzing Wait events on SQL Server with Procedure and Agent job
Steve Lim
2017. 3. 18. 18:17
These days I'm digging into how to collect and analyze wait events on SQL Server database. So I simply have created a stored procedure to collect wait event information and have set it on SQL Agent job to run every 5 or 10 minutes. Then using same procedure with different parameter, I was able to get the analyzed wait event information. Also I reviewed Paul S. Randal's post (http://www.sqlskills.com/blogs/paul/wait-statistics-or-please-tell-me-where-it-hurts/) for this stored procedure. Thanks Paul.
After collecting wait event information, I can get meaningful data to troubleshoot database issues from here.
Here is the procedure code. Please let me know if you have any comment on this.
/*dba_WaitsCollecting_V1 =====================================================
File: dba_WaitsCollecting.sql
Summary: Collect Wait stats and session information
SQL Server Versions: 2005 onwards
------------------------------------------------------------------------------
1/17/2017 : Written by Steve Lim
------------------------------------------------------------------------------
Usage : -- Collecting information
[dbo].[dba_WaitsCollecting]
-- Analyzing information
[dbo].[dba_WaitsCollecting] 0, '2017-01-17 09:00:00', '2017-01-18 17:00:00'
============================================================================*/
CREATE PROCEDURE [dbo].[dba_WaitsCollecting]
@isCollect bit = 1 /* default : 1 (1: collect, 0: analyze) */
, @beginTime datetime = NULL /* default : getdate() - 1 */
, @endTime datetime = NULL /* default : getdate() */
AS
Set NoCount On;
Set XACT_Abort On;
Set Quoted_Identifier On;
IF ISNULL(OBJECT_ID('dba_WaitTasksCollected'),0) = 0 BEGIN
CREATE TABLE [dbo].[dba_WaitTasksCollected](
[Num] [int] IDENTITY(1,1) NOT NULL,
[TimeCollected] [nvarchar](24) DEFAULT(CONVERT(VARCHAR, GETDATE(), 112) + RIGHT('00' + CONVERT(VARCHAR,DATEPART(HOUR,GETDATE())),2) + RIGHT('00' + CONVERT(VARCHAR,DATEPART(MINUTE,GETDATE())),2)),
[SPID] [smallint] NULL,
[Thread] [int] NULL,
[Scheduler] [int] NULL,
[Wait_ms] [bigint] NULL,
[Wait_type] [nvarchar](60) NULL,
[Blocking_SPID] [smallint] NULL,
[Resource_description] [nvarchar](3072) NULL,
[Node_ID] [nvarchar](3072) NULL,
[DOP] [smallint] NULL,
[DBID] [smallint] NULL,
[Help_Info_URL] [XML] NULL,
[Query_plan] [XML] NULL,
[Text] [nvarchar](max) NULL,
CONSTRAINT [PK_WaitTasksCollected] PRIMARY KEY CLUSTERED
(
[Num] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY]
END
IF ISNULL(OBJECT_ID('dba_WaitsCollected'),0) = 0 BEGIN
CREATE TABLE [dbo].[dba_WaitsCollected](
[Num] [int] IDENTITY(1,1) NOT NULL,
[TimeCollected] [nvarchar](24) DEFAULT(CONVERT(VARCHAR, GETDATE(), 112) + RIGHT('00' + CONVERT(VARCHAR,DATEPART(HOUR,GETDATE())),2) + RIGHT('00' + CONVERT(VARCHAR,DATEPART(MINUTE,GETDATE())),2)),
[wait_type] [nvarchar](60) NOT NULL,
[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,
CONSTRAINT [PK_WaitsCollected] PRIMARY KEY CLUSTERED
(
[Num] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY]
END
BEGIN
IF @isCollect = 1 -- COLLECT
BEGIN
INSERT INTO dba_WaitTasksCollected ([SPID],[Thread],[Scheduler],[Wait_ms],[Wait_type],[Blocking_SPID]
,[Resource_description],[Node_ID],[DOP],[DBID],[Help_Info_URL],[Query_plan],[Text])
SELECT
[owt].[session_id] AS [SPID],
[owt].[exec_context_id] AS [Thread],
[ot].[scheduler_id] AS [Scheduler],
[owt].[wait_duration_ms] AS [Wait_ms],
[owt].[Wait_type],
[owt].[blocking_session_id] AS [Blocking_SPID],
[owt].[Resource_description],
CASE [owt].[Wait_type]
WHEN N'CXPACKET' THEN
RIGHT ([owt].[Resource_description],
CHARINDEX (N'=', REVERSE ([owt].[Resource_description])) - 1)
ELSE NULL
END AS [Node_ID],
[eqmg].[dop] AS [DOP],
[er].[database_id] AS [DBID],
CAST ('https://www.sqlskills.com/help/waits/' + [owt].[wait_type] as XML) AS [Help_Info_URL],
[eqp].[Query_plan],
[est].text as [Text]
FROM sys.dm_os_waiting_tasks [owt]
INNER JOIN sys.dm_os_tasks [ot] ON
[owt].[waiting_task_address] = [ot].[task_address]
INNER JOIN sys.dm_exec_sessions [es] ON
[owt].[session_id] = [es].[session_id]
INNER JOIN sys.dm_exec_requests [er] ON
[es].[session_id] = [er].[session_id]
FULL JOIN sys.dm_exec_query_memory_grants [eqmg] ON
[owt].[session_id] = [eqmg].[session_id]
OUTER APPLY sys.dm_exec_sql_text ([er].[sql_handle]) [est]
OUTER APPLY sys.dm_exec_query_plan ([er].[plan_handle]) [eqp]
WHERE
[es].[is_user_process] = 1
ORDER BY
[owt].[session_id],
[owt].[exec_context_id];
INSERT INTO dba_WaitsCollected ([wait_type],[waiting_tasks_count],[wait_time_ms],[max_wait_time_ms],[signal_wait_time_ms])
SELECT [wait_type],[waiting_tasks_count],[wait_time_ms],[max_wait_time_ms],[signal_wait_time_ms] FROM sys.dm_os_wait_stats;
END
IF @isCollect = 0 -- ANALYZE
BEGIN
CREATE TABLE #dba_WaitsDelta (
wait_type nvarchar(60) NULL,
WaitS bigint NULL,
ResourceS bigint NULL,
SignalS bigint NULL,
WaitCount bigint NULL,
Percentage int NULL,
RowNum smallint NULL,
TimeAnalyzed nvarchar(80) NULL
)
DECLARE @beginSnap NVARCHAR(24), @endSnap NVARCHAR(24);
DECLARE @beginTSnap NVARCHAR(24), @endTSnap NVARCHAR(24);
-- DECLARE @beginTime datetime, @endTime datetime;
IF @beginTime is NULL SELECT @beginTime = getdate() - 1;
IF @endTime is NULL SELECT @endTime = getdate();
SELECT @beginTSnap = CONVERT(VARCHAR, @beginTime, 112) + RIGHT('00' + CONVERT(VARCHAR,DATEPART(HOUR,@beginTime)),2) + RIGHT('00' + CONVERT(VARCHAR,DATEPART(MINUTE,@beginTime)),2)
SELECT @endTSnap = CONVERT(VARCHAR, @endTime, 112) + RIGHT('00' + CONVERT(VARCHAR,DATEPART(HOUR,@endTime)),2) + RIGHT('00' + CONVERT(VARCHAR,DATEPART(MINUTE,@endTime)),2)
SELECT @beginSnap = CONVERT(VARCHAR,MIN(TimeCollected)), @endSnap = CONVERT(VARCHAR,MAX(TimeCollected))
FROM [dbo].[dba_WaitsCollected]
WHERE TimeCollected between @beginTSnap and @endTSnap;
INSERT INTO #dba_WaitsDelta (wait_type, WaitS, ResourceS, SignalS, WaitCount, Percentage, RowNum, TimeAnalyzed)
SELECT ows1.wait_type as [wait_type]
, (ows2.wait_time_ms - ows1.wait_time_ms) / 1000.0 as [WaitS]
, ((ows2.wait_time_ms - ows1.wait_time_ms) - (ows2.signal_wait_time_ms - ows1.signal_wait_time_ms)) / 1000.0 as [ResourceS]
, (ows2.signal_wait_time_ms - ows1.signal_wait_time_ms) / 1000.0 as [SignalS]
, (ows2.waiting_tasks_count - ows1.waiting_tasks_count) as [WaitCount]
, 100.0 * (ows2.wait_time_ms - ows1.wait_time_ms) / SUM (ows2.wait_time_ms - ows1.wait_time_ms) OVER() as [Percentage]
--, (ows2.signal_wait_time_ms - ows1.signal_wait_time_ms) as [signal_wait_time_ms]
, ROW_NUMBER() OVER(ORDER BY (ows2.wait_time_ms - ows1.wait_time_ms) DESC) as [RowNum]
, ows1.TimeCollected + '-' + ows2.TimeCollected as TimeAnalyzed
FROM
(select ows.wait_type, ows.waiting_tasks_count, ows.wait_time_ms, ows.signal_wait_time_ms, ows.TimeCollected
from [dbo].[dba_WaitsCollected] ows
where ows.TimeCollected = (@beginSnap)
) ows1 inner join (
select ows.wait_type, ows.waiting_tasks_count, ows.wait_time_ms, ows.signal_wait_time_ms, ows.TimeCollected
from [dbo].[dba_WaitsCollected] ows
where ows.TimeCollected in (@endSnap)
) ows2 on ows1.wait_type = ows2.wait_type
WHERE ows1.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',
-- Maybe uncomment these four if you have mirroring issues
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',
-- Maybe uncomment these six if you have AG issues
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'MEMORY_ALLOCATION_EXT',
N'ONDEMAND_TASK_QUEUE',
N'PREEMPTIVE_XE_GETTARGETSTATE',
N'PWAIT_ALL_COMPONENTS_INITIALIZED',
N'PWAIT_DIRECTLOGCONSUMER_GETNEXT',
N'QDS_PERSIST_TASK_MAIN_LOOP_SLEEP', N'QDS_ASYNC_QUEUE',
N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEE', N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP',
N'QDS_SHUTDOWN_QUEUE', N'REDO_THREAD_PENDING_WORK',
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_RECOVERY',
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')
AND (ows2.waiting_tasks_count - ows1.waiting_tasks_count) > 0;
SELECT
MAX ([W1].[wait_type]) AS [WaitType],
CAST (MAX ([W1].[WaitS]) AS DECIMAL (16,2)) AS [Wait_S],
CAST (MAX ([W1].[ResourceS]) AS DECIMAL (16,2)) AS [Resource_S],
CAST (MAX ([W1].[SignalS]) AS DECIMAL (16,2)) AS [Signal_S],
MAX ([W1].[WaitCount]) AS [WaitCount],
CAST (MAX ([W1].[Percentage]) AS DECIMAL (5,2)) AS [Percentage],
CAST ((MAX ([W1].[WaitS]) / MAX ([W1].[WaitCount])) AS DECIMAL (16,4)) AS [AvgWait_S],
CAST ((MAX ([W1].[ResourceS]) / MAX ([W1].[WaitCount])) AS DECIMAL (16,4)) AS [AvgRes_S],
CAST ((MAX ([W1].[SignalS]) / MAX ([W1].[WaitCount])) AS DECIMAL (16,4)) AS [AvgSig_S],
CAST ('https://www.sqlskills.com/help/waits/' + MAX ([W1].[wait_type]) as XML) AS [Help/Info URL],
MAX(W1.TimeAnalyzed) as TimeAnalyzed
FROM #dba_WaitsDelta AS [W1]
INNER JOIN #dba_WaitsDelta AS [W2]
ON [W2].[RowNum] <= [W1].[RowNum]
GROUP BY [W1].[RowNum]
HAVING SUM ([W2].[Percentage]) - MAX( [W1].[Percentage] ) < 97; -- percentage threshold
DROP TABLE #dba_WaitsDelta;
END
END반응형