问题描述
下面是模拟生产环境的一次ora-12005的错误，在百度,google一搜很多与这个相关的blog，但是看来看去，觉得始终跟自己的想法有点不同。
测试环境：OS:RHEL 4.8 OS:10.2.0.4.9
1，实验的前提条件
这里为了跟客户的job的时候interval致，所以需要修改主机的date，为了查看到进程后台扫描的sql，所以里面配置10046事件，为了查询12005的详细报错信息，需要配置12005的errorstack。
修改主机时间
[root@rhel4 ~]# date -s '05/30/2013 23:50:00'; Thu May 30 23:50:00 CST 2013 [root@rhel4 ~]# date Thu May 30 23:50:02 CST 2013 修改events www.htz.pw >alter system set event='10046 trace name context forever,level 12','12005 trace name errorstack level 3' scope=spfile; System altered. www.htz.pw >startup force;
专家解答
2，创建一个测试过程
www.htz.pw >create or replace procedure test_lock 2 as 3 begin 4 execute immediate 'alter index scott.pk_emp rebuild online'; 5 dbms_lock.sleep(300); 6 end; 7 /
3，创建自动作业
www.htz.pw >VARIABLE jobno NUMBER; www.htz.pw >BEGIN 2 DBMS_JOB.SUBMIT(:jobno, 'test_lock;', SYSDATE+1/1440, interval=>'trunc(add_months(sysdate,1),''MM'')-1'); 3 COMMIT; 4 END; 5 / PL/SQL procedure successfully completed.
通过dba_jobs查看作业的信息
Job ID User What Next Run Date Interval Last Run Date Failures Broken? -------- -------------------- ------------------------------ ------------------------------ ------------------------------ ------------------------------ ---------- ------- 21 SYS test_lock; 31-MAY-2013 00:06:10 trunc(add_months(sysdate,1),'M 30-MAY-2013 23:51:59 2 N M')-1
4，作业的第一次执行的信息
sess:serial INSTANCE BLOCK_SESS SQL_ID os process User STATUS seq# JOB_ID PROGRAM INST:SESS SQL_CHILD_NUMBER START_TIME -------------------- --------------- ---------- ---------- ------------ ------------------------------ --------------- -------------------- ----------- 158,7.16682 SYS ACTIVE 371 0:21 oracle@rhel4.htz.pw (J000 NO HOLDER::
这个可以看到作业的session id为158，process 为16682，查看16682的后台trace文件，查找update sys.job$的语句
从整个trace中，我们可以看出，在job当开始执行的时候就分析了update sys.job$，但是只是分析了，一直没有运行，实际运行作业更新是在39158这行才开始运行。还有一点，只要作业发起了，next_date的值都会被修改，就算作业运行失败，也同样会修改next_date的值，下面我们会证明。
5，作业的第二次运行
从alert中我们可以看到，已经开始报错了。
Fri May 31 00:00:36 2013 Errors in file /u01/app/oracle/admin/orcl10g/bdump/orcl10g_j000_7944.trc: ORA-12005: may not schedule automatic refresh for times in the past Fri May 31 00:00:37 2013 Errors in file /u01/app/oracle/admin/orcl10g/bdump/orcl10g_j000_7944.trc: ORA-12012: error on auto execute of job 1 ORA-12005: may not schedule automatic refresh for times in the past Fri May 31 00:02:41 2013 Errors in file /u01/app/oracle/admin/orcl10g/bdump/orcl10g_j000_8080.trc: ORA-12005: may not schedule automatic refresh for times in the past Fri May 31 00:02:42 2013 Errors in file /u01/app/oracle/admin/orcl10g/bdump/orcl10g_j000_8080.trc: ORA-12012: error on auto execute of job 1 ORA-12005: may not schedule automatic refresh for times in the past Fri May 31 00:04:01 2013
此时我们查看作业的next_date时间，发现了变化为上一次作业的执行的时间+2的（重试次数-1）的次方。下面是官方文档这样介绍的
If a job returns an error while Oracle is attempting to execute it,
Oracle tries to execute it again. The first attempt is made after one minute,
the second attempt after two minutes, the third after four minutes,
and so on, with the interval doubling between each attempt. If the job fails 16 times,
Oracle automatically marks the job as broken and no longer tries to execute it.
However, between attempts, you have the opportunity to correct the problem that is preventing the job from running.
This will not disturb the retry cycle, and Oracle will eventually attempt to run the job again
只要有一次成功执行，就会自己清除失败的次数，下面我们也会提到这个东西，现在分析8080这个trace文件,从trace中我们查找update sys.的语句
[oracle10g@rhel4 bdump]$ cat -n orcl10g_j000_8080.trc|grep "update sys."|grep -v "name="|grep -v "sqltxt" 26 update sys.job$ set this_date=:1 where job=:2 31 update sys.job$ set failures=0, this_date=null, flag=:1, last_date=:2, next_date = greatest(:3, sysdate), total=total+(sysdate-nvl(this_date,sysdate)) where job=:4 38509 update sys.job$ set this_date=null, failures=:1, flag=:2, next_date = greatest(:3, sysdate, next_date), total=total+(sysdate-nvl(this_date,sysdate)) where job=:4
这里我们发现，作业报错的trace文件中多一个条update语句，行31，此条sql语句就表示，更新作业失败的次数为0，next_date时间，之前我们也提到了，作业成功执行一次会，会清空failures的值。下面看一下38509行的具体内容
update sys.job$ set this_date=null, failures=:1, flag=:2, next_date = greatest(:3, sysdate, next_date), total=total+(sysdate-nvl(this_date,sysdate)) where job=:4 END OF STMT PARSE #5:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1337822033388698 BINDS #5: kkscoacd Bind#0 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0 kxsbbbfp=2a9725f3f0 bln=22 avl=02 flg=05 value=2 Bind#1 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0 kxsbbbfp=2a9725f3c0 bln=24 avl=01 flg=05 value=0 Bind#2 oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00 oacflg=18 fl2=0001 frm=00 csi=00 siz=8 off=0 kxsbbbfp=7fbfffde54 bln=08 avl=07 flg=09 value="5/31/2013 0:6:42" Bind#3 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0 kxsbbbfp=2a9725f390 bln=24 avl=02 flg=05 value=1
更新next_date值，并且也增加一次失败的次数。这条update语句是中作业抛出错误后再执行的。查询alter index的语句是否执行
[oracle10g@rhel4 bdump]$ cat orcl10g_j000_8080.trc |grep "alter index"
在trace文件中我们并没有找到alter index语句，说明作业的具体内容是没有执行的，其实可以从index的上次ddl时间我们也可以看出。
从上面测试可以得出下面的结论
1 报ORA-12051错误，并不是在作业执行完后，而是在j0nn进程发起后，并且作业的内容还没有执行前，内部应该有什么机制会去检测作业的 next_date（sysdate与invertal的结果）是否小于sysdate，如果小于sysdate的时间就会报12051错误。
2 更新next_date列的值，不管作业是否执行成功都会更新next_date，在作业成功执行后才更新next_date值，失败时的next_date的值为sysdate+2的(n-1)次方，n为作业执行失败次数
3 next_date列的值是取greatest(:3, sysdate)中的最大值，:3其实就是作业当开始执行的时候+interval的值，如果:3的值小于sysdate时（这种情况会在作业运行的时间大于作业的interval时会出现），作业会把next_date更新成sysdate，作业将马上又一次运行。
