DBMS_SCHEDULER jobs running an hour late – DST/BST issues!

This week one of our developers highlighted the fact that the DBMS_SCHEDULER on one of our 11.2.0.3 databases was running jobs an hour later than scheduled until just recently, when the clocks went back (26/10/2014) for British Summer Time (BST) …and now they’re running on-time again!

I’d not seen this before, and at first I thought we were hitting some kind of Daylight Saving Time (DST) related Oracle bug with the DBMS_SCHEDULER, but I did a bit more digging around and eventually found out why.  It’s a bit of a long winded explanation, but hopefully this all makes sense to someone else who hits a similar issue…

So what’s happening?

I took a look at the DBMS_SCHEDULER logs for the ‘MON_SAT_EVENING_REFRESH’ job which encountered the problem:

COL "Job Name" FOR A25
COL "Operation" FOR A12

SELECT l.log_id                              "Log ID", 
       l.job_name                            "Job Name", 
       TO_CHAR (l.log_date, 
       'YYYY/MM/DD HH24:MI:SS.FF TZH:TZM')   "Log Date", 
       TO_CHAR (r.actual_start_date,
       'YYYY/MM/DD HH24:MI:SS.FF TZH:TZM')   "Actual Start Date" 
FROM   dba_scheduler_job_log l, 
       dba_scheduler_job_run_details r 
WHERE  l.owner = 'DATAMART' 
       AND l.job_name = 'MON_SAT_EVENING_REFRESH' 
       AND l.log_id = r.log_id(+) 
ORDER  BY 1 DESC 
/

    Log ID Job Name                  Log Date                             Actual Start Date
---------- ------------------------- ------------------------------------ ---------------------------------
     57776 MON_SAT_EVENING_REFRESH   2014/10/30 18:30:26.767000 +00:00    2014/10/30 18:30:00.511000 +00:00
     57553 MON_SAT_EVENING_REFRESH   2014/10/29 18:30:28.455000 +00:00    2014/10/29 18:30:00.545000 +00:00
     57330 MON_SAT_EVENING_REFRESH   2014/10/28 18:30:27.162000 +00:00    2014/10/28 18:30:00.361000 +00:00
     57107 MON_SAT_EVENING_REFRESH   2014/10/27 18:30:25.415000 +00:00    2014/10/27 18:30:00.252000 +00:00
     56623 MON_SAT_EVENING_REFRESH   2014/10/25 19:30:25.217000 +01:00    2014/10/25 18:30:00.038000 +00:00
     56344 MON_SAT_EVENING_REFRESH   2014/10/24 19:30:24.684000 +01:00    2014/10/24 18:30:01.002000 +00:00
     56121 MON_SAT_EVENING_REFRESH   2014/10/23 19:30:22.536000 +01:00    2014/10/23 18:30:00.821000 +00:00

So we can see that the log date and time reflects the true time the job ran, but the actual start time contradicts this…but why??

The clue is in the time zone (TZ) setting at the end of each value (underlined).  When the jobs were created, the START_DATE used a TZ of +00:00 (GMT/UTC) as can be seen below.  Notice the SYS job TZ in comparison, which has the correct setup (although strictly speaking it should really be ‘EUROPE/LONDON’ in our case):

SELECT owner, 
       job_name, 
       start_date, 
       next_run_date 
FROM   dba_scheduler_jobs;

OWNER        JOB_NAME                       START_DATE                               NEXT_RUN_DATE
------------ ------------------------------ ---------------------------------------- ---------------------------------------
SYS          PURGE_LOG                      03-SEP-13 03.00.00.900000 EUROPE/LISBON  01-NOV-14 03.00.00.800000 EUROPE/LISBON
DATAMART     MON_SAT_EVENING_REFRESH        11-OCT-14 18.30.00.000000 +00:00         31-OCT-14 18.30.00.500000 +00:00

If we check the DBMS_SCHEDULER system time, that picks up the correct TZ too:

SELECT dbms_scheduler.stime FROM dual; 

STIME
-------------------------------------------------------------------
31-OCT-14 15.10.05.521000000 EUROPE/LISBON

So where is GMT being picked up from?

Well, I created a test job without specifying a TZ in the date/time string:

