ORA-00470: LGWR process terminated with error

2^#

发表于 2012-8-6 19:28:10

Thu Aug  2 17:15:35 2012
GES: Potential blocker (pid=43450460) on resource CF-0x0-0x0;
enqueue info in file /oracle/admin/zdcomora/bdump/zdcomora2_lmd0_37748874.trc and DIAG trace file
Thu Aug  2 17:15:35 2012
Errors in file /oracle/admin/zdcomora/bdump/zdcomora2_lgwr_12976142.trc:
ORA-00600: internal error code, arguments: [2103], [0], [0], [1], [900], [], [], []
Thu Aug  2 17:15:35 2012
Errors in file /oracle/admin/zdcomora/bdump/zdcomora2_lgwr_12976142.trc:
ORA-00600: internal error code, arguments: [2103], [0], [0], [1], [900], [], [], []
Thu Aug  2 17:15:35 2012
LGWR: terminating instance due to error 470

AIX 10.2.0.1 + RAC

LGWR进程终止了实例

LGWR之前一直在等 enq: CF - contention
484432E9:06AAA558 14 158 10005 1 KSL WAIT BEG [enq: CF - contention] 1128660997/0x43460005 0/0x0 0/0x0
484BA64E:06AAA633 14 158 10005 2 KSL WAIT END [enq: CF - contention] 1128660997/0x43460005 0/0x0 0/0x0 time=488292
484BA652:06AAA634 14 158 10005 1 KSL WAIT BEG [enq: CF - contention] 1128660997/0x43460005 0/0x0 0/0x0
485319B7:06AAA750 14 158 10005 2 KSL WAIT END [enq: CF - contention] 1128660997/0x43460005 0/0x0 0/0x0 time=488291
485319BA:06AAA751 14 158 10005 1 KSL WAIT BEG [enq: CF - contention] 1128660997/0x43460005 0/0x0 0/0x0
485A8D1F:06AAA870 14 158 10005 2 KSL WAIT END [enq: CF - contention] 1128660997/0x43460005 0/0x0 0/0x0 time=488291
485A8D23:06AAA871 14 158 10005 1 KSL WAIT BEG [enq: CF - contention] 1128660997/0x43460005 0/0x0 0/0x0
48620087:06AAA961 14 158 10005 2 KSL WAIT END [enq: CF - contention] 1128660997/0x43460005 0/0x0 0/0x0 time=488291
48620089:06AAA962 14 158 10005 1 KSL WAIT BEG [enq: CF - contention] 1128660997/0x43460005 0/0x0 0/0x0
4867DFD8:06AAAA06 14 158 10005 2 KSL WAIT END [enq: CF - contention] 1128660997/0x43460005 0/0x0 0/0x0 time=384846

call stack;

Media recovery not enabled or manual archival only 0x10000
*** 2012-08-02 16:51:40.395
Media recovery not enabled or manual archival only 0x10000
*** 2012-08-02 17:15:35.132
TIMEOUT ON CONTROL FILE ENQUEUE
mode=X, type=0, wait=1, eqt=900
*** 2012-08-02 17:15:35.132
ksedmp: internal or fatal error
ORA-00600: internal error code, arguments: [2103], [0], [0], [1], [900], [], [], []
----- Call Stack Trace -----
calling             call    entry             argument values in hex
location          type    point             (? means dubious value)
-------------------- -------- -------------------- ----------------------------
ksedst+001c       bl    ksedst1             900000000311754 ? 000000000 ?
ksedmp+0290       bl    ksedst             1047CA430 ?
ksfdmp+0018       bl    03F53DA4
kgeriv+0108       bl    _ptrgl
kgesiv+0080       bl    kgeriv             000000020 ? 700000010008000 ?
                                                FFFFFFFFFFFFED0 ? 000000004 ?
                                                10484B7A0 ?
ksesic4+0060       bl    kgesiv             FFFFFFFFFFFCBE0 ? 000000000 ?
                                                FFFFFFFFFFFCC48 ? 000000001 ?
                                                FFFFFFFFFFFD148 ?
kccocx+06c0       bl    ksesic4             83700000837 ? 000000000 ?
                                                000000000 ? 000000000 ?
                                                000000000 ? 000000000 ?
                                                000000001 ? 000000000 ?
kccbcx+0018       bl    kccocx             FFFFFFFFFFFD148 ? 00481211C ?
                                                04A41A910 ? 11003BEA8 ?
kcrfwl+021c       bl    kccbcx             000000000 ? 700000010018148 ?
ksbabs+03a8       bl    _ptrgl
ksbrdp+03e0       bl    _ptrgl
opirip+03fc       bl    01FC6EC0
opidrv+0448       bl    opirip             1103BE410 ? 4103BFD50 ?
                                                FFFFFFFFFFFF330 ?
sou2o+0090          bl    opidrv             3202337C1C ? 4A006EC80 ?
                                                FFFFFFFFFFFF330 ?
