We recently upgraded databases from 11.2.0.4 to 12.1.0.2. With that upgrade, we noticed that after submitted jobs via dbms_job, the procedures can take anywhere between 5-30 seconds in order to actually start to execute after committing. A sample script to reproduce the issue is below:
create or replace procedure write_to_log(p_dir in varchar2,p_file_name IN VARCHAR2, p_msg IN VARCHAR2)
IS
l_file_handle UTL_FILE.FILE_TYPE;
l_log_file_path VARCHAR2(255);
l_file_name VARCHAR2(50) := p_file_name;
l_msg VARCHAR2(4000);
BEGIN
l_log_file_path := p_dir;
BEGIN
l_file_handle := UTL_FILE.FOPEN(l_log_file_path,l_file_name,'A');
EXCEPTION
WHEN UTL_FILE.INVALID_OPERATION
THEN
l_file_handle := UTL_FILE.FOPEN(l_log_file_path,l_file_name,'W');
END;
UTL_FILE.PUT_LINE(l_file_handle,'****** LOGGED: ' || to_char(sysdate,'mm/dd/yyyy hh24:mi:ss') || ' ********************');
UTL_FILE.FFLUSH(l_file_handle);
l_msg := SUBSTR(LTRIM(RTRIM(p_msg)),1,4000);
UTL_FILE.PUT_LINE(l_file_handle,l_msg);
UTL_FILE.FFLUSH(l_file_handle);
-- UTL_FILE.PUT_LINE(l_file_handle,'***************************************************************************');
-- UTL`_FILE.FFLUSH(l_file_handle);
UTL_FILE.FCLOSE(l_file_handle);
EXCEPTION
WHEN OTHERS THEN
UTL_FILE.FCLOSE(l_file_handle);
END;
/
create or replace procedure print_time
is
begin
write_to_log('UTL_FILE_DIR','AARON_DBMS_JOB.log',to_char(sysdate, 'DS TS') || ' - IN PRINT TIME BEFORE SLEEP');
dbms_lock.sleep(5);
write_to_log('UTL_FILE_DIR','AARON_DBMS_JOB.log',to_char(sysdate, 'DS TS') || ' - IN PRINT TIME AFTER SLEEP');
end;
/
declare
l_job number;
begin
dbms_job.submit(l_job, 'print_time;');
write_to_log('UTL_FILE_DIR','AARON_DBMS_JOB.log',to_char(sysdate, 'DS TS') || ' - SUBMITTED');
commit;
write_to_log('UTL_FILE_DIR','AARON_DBMS_JOB.log',to_char(sysdate, 'DS TS') || ' - COMMITTED');
end;
/
Which results in an output file that looks something like this:
****** LOGGED: 06/20/2017 17:49:36 ********************
6/20/2017 5:49:36 PM - SUBMITTED
****** LOGGED: 06/20/2017 17:49:36 ********************
6/20/2017 5:49:36 PM - COMMITTED
****** LOGGED: 06/20/2017 17:50:04 ********************
6/20/2017 5:50:04 PM - IN PRINT TIME BEFORE SLEEP
****** LOGGED: 06/20/2017 17:50:09 ********************
6/20/2017 5:50:09 PM - IN PRINT TIME AFTER SLEEP
I know that the job_queue_processes parameter is large enough, as this is the only job that's running in the database and I found some documentation on the hidden parameter _job_queue_interval, but I do not think this is related either as this parameter's value is 5.
Has anything changed in 12cR1 that would have caused the polling of the dbms_job queue to increase in length?
Not that I know of, but there have been some bugs in various versions of Oracle the CJQ0 process (the one that wakes up and keeps an eye on the job queue).
I would look at:
a) tracing CJQ0 for a while to make sure its not hung or spinning
b) see if a new CJQ0 fixes the issue, ie
alter system set job_queue_process=0;
kill cjq0 process from OS
alter system set job_queue_process= [previous val];
which should start a new CJQ0
If that doesn't work, its time to contact Support