BEGIN
DBMS_SCHEDULER.CREATE_JOB (
   job_name             => 'hr.my_job',
   job_type             => 'PLSQL_BLOCK',
   job_action           => 'BEGIN DBMS_STATS.GATHER_TABLE_STATS(''HR'',
                            ''EMPLOYEES''); END;',
   start_date           =>  TO_DATE('01-OCT-2014 14:00','DD-MON-YYYY HH24:MI'),
   repeat_interval      => 'FREQ=DAILY',
   end_date             =>  TO_DATE('01-DEC-2014 14:00','DD-MON-YYYY HH24:MI'),
   enabled              =>  TRUE,
   comments             => 'Gather table statistics');
END;
/

PL/SQL procedure successfully completed.

…and it used the same TZ (GMT) as the ‘DATAMART’ owned job above:

SELECT owner, 
       job_name, 
       start_date, 
       next_run_date 
FROM   dba_scheduler_jobs 
WHERE  owner = 'HR';

OWNER        JOB_NAME       START_DATE                               NEXT_RUN_DATE
------------ -------------- ---------------------------------------- --------------------------------
HR           MY_JOB         01-OCT-14 14.00.00.000000 +00:00         31-OCT-14 14.00.00.000000 +00:00

…after checking the session TZ used by my client, I can see where that’s being derived that from now:

SELECT sessiontimezone FROM dual; 

SESSIONTIMEZONE
-------------------------------------------------------------
+00:00

Using a bit of PL/SQL and calling the DBMS_SCHEDULER.EVALUATE_CALENDAR_STRING procedure, I was able to determine exactly what the next run date/time values would have been used from 23/10/2014, for a weeks’ worth of executions (clock change was 26/10/2014):

-- Current GMT TZ
DECLARE
-- Set repeat interval
interval_string VARCHAR2(100) DEFAULT 'FREQ=DAILY;BYDAY=MON,TUE,WED,THU,FRI,SAT,SUN;BYHOUR=14';
start_date TIMESTAMP with time zone;
return_date_after TIMESTAMP with time zone;
next_run_date TIMESTAMP with time zone;
no_of_days PLS_INTEGER DEFAULT 7;

BEGIN
-- Set start_date NOT TO INCLUDE TZ   
start_date := to_timestamp_tz('22-OCT-2014 14:00:00' ,'DD-MON-YYYY HH24:MI:SS');
return_date_after := start_date;

FOR i IN 1..no_of_days LOOP
DBMS_SCHEDULER.EVALUATE_CALENDAR_STRING( 
interval_string
,start_date
,return_date_after
,next_run_date);

DBMS_OUTPUT.PUT_LINE('Next Run: ' ||to_char(next_run_date, 'DY DD-MON-YYYY HH24:MI:SS TZD TZH TZR'));
return_date_after := next_run_date;
END LOOP;
END;
/

Next Run: THU 23-OCT-2014 14:00:00  +00 +00:00
Next Run: FRI 24-OCT-2014 14:00:00  +00 +00:00
Next Run: SAT 25-OCT-2014 14:00:00  +00 +00:00
Next Run: SUN 26-OCT-2014 14:00:00  +00 +00:00
Next Run: MON 27-OCT-2014 14:00:00  +00 +00:00
Next Run: TUE 28-OCT-2014 14:00:00  +00 +00:00
Next Run: WED 29-OCT-2014 14:00:00  +00 +00:00

PL/SQL procedure successfully completed.

The important thing to note here, is that my START_DATE didn’t include a time zone:

start_date := to_timestamp_tz('22-OCT-2014 14:00:00' ,'DD-MON-YYYY HH24:MI:SS')

Running the same procedure again, but this time including the TZ in the START_DATE yielded the results we’d expect to see:

-- New BST TZ
DECLARE
-- Set repeat interval
interval_string VARCHAR2(100) DEFAULT 'FREQ=DAILY;BYDAY=MON,TUE,WED,THU,FRI,SAT,SUN;BYHOUR=14';
start_date TIMESTAMP with time zone;
return_date_after TIMESTAMP with time zone;
next_run_date TIMESTAMP with time zone;
no_of_days PLS_INTEGER DEFAULT 7;

