Oracle診斷案例-Job任務中止執行

時間  2019-11-16
標籤 oracle 診斷 案例 job 任務 中止 執行 欄目 Oracle 简体版
原文   原文鏈接

昨天接到研發人員報告，數據庫定時任務未正常執行，致使某些操做失敗。sql

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

1.首先介入檢查數據庫任務bash

$ 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執行。可是沒有執行。oracle

2.創建測試JOBapp

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(<job>)執行沒有任何問題。函數

3.進行恢復嘗試測試

懷疑是CJQ0進程失效，首先設置JOB_QUEUE_PROCESSES爲0，Oracle會殺掉CJQ0及相應job進程
SQL> ALTER SYSTEM SET JOB_QUEUE_PROCESSES = 0;this

等2~3分鐘，從新設置spa

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;

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

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仍然不執行。

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.08
bash-2.03$ date
Fri 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 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>

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.sh
num is 32 bits long
num = 0xffffffff
num + 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
----------
4294967295

SQL> /                   

     HSECS
----------
4294967295

SQL> /

     HSECS
----------
4294967295

SQL>
相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程