Using Extended Events to Find Statement Causing a Job to Run Long or Hang

On one of the servers that we monitor, it was reported that periodically a specific job would seem to hang and take forever to complete.  I was asked to set up something to help find exactly what statement in the job that was the root cause of the hang. 

Since the issue only occurred intermittently, I needed to collect data every day until we could catch the job hang in action.  I decided to use extended events since the overhead of the collection would be minimal and I can limit the number and size of the files generated.  Since this is a very busy system, I also wanted to only catch statements sent by this specific job which meant that I needed to figure out how to set up a filter for the events that would capture all job steps that were run.  The challenge in setting the filter is that a job when running shows up as hex in sqlserver.client_app_name in extended events.

SQLAgent – TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 1)

I know that we can get the job name from the hex…..  Query to Get SQL Job Info from sysprocesses – SQLRx  …..but since my job has 11 steps I wanted something that would generate the filter I needed for all steps.

After doing a little more research I found that Jonathan Kehayias had done something similar to what I wanted but had been looking for waits.  Tracking Extended Events for a SQL Agent Job – Jonathan Kehayias (sqlskills.com)  Since imitation is the best form of flattery, I came up with my version of setting up an extended events session but wanted to collect both starting and completed events so that I could catch the exact statement if it either took a long time to complete or if it was started but never stopped.

I collected the following events:

• sqlserver.rpc_starting
• sqlserver.rpc_completed
• sqlserver.sp_statement_starting
• sqlserver.sp_statement_completed
• sqlserver.sql_batch_starting
• sqlserver.sql_batch_completed
• sqlserver.sql_statement_completed

Step 1 – Create an Extended Events Session for a Specific Job

/****************************
Create xevents session statement for a specific job.
****************************/
DECLARE @JobName NVARCHAR(128) 
DECLARE @JobStepsFilterForXevents NVARCHAR(MAX) = ''
DECLARE @MaxJobSteps INT
DECLARE @XeventsPath NVARCHAR(128)
DECLARE @XeventsSessionStmt NVARCHAR(MAX)

SET @JobName = 'BranchReport'
SET @XeventsPath = 'C:\TEMP\'

SELECT @MaxJobSteps = MAX(js.step_id)
        FROM msdb.dbo.sysjobs AS j
        INNER JOIN msdb.dbo.sysjobsteps AS js
            ON j.job_id = js.job_id
        WHERE j.name = @JobName

SELECT @JobStepsFilterForXevents = @JobStepsFilterForXevents + 
    'sqlserver.client_app_name = ''' +
    'SQLAgent - TSQL JobStep (Job 0x'+
    SUBSTRING(job_id,7,2) +
    SUBSTRING(job_id,5,2) +
    SUBSTRING(job_id,3,2) +
    SUBSTRING(job_id,1,2) +
    SUBSTRING(job_id,12,2) +
    SUBSTRING(job_id,10,2) +
    SUBSTRING(job_id,17,2) +
    SUBSTRING(job_id,15,2) +
    SUBSTRING(job_id,20,4) +
    SUBSTRING(job_id,25,12) + 
    ' : Step ' + 
    CAST(step_id AS VARCHAR(3)) + 
    ')''' + (CASE WHEN step_id <> @MaxJobSteps THEN ' OR ' WHEN step_id = @MaxJobSteps THEN '' END)
FROM( SELECT CAST(j.job_id AS VARCHAR(50)) AS job_id,
            js.step_id
        FROM msdb.dbo.sysjobs AS j
        INNER JOIN msdb.dbo.sysjobsteps AS js
            ON j.job_id = js.job_id
        WHERE j.name = @JobName) AS ClientAppNameFltr
ORDER BY step_id;

SET @XeventsSessionStmt = 'CREATE EVENT SESSION [JobHangSession] ON SERVER 
ADD EVENT sqlserver.rpc_starting(SET collect_statement=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE ('+@JobStepsFilterForXevents + ')),
ADD EVENT sqlserver.rpc_completed(SET collect_output_parameters=(1),collect_statement=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE ('+@JobStepsFilterForXevents + ')),
ADD EVENT sqlserver.sp_statement_starting(SET collect_object_name=(1),collect_statement=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE ('+@JobStepsFilterForXevents + ')),
ADD EVENT sqlserver.sp_statement_completed(SET collect_object_name=(1),collect_statement=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE ('+@JobStepsFilterForXevents + ')),
ADD EVENT sqlserver.sql_batch_starting(SET collect_batch_text=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE ('+@JobStepsFilterForXevents + ')),
ADD EVENT sqlserver.sql_batch_completed(SET collect_batch_text=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE ('+@JobStepsFilterForXevents + ')),
    ADD EVENT sqlserver.sql_statement_starting(SET collect_statement=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE ('+@JobStepsFilterForXevents + ')),