BEGIN
-- Set start_date NOT TO INCLUDE TZ
--start_date := to_timestamp_tz('22-OCT-2014 14:00:00' ,'DD-MON-YYYY HH24:MI:SS');

-- Set start_date TO INCLUDE TZ
start_date := to_timestamp_tz('22-OCT-2014 14:00:00 Europe/London' ,'DD-MON-YYYY HH24:MI:SS TZR');
return_date_after := start_date;

FOR i IN 1..no_of_days LOOP
DBMS_SCHEDULER.EVALUATE_CALENDAR_STRING(
interval_string
,start_date
,return_date_after
,next_run_date);

DBMS_OUTPUT.PUT_LINE('Next Run: ' ||to_char(next_run_date, 'DY DD-MON-YYYY HH24:MI:SS TZD TZH TZR'));
return_date_after := next_run_date;
END LOOP;
END;
/

Next Run: THU 23-OCT-2014 14:00:00 BST +01 EUROPE/LONDON
Next Run: FRI 24-OCT-2014 14:00:00 BST +01 EUROPE/LONDON
Next Run: SAT 25-OCT-2014 14:00:00 BST +01 EUROPE/LONDON
Next Run: SUN 26-OCT-2014 14:00:00 GMT +00 EUROPE/LONDON
Next Run: MON 27-OCT-2014 14:00:00 GMT +00 EUROPE/LONDON
Next Run: TUE 28-OCT-2014 14:00:00 GMT +00 EUROPE/LONDON
Next Run: WED 29-OCT-2014 14:00:00 GMT +00 EUROPE/LONDON

PL/SQL procedure successfully completed.

NOTE: The START_DATE used this time included the time zone:

start_date := to_timestamp_tz('22-OCT-2014 14:00:00 Europe/London' ,'DD-MON-YYYY HH24:MI:SS TZR');

So if you don’t specify a start date to include your TZ, it’ll pickup your session level TZ, which is most likely set incorrectly and take that into account for the next run date.  You’ll then end up with jobs created during GMT running on time throughout GMT (30/03/2014-26/10/2014 in our case), but then they’ll be 1 hour out during BST, which is what we’d been seeing with the job scheduler for this particular database.

There are other scenarios and conditions where the session TZ is used too, so as per Oracle’s recommendation (see MOS Doc 467722.1):

…the best option is to always specify a full start date with a timezone name that uses the DST rules you expect or to use for example CURRENT_TIMESTAMP and set the session timezone first to the timezone name that uses the DST rules you expect.

What did I do to fix this?

It’s pretty simple really, for my test job, I just updated the START_DATE to include the correct TZ:

BEGIN
DBMS_SCHEDULER.SET_ATTRIBUTE (
   name                 => 'HR.MY_JOB',
   attribute            => 'start_date',
   value                => TO_TIMESTAMP_TZ('22-OCT-2014 14:00:00 Europe/London' ,'DD-MON-YYYY HH24:MI:SS TZR'));
END;
/

PL/SQL procedure successfully completed.

SELECT owner, 
       job_name, 
       start_date, 
       next_run_date 
FROM   dba_scheduler_jobs 
WHERE  owner = 'HR';

OWNER        JOB_NAME       START_DATE                               NEXT_RUN_DATE
------------ -------------- ---------------------------------------- ---------------------------------------
HR           MY_JOB         22-OCT-14 14.00.00.000000 EUROPE/LONDON  01-NOV-14 14.00.00.400000 EUROPE/LONDON

By the way, if anyone’s wondering where the EUROPE/LISBON TZ came from for the SYS jobs earlier on, that’s what the default DBMS_SCHEDULER TZ was set to on that database:

SELECT * 
FROM   dba_scheduler_global_attribute 
WHERE  attribute_name = 'DEFAULT_TIMEZONE'; 

ATTRIBUTE_NAME                 VALUE
------------------------------ ---------------------
DEFAULT_TIMEZONE               Europe/Lisbon

That’s something else I’ve learnt this week 🙂

References:
Configuring Oracle Scheduler – Setting Scheduler Preferences
Pythian – Have Your Scheduler Jobs Changed Run Times Since DST ??
Scheduler (DBMS_SCHEDULER) in Oracle Database 10g – Time Zones