Oracle診斷案例-Job任務停止執行[最終版]

來源:互聯網
上載者:User
oracle|執行
Oracle診斷案例-Job任務停止執行

Last Updated: Friday, 2004-11-26 9:48 Eygle
    
 


 

昨天接到研發人員報告,資料庫定時任務未正常執行,導致某些操作失敗。

開始介入處理該事故.
系統內容:
SunOS DB 5.8 Generic_108528-21 sun4u sparc SUNW,Ultra-4
Oracle9i Enterprise Edition Release 9.2.0.3.0 - Production

1.首先介入檢查資料庫任務

 

$ sqlplus "/ as sysdba"SQL*Plus: Release 9.2.0.3.0 - Production on Wed Nov 17 20:23:53 2004Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.Connected to:Oracle9i Enterprise Edition Release 9.2.0.3.0 - ProductionWith the Partitioning, OLAP and Oracle Data Mining optionsJServer Release 9.2.0.3.0 - ProductionSQL> 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 FAILURESINTERVAL---------- --------- ---------------- --------- ---------------- - ---------- ---------------------------- 31 16-NOV-04 01:00:02 17-NOV-04 01:00:00 N 0trunc(sysdate+1)+1/24 27 16-NOV-04 00:00:04 17-NOV-04 00:00:00 N 0TRUNC(SYSDATE) + 1 35 16-NOV-04 01:00:02 17-NOV-04 01:00:00 N 0trunc(sysdate+1)+1/24 29 16-NOV-04 00:00:04 17-NOV-04 00:00:00 N 0TRUNC(SYSDATE) + 1 30 01-NOV-04 06:00:01 01-DEC-04 06:00:00 N 0trunc(add_months(sysdate,1),'MM')+6/24 65 16-NOV-04 04:00:03 17-NOV-04 04:00:00 N 0trunc(sysdate+1)+4/24 46 16-NOV-04 02:14:27 17-NOV-04 02:14:27 N 0sysdate+1 66 16-NOV-04 03:00:02 17-NOV-04 18:14:49 N 0trunc(sysdate+1)+3/248 rows selected.

發現JOB任務是都沒有正常執行,最早一個應該在17-NOV-04 01:00:00執行。但是沒有執行。

2.建立測試JOB

 

create or replace PROCEDURE pining ISBEGIN 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(<job>)執行沒有任何問題。

3.進行恢複嘗試

懷疑是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 2004ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY;Thu Nov 18 12:01:30 2004ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY;Thu Nov 18 12:01:30 2004Restarting dead background process CJQ0CJQ0 started with pid=8

 

但是Job仍然不執行,而且在再次修改的時候,CJQ0直接死掉了。

 

Thu Nov 18 13:52:05 2004ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY;Thu Nov 18 14:09:30 2004ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY;Thu Nov 18 14:10:27 2004ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY;Thu Nov 18 14:10:42 2004ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY;Thu Nov 18 14:31:07 2004ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY;Thu Nov 18 14:40:14 2004ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY;Thu Nov 18 14:40:28 2004ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY;Thu Nov 18 14:40:33 2004ALTER SYSTEM SET job_queue_processes=1 SCOPE=MEMORY;Thu Nov 18 14:40:40 2004ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY;Thu Nov 18 15:00:42 2004ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY;Thu Nov 18 15:01:36 2004ALTER SYSTEM SET job_queue_processes=15 SCOPE=MEMORY;

4.嘗試重起資料庫
這個必須在晚上進行

 

PMON started with pid=2DBW0 started with pid=3LGWR started with pid=4CKPT started with pid=5SMON started with pid=6RECO started with pid=7CJQ0 started with pid=8QMN0 started with pid=9....

CJQ0正常啟動,但是Job仍然不執行。

5.沒辦法了...

繼續研究...居然發現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.08bash-2.03$ dateFri Nov 19 22:00:14 CST 2004

 

剛好到事發時是497天多一點.ft.

6.安排重起主機系統..

