SQL Agent skipping Scheduled job runs!!– But the Job History does not reveal anything!

  • Article

A Scheduled SQL Agent job skipped a Scheduled run on one particular day and the DBA wanted to investigate the root cause as he did not see any error messages or Job failures reported!

This Job was used to collect some information and upload the data at regular intervals for the DBA’s customers to use. He was only notified about this when the DBA’s clients complained that there was no data available one morning.

When he checked to see if the job had run on time and found that it had actually quietly skipped a scheduled run.    

He had already checked that the

  •   SQL Error logs do not show any errors
  •   Event logs did not record any errors
  •   We did not have any entry in the Job activity monitor that showed us if the Job ran successfully or failed!

We used the below steps to understand the cause of the Job quietly skipping its schedule!

  •  
    We used the following to query the sysjobhistory table in the MSDB

     

select j.name as 'JobName', run_date, run_time, msdb.dbo.agent_datetime(run_date, run_time) as 'RunDateTime', run_duration From msdb.dbo.sysjobs j INNER JOIN msdb.dbo.sysjobhistory h ON j.job_id = h.job_id where j.enabled = 1 --Only Enabled Jobs order by JobName, RunDateTime desc

JobName Step StepName RunDateTime RunDurationMinutes

Execute_Daily_Job 2 run batch file 2013-09-04 06:15:01.000 89

Execute_Daily_Job 1 Check If the Data is Ready 2013-09-04 04:30:00.000 105

Execute_Daily_Job 1 Check If the Data is Ready 2013-09-03 04:30:00.000 0

Execute_Daily_Job 2 run batch file 2013-08-31 04:30:00.000 87

Execute_Daily_Job 1 Check If the Data is Ready 2013-08-31 04:30:00.000 0

Execute_Daily_Job 1 Check If the Data is Ready 2013-08-30 04:30:00.000 0

Execute_Daily_Job 2 run batch file 2013-08-30 04:30:00.000 102

Execute_Daily_Job 1 Check If the Data is Ready 2013-08-29 04:30:00.000 0

Execute_Daily_Job 2 run batch file 2013-08-29 04:30:00.000 71

Execute_Daily_Job 1 Check If the Data is Ready 2013-08-28 04:30:00.000 0

Execute_Daily_Job 2 run batch file 2013-08-28 04:30:00.000 75

Execute_Daily_Job 2 run batch file 2013-08-27 04:30:01.000 74

Execute_Daily_Job 1 Check If the Data is Ready 2013-08-27 04:30:00.000 0

Execute_Daily_Job 1 Check If the Data is Ready 2013-08-24 04:30:00.000 0

Execute_Daily_Job 2 run batch file 2013-08-24 04:30:00.000 75

Execute_Daily_Job 1 Check If the Data is Ready 2013-08-23 04:30:00.000 0

Execute_Daily_Job 2 run batch file 2013-08-23 04:30:00.000 88

Execute_Daily_Job 1 Check If the Data is Ready 2013-08-22 04:30:00.000 0

Execute_Daily_Job 2 run batch file 2013-08-22 04:30:00.000 72

Execute_Daily_Job 2 run batch file 2013-08-20 04:35:00.000 1652

Execute_Daily_Job 1 Check If the Data is Ready 2013-08-20 04:30:00.000 5

Execute_Daily_Job 2 run batch file 2013-08-17 04:30:00.000 541

    We saw that in the last run before the skipped schedule

1.The first step completed in 5 minutes 4.30 - 4.35

2. However the second step took 1652 minutes which is 27.5 hours. This is more then the Next scheduled runtime ( Which was every 24 hours)

Thus we saw that The SQL Server Agent actually checks whether a job is already running before starting the next iteration.

Suppose you have a long running job and its schedule comes up, it would be skipped until the next interval!

Here is how you may test this with a simple Scenario to understand the above behavior of the SQL Agent with a scheduled Job:

1 . We will be creating a simple Job with a WAITFORDELAY inside it and schedule the job to run such that the Next scheduled run time is shorter than the WAITFORDELAY

image

   

2 . It is a simple job that inserts a number into a table along with a WAITFORDELAY of 25 seconds

2

3. Set the Schedule of the job to run every 10 seconds (which is lesser than our WAITFORDELAY value)

4

4. Once the job is enabled and is running, You can use this query to check the RunDateTime of the steps in the Job

select j.name as 'JobName', s.step_id as 'Step', s.step_name as 'StepName', msdb.dbo.agent_datetime(run_date, run_time) as 'RunDateTime', ((run_duration/10000*3600 + (run_duration/100)%100*60 + run_duration%100 + 31 ) / 60) as 'RunDurationMinutes' From msdb.dbo.sysjobs j INNER JOIN msdb.dbo.sysjobsteps s ON j.job_id = s.job_id INNER JOIN msdb.dbo.sysjobhistory h ON s.job_id = h.job_id AND s.step_id = h.step_id AND h.step_id <> 0 where j.enabled = 1

5

Since we scheduled the Job to run every 10 seconds we would expect to see 10 second Intervals between the RundateTime of each execution

However, if you notice above, we have many skipped schedules

5. What makes this more confusing for a DBA who is attempting to find the cause of “Why did the job skip its scheduled run” is the fact that the Job history would not show any errors or messages that a Job schedule has been skipped. 

     

6

But we now know why the job skipped its scheduled run! Smile