摘要: 本文通過一次Oracle Job任務異常案例診斷，分析其原因及解決過程，從內部揭示Oracle Job任務調度及內部計時機制。 問題及環境 接到研發人員報告，數據庫定時任務未正常執行，導致某些操作失敗,開始介入處理該事故。 系統環境: SunOS DB 5.8 Generic_108528-21 sun4u sparc SUNW,Ultra-4 Oracle9i Enterprise Edition Release 9.2.0.3.0 - ProdUCtion解決過程 首先介入檢查數據庫任務 $ sqlplus '/ as sysdba' SQL*Plus: Release 9.2.0.3.0 - Production on Wed Nov 17 20:23:53 2004 Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved. Connected to: Oracle9i Enterprise Edition Release 9.2.0.3.0 - Production With the Partitioning, OLAP and Oracle Data Mining options JServer Release 9.2.0.3.0 - Production SQL> select job,last_date,last_sec,next_date,next_sec,broken,failures from dba_jobs; JOB LAST_DATE LAST_SEC NEXT_DATE NEXT_SEC B FAILURES INTERVAL 31 16-NOV-04 01:00:02 17-NOV-04 01:00:00 N 0 trunc(sysdate+1)+1/24 27 16-NOV-04 00:00:04 17-NOV-04 00:00:00 N 0 TRUNC(SYSDATE) + 1 35 16-NOV-04 01:00:02 17-NOV-04 01:00:00 N 0 trunc(sysdate+1)+1/24 29 16-NOV-04 00:00:04 17-NOV-04 00:00:00 N 0 TRUNC(SYSDATE) + 1 30 01-NOV-04 06:00:01 01-DEC-04 06:00:00 N 0 trunc(add_months(sysdate,1),’MM’)+6/24 65 16-NOV-04 04:00:03 17-NOV-04 04:00:00 N 0 trunc(sysdate+1)+4/24 46 16-NOV-04 02:14:27 17-NOV-04 02:14:27 N 0 sysdate+1 66 16-NOV-04 03:00:02 17-NOV-04 18:14:49 N 0 trunc(sysdate+1)+3/24 8 rows selected. 發現JOB任務是都沒有正常執行，最早一個應該在17-NOV-04 01:00:00執行。但是沒有執行。 建立測試JOB create or replace PROCEDURE pining IS BEGIN NULL; END; / variable jobno number; variable instno number; begin select instance_number into :instno from v$instance; dbms_job.submit(:jobno, ’pining;’, trunc(sysdate+1/288,’MI’), ’trunc(SYSDATE+1/288,’’MI’’)’, TRUE, :instno); end; /發現同樣的，不執行。但是通過dbms_job.run()執行沒有任何問題。進行恢復嘗試 懷疑是CJQ0進程失效，首先設置JOB_QUEUE_PROCESSES為0，Oracle會殺掉CJQ0及相應job進程 SQL> ALTER SYSTEM SET JOB_QUEUE_PROCESSES = 0; 等2~3分鐘，重新設置 SQL> ALTER SYSTEM SET JOB_QUEUE_PROCESSES = 5; 此時PMON會重起CJQ0進程 Thu Nov 18 11:59:50 2004 ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY; Thu Nov 18 12:01:30 2004 ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY; Thu Nov 18 12:01:30 2004 Restarting dead background process CJQ0 CJQ0 started with pid=8但是Job仍然不執行，而且在再次修改的時候，CJQ0直接死掉了。 Thu Nov 18 13:52:05 2004 ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY; Thu Nov 18 14:09:30 2004 ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY; Thu Nov 18 14:10:27 2004 ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY; Thu Nov 18 14:10:42 2004 ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY; Thu Nov 18 14:31:07 2004 ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY; Thu Nov 18 14:40:14 2004 ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY; Thu Nov 18 14:40:28 2004 ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY; Thu Nov 18 14:40:33 2004 ALTER SYSTEM SET job_queue_processes=1 SCOPE=MEMORY; Thu Nov 18 14:40:40 2004 ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY; Thu Nov 18 15:00:42 2004 ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY; Thu Nov 18 15:01:36 2004 ALTER SYSTEM SET job_queue_processes=15 SCOPE=MEMORY;嘗試重起數據庫，這個必須在晚上進行： PMON started with pid=2 DBW0 started with pid=3 LGWR started with pid=4 CKPT started with pid=5 SMON started with pid=6 RECO started with pid=7 CJQ0 started with pid=8 QMN0 started with pid=9 ....CJQ0正常啟動，但是Job仍然不執行。 沒辦法了... 繼續研究...居然發現Oralce有這樣一個bug ： 1. Clear description of the problem encountered: slgcsf() / slgcs() on Solaris will stop incrementing after 497 days 2 hrs 28 mins (approx) machine uptime. 2. Pertinent configuration information No special configuration other than long machine uptime. . 3. Indication of the frequency and predictability of the problem 100% but only after 497 days. 4. Sequence of events leading to the problem If the gethrtime() OS call returns a value > 42949672950000000 nanoseconds then slgcs() stays at 0xffffffff. This can cause some problems in parts of the code which rely on slgcs() to keep moving. eg: In kkjssrh() does 'now = slgcs(&se)' and compares that to a previous timestamp. After 497 days uptime slgcs() keeps returning 0xffffffff so 'now - kkjlsrt' will always return 0. . 5. Technical impact on the customer. Include persistent after effects. In this case DBMS JOBS stopped running after 497 days uptime. Other symptoms could occur in various places in the code.好么，原來是計時器溢出了，一檢查我的主機: bash-2.03$ uptime 10:00pm up 500 day(s), 14:57, 1 user, load average: 1.31, 1.09, 1.08 bash-2.03$ date Fri Nov 19 22:00:14 CST 2004剛好到事發時是497天多一點。安排重起主機系統，這個問題夠郁悶的，誰曾想Oracle這都成... Oracle最后聲稱: fix made it into 9.2.0.6 patchset。在Solaris上的9206尚未發布...暈.好了，就當是個經歷吧，假如有問題非常不可思議的話，那么大膽懷疑Oracle吧，是Bug，可能就是Bug。 重起以后問題解決，狀態如下: $ sqlplus '/ as sysdba' SQL*Plus: Release 9.2.0.3.0 - Production on Fri Nov 26 09:21:21 2004 Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved. Connected to: Oracle9i Enterprise Edition Release 9.2.0.3.0 - Production With the Partitioning, OLAP and Oracle Data Mining options JServer Release 9.2.0.3.0 - Production SQL> select job,last_date,last_sec,next_date,next_sec from user_jobs; JOB LAST_DATE LAST_SEC NEXT_DATE NEXT_SEC 70 26-NOV-04 09:21:04 26-NOV-04 09:26:00 SQL> / JOB LAST_DATE LAST_SEC NEXT_DATE NEXT_SEC 70 26-NOV-04 09:26:01 26-NOV-04 09:31:00 SQL> SQL> select * from v$timer; HSECS 3388153 SQL> select * from v$timer; HSECS 3388319 SQL> FAQ