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