Collecting and Analyzing Wait events on SQL Server with Procedure and Agent job

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

Leave a Reply