opimai_real+0150    bl    01FC1614
main+0098          bl    opimai_real       000000000 ? 000000000 ?
__start+0070       bl    main                000000000 ? 000000000 ?

2100 server/rcv Control File mgmt

*** 2012-08-02 17:15:35.131
DUMP LOCAL BLOCKER/HOLDER: block level 4 res [0x0][0x0],[CF]
----------resource 0x7000002407d0ba8----------------------
resname    : [0x0][0x0],[CF]
Local node : 1
dir_node    : 0
master_node : 0
hv idx       : 95
hv last r.inc : 0
current inc : 8
hv status    : 0
hv master    : 0
open options  : dd
Held mode    : KJUSERPR
Cvt mode    : KJUSERNL
Next Cvt mode : KJUSERNL
msg_seq    : a8e0a8e
res_seq    : 10
grant_bits : KJUSERNL KJUSERCR KJUSERPR
grant mode : KJUSERNL  KJUSERCR  KJUSERCW  KJUSERPR  KJUSERPW  KJUSEREX
count       : 1       1       0       1       0       0
val_state    : KJUSERVS_VALUE
valblk       : 0x0009b3abffffdd780700000010018148 .xH
access_node : 1
vbreq_state : 0
state       : x8
resp       : 7000002407d0ba8
On Scan_q? : N
Total accesses: 24215
Imm.  accesses: 10126
Granted_locks : 2
Cvting_locks  : 1
value_block:  00 09 b3 ab ff ff dd 78 07 00 00 00 10 01 81 48
GRANTED_Q :
lp 700000259297980 gl KJUSERPR rp 7000002407d0ba8 [0x0][0x0],[CF]
  master 0 gl owner 700000257171a20 possible pid 43450460 xid 2002-002E-0000000C bast 0 rseq 10 mseq 0 history 0x495149a5
  open opt KJUSERDEADLOCK  KJUSERIDLK
lp 70000025e3aec90 gl KJUSERCR rp 7000002407d0ba8 [0x0][0x0],[CF]
  master 0 gl owner 70000025817f5a8 possible pid 32899162 xid 0000-000F-0000000A bast 0 rseq 10 mseq 0 history 0x9a5
  open opt KJUSERDEADLOCK  KJUSERIDLK
CONVERT_Q:
lp 7000002592791f8 gl KJUSERNL rl KJUSERPW rp 7000002407d0ba8 [0x0][0x0],[CF]
  master 0 gl owner 700000257183530 possible pid 12976142 xid 2000-000E-00000006 bast 0 rseq 10 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE KJUSERNODEADLOCKWAIT KJUSERTRCCANCEL
----------enqueue 0x700000259297980------------------------
lock version    : 471
Owner node    : 1
grant_level    : KJUSERPR
req_level       : KJUSERPR
bast_level    : KJUSERNL
notify_func    : 0
resp          : 7000002407d0ba8
procp          : 700000257237528
pid             : 43450460
proc version    : 4
oprocp          : 0
opid          : 0
group lock owner : 700000257171a20
possible pid    : 43450460
xid             : 2002-002E-0000000C
dd_time       : 0.0 secs
dd_count       : 0
timeout       : 0.0 secs
On_timer_q?    : N
On_dd_q?       : N
lock_state    : GRANTED
Open Options    : KJUSERDEADLOCK  KJUSERIDLK
Convert options  : KJUSERGETVALUE KJUSERNODEADLOCKWAIT KJUSERTRCCANCEL
History       : 0x495149a5
Msg_Seq       : 0x0
res_seq       : 10
valblk          : 0x0009b3abffffdd780700000010018148 .xH
DUMP LOCAL BLOCKER: initiate state dump for
  possible owner[46.43450460]
Submitting asynchronized dump request [28]
KCC: controlfile sequence number from SGA =  635819

PID 43450460  持有此 CF enqueue lock ，导致 lgwr 12976142 长期无法完成工作

3^#

发表于 2012-8-6 19:33:34

kccocx + 2103 搜索metalink 可以找到bug note:

ODM FINDING:

10.2.0.3 Instance Crash With ORA-600 [2103] Error

Applies to:

Oracle Server - Enterprise Edition - Version: 10.2.0.3 to 10.2.0.3 - Release: 10.2 to 10.2
Information in this document applies to any platform.
Symptoms

-- Problem Statement:
Getting ORA-00600: internal error code, arguments: [2103], [1], [0], [1], [900], [], [], []. After this instance fails due to timeout on control file.

Call stack:

ksedmp kgeriv kgesiv ksesic4 kccocx kcrribcx kcrrcrl_dbc kcrrcrlc kcrrwk ksbcti ksbabs ksbrdp opirip opidrv sou2o opimai_real main start

Cause

Call stack in the trace file matched that of the Bug 7375873 which was closed as a duplicate of Bug 7309327 which was closed as a duplicate of a merged patch on top of 10.2.0.3

Solution

Download and apply patch 8608814

