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 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执行。但是没有执行。
2.建立测试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(
1<job>)执行没有任何问题。
2
33.进行恢复尝试
4
5怀疑是CJQ0进程失效，首先设置JOB_QUEUE_PROCESSES为0，Oracle会杀掉CJQ0及相应job进程
6SQL> ALTER SYSTEM SET JOB_QUEUE_PROCESSES = 0;
7
8等2~3分钟，重新设置
9
10SQL> ALTER SYSTEM SET JOB_QUEUE_PROCESSES = 5;
11
12此时PMON会重起CJQ0进程
13
14在警报日志中可以看到以下信息:
15
16>
17> Thu Nov 18 11:59:50 2004
18> ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY;
19> Thu Nov 18 12:01:30 2004
20> ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY;
21> Thu Nov 18 12:01:30 2004
22> Restarting dead background process CJQ0
23> CJQ0 started with pid=8
24
25---
26
27但是Job仍然不执行，而且在再次修改的时候，CJQ0直接死掉了。
28
29>
30> Thu Nov 18 13:52:05 2004
31> ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY;
32> Thu Nov 18 14:09:30 2004
33> ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY;
34> Thu Nov 18 14:10:27 2004
35> ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY;
36> Thu Nov 18 14:10:42 2004
37> ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY;
38> Thu Nov 18 14:31:07 2004
39> ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY;
40> Thu Nov 18 14:40:14 2004
41> ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY;
42> Thu Nov 18 14:40:28 2004
43> ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY;
44> Thu Nov 18 14:40:33 2004
45> ALTER SYSTEM SET job_queue_processes=1 SCOPE=MEMORY;
46> Thu Nov 18 14:40:40 2004
47> ALTER SYSTEM SET job_queue_processes=10 SCOPE=MEMORY;
48> Thu Nov 18 15:00:42 2004
49> ALTER SYSTEM SET job_queue_processes=0 SCOPE=MEMORY;
50> Thu Nov 18 15:01:36 2004
51> ALTER SYSTEM SET job_queue_processes=15 SCOPE=MEMORY;
52>
53
54---
55
564.尝试重起数据库
57这个必须在晚上进行
58
59>
60> PMON started with pid=2
61> DBW0 started with pid=3
62> LGWR started with pid=4
63> CKPT started with pid=5
64> SMON started with pid=6
65> RECO started with pid=7
66> CJQ0 started with pid=8
67> QMN0 started with pid=9
68> ....
69>
70
71---
72
73CJQ0正常启动，但是Job仍然不执行。
74
755.没办法了...
76
77继续研究...居然发现Oralce有这样一个bug
78
791\. Clear description of the problem encountered:
80slgcsf() / slgcs() on Solaris will stop incrementing after
81497 days 2 hrs 28 mins (approx) machine uptime.
82
83
842\. Pertinent configuration information
85No special configuration other than long machine uptime. .
86
873\. Indication of the frequency and predictability of the problem
88100% but only after 497 days.
89
904\. Sequence of events leading to the problem
91If the gethrtime() OS call returns a value > 42949672950000000
92nanoseconds then slgcs() stays at 0xffffffff. This can
93cause some problems in parts of the code which rely on
94slgcs() to keep moving.
95eg: In kkjssrh() does "now = slgcs(&se)" and compares that
96to a previous timestamp. After 497 days uptime slgcs()
97keeps returning 0xffffffff so "now - kkjlsrt" will
98always return 0. .
99
1005\. Technical impact on the customer. Include persistent after effects.
101In this case DBMS JOBS stopped running after 497 days uptime.
102Other symptoms could occur in various places in the code.
103
104好么，原来是计时器溢出了，一检查我的主机:
105
106>
107> bash-2.03$ uptime
108> 10:00pm up 500 day(s), 14:57, 1 user, load average: 1.31, 1.09, 1.08
109> bash-2.03$ date
110> Fri Nov 19 22:00:14 CST 2004
111
112---
113
114刚好到事发时是497天多一点.ft.
115
1166.安排重起主机系统..
117
118这个问题够郁闷的，NND，谁曾想Oracle这都成...
119
120Oracle最后声称:
121
122fix made it into 9.2.0.6 patchset
123
124在Solaris上的9206尚未发布...晕.
125
126好了，就当是个经历吧，如果有问题非常不可思议的话，那么大胆怀疑Oracle吧，是Bug，可能就是Bug。
127
128重起以后问题解决，状态如下:
129
130>
131> $ sqlplus "/ as sysdba"
132>
133> SQL*Plus: Release 9.2.0.3.0 - Production on Fri Nov 26 09:21:21 2004
134>
135> Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.
136>
137>
138> Connected to:
139> Oracle9i Enterprise Edition Release 9.2.0.3.0 - Production
140> With the Partitioning, OLAP and Oracle Data Mining options
141> JServer Release 9.2.0.3.0 - Production
142>
143> SQL> select job,last_date,last_sec,next_date,next_sec from user_jobs;
144>
145> JOB LAST_DATE LAST_SEC NEXT_DATE NEXT_SEC
146> ---------- --------- ---------------- --------- ----------------
147> 70 26-NOV-04 09:21:04 26-NOV-04 09:26:00
148>
149>
150> SQL> /
151>
152> JOB LAST_DATE LAST_SEC NEXT_DATE NEXT_SEC
153> ---------- --------- ---------------- --------- ----------------
154> 70 26-NOV-04 09:26:01 26-NOV-04 09:31:00
155>
156> SQL>
157> SQL> select * from v$timer;
158>
159> HSECS
160> ----------
161> 3388153
162>
163> SQL> select * from v$timer;
164>
165> HSECS
166> ----------
167> 3388319
168>
169> SQL>
170>
171
172---
173
1747.FAQ
175
176一些朋友在Pub上问的问题
177Q:对于不同平台，是否存在同样的问题?
178
179A:对于不同平台，存在同样的问题
180因为Oracle使用了标准C函数gethrtime
181参考:
182http://www.eygle.com/unix/Man.Page.Of.gethrtime.htm
183
184使用了该函数的代码都会存在问题.
185
186在Metalink Note:3427424.8 文档中，Oracle定义的平台影响为:Generic (all / most platforms affected)
187
188Q.计数器溢出，看了看job 中基本都是1天左右执行一次，如果设置 3 天执行一次的 job , 是否出问题的uptime 应该是 497*3 之后呢 ？
189
190A:不会
191
192Oracle内部通过计时器来增进相对时间.
193由于Oracle内部hrtime_t使用了32位计数
194
195那么最大值也就是0xffffffff
1960xffffffff = 4294967295
197
198slgcs()是10亿分之一秒，溢出在42949672950000000这个点上.
199
200注意，这里0xffffffff，达到这个值时，本来是无符号整型，现在变成了-1，那么这个值递增时，+1 = 0了。
201时间就此停住了。
202
203
204我写了一小段代码来验证这个内容，参考：
205
206
207>
208>
209>
210> [oracle@jumper oracle]$ cat unsign.c
211> #include
212> int main(void){
213> unsigned int num = 0xffffffff;
214>
215> printf("num is %d bits long\n", sizeof(num) * 8);
216> printf("num = 0x%x\n", num);
217> printf("num + 1 = 0x%x\n", num + 1);
218>
219> return 0;
220> }
221>
222> [oracle@jumper oracle]$ gcc -o unsign.sh unsign.c
223> [oracle@jumper oracle]$ ./unsign.sh
224> num is 32 bits long
225> **num = 0xffffffff
226> num + 1 = 0x0**
227> [oracle@jumper oracle]$
228>
229
230---
231
232
233Q:内部时钟之一应该就是这个吧： v$timer 精确到1/100 秒的数据
234
235没错!
236
237注意前面说的:
238
2394\. Sequence of events leading to the problem
240If the gethrtime() OS call returns a value > 42949672950000000
241nanoseconds then slgcs() stays at 0xffffffff. This can
242cause some problems in parts of the code which rely on
243slgcs() to keep moving.
244
245也就是说如果gethrtime() 操作系统调用返回值大于42949672950000000（单位10亿分之一秒）
246
247也就是说Oracle将得到一个cs值为4294967295的时间值
248
249而4294967295值就是0xffffffff
250
251所以当时v$timer的计时也就是:
252
253>
254> SQL> select * from v$timer;
255>
256> HSECS
257> ----------
258> 4294967295
259>
260> SQL> /
261>
262> HSECS
263> ----------
264> 4294967295
265>
266> SQL> /
267>
268> HSECS
269> ----------
270> 4294967295
271>
272> SQL>
273>
274
275---
276
277本文作者:
278eygle,Oracle技术关注者,来自中国最大的Oracle技术论坛 itpub .
279www.eygle.com 是作者的个人站点.你可通过 [email protected] 来联系作者.欢迎技术探讨交流以及链接交换.
280
281* * *
282
283原文出处:
284
285http://www.eygle.com/case/Job.Can.Not.Execute.Auto.htm
286
287* * *</job>