ADD EVENT sqlserver.sql_statement_completed(SET collect_statement=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE ('+@JobStepsFilterForXevents + ')) 
ADD TARGET package0.event_file(SET filename=N'''+@XeventsPath+'job_hang.xel'',max_file_size=(100),max_rollover_files=(5))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=5 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)
'

--PRINT @XeventsSessionStmt
EXEC (@XeventsSessionStmt)
GO

Here is the actual statement that was created for my new extended events session.

CREATE EVENT SESSION [JobHangSession] ON SERVER 
ADD EVENT sqlserver.rpc_completed(SET collect_output_parameters=(1),collect_statement=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE (sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 1)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 3)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 4)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 5)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 6)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 7)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 8)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 9)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 10)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 11)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 2)')),
ADD EVENT sqlserver.rpc_starting(SET collect_statement=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE (sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 1)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 3)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 4)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 5)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 6)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 7)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 8)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 9)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 10)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 11)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 2)')),
ADD EVENT sqlserver.sp_statement_completed(SET collect_object_name=(1),collect_statement=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE (sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 1)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 3)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 4)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 5)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 6)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 7)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 8)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 9)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 10)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 11)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 2)')),
ADD EVENT sqlserver.sp_statement_starting(SET collect_object_name=(1),collect_statement=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE (sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 1)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 3)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 4)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 5)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 6)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 7)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 8)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 9)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 10)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 11)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 2)')),
ADD EVENT sqlserver.sql_batch_completed(SET collect_batch_text=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE (sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 1)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 3)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 4)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 5)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 6)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 7)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 8)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 9)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 10)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 11)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 2)')),
ADD EVENT sqlserver.sql_batch_starting(SET collect_batch_text=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE (sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 1)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 3)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 4)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 5)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 6)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 7)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 8)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 9)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 10)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 11)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 2)')),
ADD EVENT sqlserver.sql_statement_completed(SET collect_statement=(1)
    ACTION(package0.event_sequence,sqlserver.client_app_name,sqlserver.client_hostname,sqlserver.database_id,sqlserver.database_name,sqlserver.query_hash,sqlserver.query_plan_hash,sqlserver.request_id,sqlserver.server_instance_name,sqlserver.server_principal_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_frame,sqlserver.tsql_stack)
    WHERE (sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 1)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 3)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 4)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 5)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 6)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 7)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 8)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 9)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 10)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 11)' OR sqlserver.client_app_name = 'SQLAgent - TSQL JobStep (Job 0x8B6A4AE0E8D7FA45BAE028C8F8043511 : Step 2)')) 
ADD TARGET package0.event_file(SET filename=N'C:\TEMP\job_hang.xel',max_file_size=(100),max_rollover_files=(5))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=5 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)

Step 2 – Start the Extended Events session

/****************************
Start or stop the session
****************************/
ALTER EVENT SESSION [JobHangSession] ON SERVER STATE = START; 

ALTER EVENT SESSION [JobHangSession] ON SERVER STATE = STOP; 

The above statements were put into jobs, with one that started the extended events session at the time that I wanted it and the other that stops the session after the job should have completed.  I had to give myself a pretty large window of time since we never knew exactly how long it would take to complete the job when it did run longer than usual.

Step 3 – Evaluate data collected by the Extended Events session

Once you have the event caught then you need to check to see if you can find the issue.  Since the job completed but took a very long time to complete as compared to other runs, I decided to look for high duration values since whatever took so long should be at the top of the list.

/****************************
Query the collected data to look for the statement that took a long time.
****************************/
IF EXISTS (SELECT name FROM tempdb.sys.objects WHERE name like N'#XEventJobHang%' AND type = 'U')
    DROP TABLE #XEventJobHang
CREATE TABLE #XEventJobHang (ID INT PRIMARY KEY IDENTITY (1,1), JH_XML [xml] NOT NULL)

INSERT INTO #XEventJobHang (JH_XML)
SELECT CAST([XML DATA] AS XML) AS JH_XML
FROM
    (SELECT OBJECT_NAME AS [Event], 
          CONVERT(XML, event_data) AS [XML Data]
    FROM sys.fn_xe_file_target_read_file('C:\TEMP\job_hang_0_133045998003300000.xel', null, null, null)) AS v

SELECT JH_XML.value(N'(event/@timestamp)[1]', N'datetime') AS EventTime, 
JH_XML.value(N'(event/data[@name="duration"]/value)[1]', N'bigint') AS Duration, 
* 
FROM #XEventJobHang
WHERE JH_XML.value(N'(event/data[@name="duration"]/value)[1]', N'bigint') > 0
ORDER BY JH_XML.value(N'(event/data[@name="duration"]/value)[1]', N'bigint') DESC

The results show the long running query that caused the job to be so slow.  The top 2 records are the completion of the stored proc that was called by job step 4.  On this run, job step 4 took 99 minutes to run!  If you want to review the XML to see exactly what statement is in each, just click on the XML and it should pop into a new window for you.

Since the request I had was to simply let them know which query was the culprit, I stopped there and sent the query text to the developers for them to work on.  Another thing we can see in the XML that is captured is cpu_time, logical_reads, writes and spills.  Those would further help in identifying what resources are being used and where to attack the query from a performance perspective. 

Ultimately we did help out later on and found that the results of the view DWhse.dbo.vwTribPLSales3 needed to be converted to instead be loaded into a temp table which the proc needed to use in place of the view. 

And there you have it!  This can be used for any job to track performance and even compare runs.  And, since we are also capturing the query_hash and query_plan_hash, which to my understanding usually indicates that the query is a candidate for optimization, you can also either filter by sqlserver.query_hash <> 0 to only catch queries that might need help or you can use the query_plan_hash to get more info on the plan.  For that I will refer you back to the estimable Mr. Kehayias again.  How useful are query_hash and query_plan_hash for troubleshooting? – Jonathan Kehayias (sqlskills.com)

For more information about blog posts, concepts and definitions, further explanations, or questions you may have…please contact us at SQLRx@sqlrx.com. We will be happy to help! Leave a comment and feel free to track back to us. Visit us at www.sqlrx.com!