Cause

This has been addressed in the following Bugs:
Bug 4582225 ORA-00600: INTERNAL ERROR CODE, ARGUMENTS: [2103], [0], [0], [1], [900], [], []
Solution

Set the following hidden parameter _CONTROLFILE_ENQUEUE_TIMEOUT > 900 .

一种可选的解决方式是设置控制文件队列超时为900s以上即_CONTROLFILE_ENQUEUE_TIMEOUT > 900 .

实际建议升级数据库到版本10.2.0.5.8

4^#

发表于 2012-8-7 16:39:37

LGWR在等待 enq: CF - contention 时，数据库是什么状态？会挂起吗？

5^#

发表于 2012-8-7 17:11:28

这个是当时段的AWR，可以解释下enq: SQ - contention，row cache lock 分别在干嘛吗？

awr_report_2499_2500.html (349.5 KB, 下载次数: 755)
当时，节点2重启了，跟上面的BUG有关系吗？

6^#

发表于 2012-8-7 17:14:58

enq: SQ - contention    24,680    71,997    2,917    63.1 Configuration
gc domain validation    8,007    15,443    1,929    13.5 Cluster
row cache lock    4,932    12,071    2,448    10.6 Concurrency
gc buffer busy    9,922    9,491    957    8.3 Cluster
gc cr failure    2,581    3,147    1,219    2.8 Cluster

发生问题重启的是2节点，这是1节点经历的 hang，请你在语境里说明清楚， 2节点重启会导致 gcs/ges frozen ，1节点hang住属于意料中的现象，但就这个AWR看 1节点hang 了很久

还是建议至少升级到 10.2.0.5.8

7^#

发表于 2012-8-7 17:16:04

间歇就会有row cache lock wait，

awr_report_2624_2625.html (348.1 KB, 下载次数: 695)

我查到的enq: SQ - contention，P2 值是 144，SYS.AUDSES$ SEQUENCE，能否介绍一下？

8^#

发表于 2012-8-7 21:05:24

Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
row cache lock    4,300    11,481    2,670    47.5 Concurrency
buffer busy waits    5,303    4,956    935    20.5 Concurrency
gc buffer busy    4,710    4,598    976    19.0 Cluster
CPU time         1,265         5.2
library cache pin    407    958    2,354    4.0 Concurrency

TOp 5是主要是解析等待和 buffer busy

硬解析耗费了绝大多数的DB TIME

Soft Parse %:    72.49 软解析率很低
parse time elapsed 12,484.70 51.71
hard parse elapsed time 11,497.50 47.62
sql execute elapsed time 11,308.88 46.84
DB CPU 1,264.62 5.24
sequence load elapsed time 0.04 0.00

sequence load elapsed time    很低

2,375 0 1,718 1.38 9.84 84jtsaytwuj7s    zdcomddbagent@localhost.localdomain (TNS V1-V3) INSERT /*+APPEND*/ INTO T_CA_S...
2,322 11 49,382 0.05 9.62 1dk3s4t7krtba    zdcomddbagent@localhost.localdomain (TNS V1-V3) INSERT /*+APPEND*/ INTO T_JK_L...
2,147 10 49,650 0.04 8.89 b8ba5qu9kamvv    zdcomddbagent@localhost.localdomain (TNS V1-V3) INSERT /*+APPEND*/ INTO T_JK_A...

INSERT /*+APPEND*/ INTO T_CA_STARTENDINF201208(O_TERMINALNO, O_BUSNAME, O_LINENO, O_LINENAME, O_UP , O_SSTATIONNO, O_SSTATIONNOC, O_SSTATIONNAME, O_STARTTIME, O_SDATE, O_STIME, O_SCMDKIND, O_RUNNUMBER, O_BANNUMBER, O_DOWNLINE) VALUES (:V1, :V2, :V3, :V4, :V5, :V6, :V7, :V8, :V9, :V10, :V11, :V12, :V13, :V14, :V15)

这种单条插入用了append ? 有什么意义？而且绑定变量这么多可能导致游标无法共享的

建议你先解决上面的问题

9^#

发表于 2012-8-8 00:55:36

谢谢！很精辟！

参考了以下信息，自己觉得理解了！

http://blog.csdn.net/tianlesoftware/article/details/7239890

https://support.oracle.com/CSP/m ... OT&id=4390868.8

https://support.oracle.com/CSP/m ... =BUG&id=4390868

https://support.oracle.com/CSP/m ... NOT&id=395314.1

https://support.oracle.com/CSP/m ... =BUG&id=2855838

http://www.technicalconferenceso ... NTERNAL&z=16260

枕霜卧雪

10^#

发表于 2012-8-8 09:22:25

精彩，学习了！分析丝丝入扣，步步深入啊。
我们也遇到过10.2.0.4的RAC上的类似问题，最终确定是bug引起的。
因此在采用10g的时候，大师们都建议升级到最新的版本并打上相应的补丁。不是没有道理的。