Oracle诊断案例-Job任务中止执行

时间 2019-11-16

原文原文链接

昨天接到研发人员报告，数据库定时任务未正常执行，致使某些操做失败。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 秒的数据

没错!

注意前面说的:

也就是说若是gethrtime() 操做系统调用返回值大于42949672950000000（单位10亿分之一秒）

也就是说Oracle将获得一个cs值为4294967295的时间值

而4294967295值就是0xffffffff

因此当时v$timer的计时也就是:

SQL> select * from v$timer;

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

SQL> /                   

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

SQL> /

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

SQL>