這個問題夠鬱悶的,NND,誰曾想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 2004Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.Connected to:Oracle9i Enterprise Edition Release 9.2.0.3.0 - ProductionWith the Partitioning, OLAP and Oracle Data Mining optionsJServer Release 9.2.0.3.0 - ProductionSQL> 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:00SQL> / JOB LAST_DATE LAST_SEC NEXT_DATE NEXT_SEC---------- --------- ---------------- --------- ---------------- 70 26-NOV-04 09:26:01 26-NOV-04 09:31:00SQL> SQL> select * from v$timer; HSECS---------- 3388153SQL> select * from v$timer; HSECS---------- 3388319SQL>

 

7.FAQ

一些朋友在Pub上問的問題
Q:對於不同平台,是否存在同樣的問題?

A:對於不同平台,存在同樣的問題
因為Oracle使用了標準C函數gethrtime
參考:
http://www.eygle.com/unix/Man.Page.Of.gethrtime.htm

使用了該函數的代碼都會存在問題.

在Metalink Note:3427424.8 文檔中,Oracle定義的平台影響為:Generic (all / most platforms affected)

Q.計數器溢出,看了看job 中基本都是1天左右執行一次,如果設定 3 天執行一次的 job , 是否出問題的uptime 應該是 497*3 之後呢 ?

A:不會

Oracle內部通過計時器來增進相對時間.
由於Oracle內部hrtime_t使用了32位計數

那麼最大值也就是0xffffffff
0xffffffff = 4294967295

slgcs()是10億分之一秒,溢出在42949672950000000這個點上.

注意,這裡0xffffffff,達到這個值時,本來是無符號整型,現在變成了-1,那麼這個值遞增時,+1 = 0了。
時間就此停住了。

我寫了一小段代碼來驗證這個內容,參考:

 [oracle@jumper oracle]$ cat unsign.c#include int main(void){unsigned int num = 0xffffffff;printf("num is %d bits long\n", sizeof(num) * 8);printf("num = 0x%x\n", num);printf("num + 1 = 0x%x\n", num + 1);return 0;}[oracle@jumper oracle]$ gcc -o unsign.sh unsign.c[oracle@jumper oracle]$ ./unsign.shnum is 32 bits longnum = 0xffffffffnum + 1 = 0x0[oracle@jumper oracle]$

 


Q:內部時鐘之一應該就是這個吧: v$timer 精確到1/100 秒的資料

沒錯!

注意前面說的:

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.

也就是說如果gethrtime() 作業系統調用傳回值大於42949672950000000(單位10億分之一秒)

也就是說Oracle將得到一個cs值為4294967295的時間值

而4294967295值就是0xffffffff

所以當時v$timer的計時也就是:

SQL> select * from v$timer; HSECS----------4294967295SQL> / HSECS----------4294967295SQL> / HSECS----------4294967295SQL>





 

本文作者:
eygle,Oracle技術粉絲,來自中國最大的Oracle技術論壇itpub.
www.eygle.com是作者的個人網站.你可通過Guoqiang.Gai@gmail.com來聯絡作者.歡迎技術探討交流以及連結交換.

原文出處:

http://www.eygle.com/case/Job.Can.Not.Execute.Auto.htm

 


相關文章

聯繫我們

該頁面正文內容均來源於網絡整理,並不代表阿里雲官方的觀點,該頁面所提到的產品和服務也與阿里云無關,如果該頁面內容對您造成了困擾,歡迎寫郵件給我們,收到郵件我們將在5個工作日內處理。

如果您發現本社區中有涉嫌抄襲的內容,歡迎發送郵件至: info-contact@alibabacloud.com 進行舉報並提供相關證據,工作人員會在 5 個工作天內聯絡您,一經查實,本站將立刻刪除涉嫌侵權內容。

A Free Trial That Lets You Build Big!

Start building with 50+ products and up to 12 months usage for Elastic Compute Service

  • Sales Support

    1 on 1 presale consultation

  • After-Sales Support

    24/7 Technical Support 6 Free Tickets per Quarter Faster Response

  • Alibaba Cloud offers highly flexible support services tailored to meet your exact needs.