ITPub博客

首页 > Linux操作系统 > Linux操作系统 > RAC生产库出现严重row cache lock和log file switch(archiving need)

RAC生产库出现严重row cache lock和log file switch(archiving need)

原创 Linux操作系统 作者:myownstars 时间:2012-03-30 16:18:28 0 删除 编辑
Oracle:   10.2.0.5  3节点RAC
OS: AIX 6
症状:
早上发现节点1正在经历严重的row cache lock
Alertlog记录如下,
Thu Mar 29 19:54:34 EDT 2012
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=109
Thu Mar 29 19:54:34 EDT 2012
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=110
Thu Mar 29 19:54:34 EDT 2012
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=112
Thu Mar 29 19:54:34 EDT 2012
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=114
Thu Mar 29 19:54:34 EDT 2012
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=115
Thu Mar 29 19:54:35 EDT 2012
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=116
Thu Mar 29 19:54:35 EDT 2012
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=117
Thu Mar 29 20:22:19 EDT 2012
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=118
System State dumped to trace file /orasw/app/oracle/admin/BBB/udump/bbb1_ora_12451870.trc
先用ass109.awk分析该文件,结果显示所有的row cache lock会话都在等待7000000c9acb348
但是并没有holder信息
aaa098[]:/orasw/dba>awk -f ass109.awk /orasw/app/oracle/admin/BBB/udump/bbb1_ora_18284680.trc
Starting Systemstate 1
....................................................
Ass.Awk Version 1.0.9 - Processing /orasw/app/oracle/admin/BBB/udump/bbb1_ora_18284680.trc
System State 1
~~~~~~~~~~~~~~~~
1:                                     
2:  waiting for 'pmon timer'           
3:  waiting for 'DIAG idle wait'       
4:  waiting for 'rdbms ipc message'    
5:  waiting for 'rdbms ipc message'    [Latch received-location:]
6:  waiting for 'ges remote message'   
7:  waiting for 'gcs remote message'   
8:  waiting for 'gcs remote message'   
9:  waiting for 'gcs remote message'   
10: waiting for 'rdbms ipc message'    
11: waiting for 'rdbms ipc message'    
12: waiting for 'rdbms ipc message'    
13: waiting for 'rdbms ipc message'    
14: waiting for 'rdbms ipc message'    
15: last wait for 'smon timer'         
16: waiting for 'rdbms ipc message'    
17: waiting for 'rdbms ipc message'    
18: waiting for 'reliable message'     
19: waiting for 'rdbms ipc message'    
20: waiting for 'rdbms ipc message'    
21: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
22: waiting for 'ASM background timer' 
23: waiting for 'rdbms ipc message'    
24: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
25: waiting for 'rdbms ipc message'    
26: waiting for 'rdbms ipc message'    
27: waiting for 'Streams AQ: qmn coordinator idle wait'
28: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
29: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
30: waiting for 'SQL*Net message from client'
31: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
32: waiting for 'SQL*Net message from client'
33: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
34: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
35: for 'Streams AQ: waiting for messages in the queue'
36: waiting for 'SQL*Net message from client'
37: for 'Streams AQ: waiting for time management or cleanup tasks'
38: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
39: waiting for 'SQL*Net message from client'
40: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
41: waiting for 'SQL*Net message from client'
42: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
43: waiting for 'SQL*Net message from client'
44: waiting for 'SQL*Net message from client'
45: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
46: waiting for 'SQL*Net message from client'
47: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
48: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
49: waiting for 'SQL*Net message from client'
50: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
51: waiting for 'SQL*Net message from client'
52: waiting for 'row cache lock'       [Rcache bject=7000000c9acb348,]
     Cmd: Select
Blockers
~~~~~~~~
        Above is a list of all the processes. If they are waiting for a resource
        then it will be given in square brackets. Below is a summary of the
        waited upon resources, together with the holder of that resource.
        Notes:
        ~~~~~
         o A process id of '???' implies that the holder was not found in the
           systemstate.
                    Resource Holder State
    Latch received-location:    ??? Blocker
Rcache bject=7000000c9acb348,    ??? Blocker
Object Names
~~~~~~~~~~~~
Latch received-location:                      last post received-location: kjmdrms
Rcache bject=7000000c9acb348,                               

查看原文件,搜索7000000c9acb348,发现指向dc_sequences
----------------------------------------
          SO: 700000051376650, type: 50, owner: 7000000c0371d98, flag: INIT/-/-/0x00
          row cache enqueue: count=1 session=7000000c8a00a50 bject=7000000c9acb348, request=X—请求x mode
          savepoint=0x6a7
          row cache parent object: address=7000000c9acb348 cid=13(dc_sequences)
          hash=f9b631e5 typ=11 transaction=7000000c03c3d68 flags=0000012a
          wn=7000000c9acb418[7000000bd2b07e0,7000000bd2b07e0] wat=7000000c9acb428[7000000bd2b05a0,700000051376f80] mode=X
          status=VALID/UPDATE/-/-/IO/-/-/-/-
          request=N release=TRUE flags=0
          instance lock id=QN f9b631e5 53ff802a
          data=
          0000b7d6 0e000002 00020008 00010005 c1020000 00000000 00000000 00000000
          0000c102 00000000 00000000 00000000 00000000 c7646464 64646464 00000000
          00000000 00008000 00000000 00000000 00000000 00000000 c4193e62 14000000
          00000000 00000000 00002d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d
          2d2d2d2d 2d2d2d2d 2d2d0000 00000000
………………
SO: 7000000c8a00a50, type: 4, owner: 7000000cb6624b8, flag: INIT/-/-/0x00—查找对应的session,正在等待row  cache lock,且已经等待了很长时间
    (session) sid: 1030 trans: 7000000c0371d98, creator: 7000000cb6624b8, flag: (8000041) USR/- BSY/-/-/-/-/-
              DID: 0001-0015-00000039, short-term DID: 0001-0015-0000003A
              txn branch: 0
              oct: 3, prv: 0, sql: 7000000c93c3318, psql: 7000000c9304dc8, user: 55/SCRFVAL
    service name: bbb.world
    O/S info: user: ksdl839, term: unknown, ospid: 1234, machine: USSBSOAPINT03
              program: JDBC Thin Client
    application name: JDBC Thin Client, hash value=2546894660
    waiting for 'row cache lock' wait_time=0, seconds since wait started=1662
                cache id=d, mode=0, request=5
                blocking sess=0x0 seq=1118
    Dumping Session Wait History
     for 'row cache lock' count=1 wait_time=2.942778 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929735 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929736 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929740 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929741 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929767 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929737 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929744 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929743 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929737 sec
                cache id=d, mode=0, request=5
对系统做hanganalyze 3, 系统出现了cycle
*** ACTION NAME:() 2012-03-29 22:14:36.569
*** MODULE NAME:(sqlplus@aaa098 (TNS V1-V3)) 2012-03-29 22:14:36.569
*** SERVICE NAME:(SYS$USERS) 2012-03-29 22:14:36.569
*** SESSION ID:(1051.2302) 2012-03-29 22:14:36.569
*** 2012-03-29 22:14:36.569
==============
HANG ANALYSIS:
==============
Found 20 objects waiting for
    <0/1030/79/0xcb6624b8/11206794/row cache lock>
Found 19 objects waiting for
    <0/1034/111/0xc86608e0/47710314/row cache lock>
Cycle 1 : :
    <0/1036/3732/0xcb67d158/8847510/row cache lock>
Cycle 2 : :
    <0/1036/3732/0xcb67d158/8847510/row cache lock>
Cycle 3 : :
    <0/993/2335/0xc866df30/26411190/row cache lock>
Cycle 4 : :
    <0/939/2776/0xc86726a0/27656270/row cache lock>
Open chains found:
Chain 1 : :
    <0/926/17172/0xc8672e90/18284680/row cache lock>
 -- <0/1021/1641/0xc86687e0/33423456/row cache lock>
 -- <0/991/1696/0xc8670ed0/12451870/row cache lock>
Chain 2 : :
    <0/933/4103/0xcb673298/34865224/gc current request>
 -- <0/993/2335/0xc866df30/26411190/row cache lock>
 -- <0/956/46180/0xcb677a08/41746508/row cache lock>
 -- <0/992/16725/0xcb6781f8/17170470/row cache lock>
Chain 3 : :
    <0/942/21768/0xcb66bb88/32374784/gc current request>
 -- <0/944/3668/0xcb67a9a8/36831462/enq: SQ - contention>
 -- <0/1078/3594/0xc8673680/21561442/enq: SQ - contention>
对进程11206794做errorstack跟踪
SQL> oradebug setospid 11206794
Oracle pid: 21, Unix process pid: 11206794, image: oracle@aaa098
SQL> oradebug unlimit
Statement processed.
SQL> oradebug dump errorstack 3
Statement processed.
SQL> oradebug tracefile_name
/orasw/app/oracle/admin/BBB/udump/bbb1_ora_11206794.trc
查看生成的跟踪文件
*** 2012-03-29 21:56:04.878
*** 2012-03-29 21:56:04.878
================================
PROCESS DUMP FROM HANG ANALYZER:
================================
Current SQL statement for this session:
SELECT SHIP _SEQ.NEXTVAL, SYSDATE FROM DUAL
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
7000000b7b46590        48  procedure SUT_ENT
70000009c1eeea8         1  anonymous block
*** 2012-03-29 21:56:04.878
----- Call Stack Trace -----
calling              call     entry                argument values in hex     
location             type     point                (? means dubious value)    
-------------------- -------- -------------------- ----------------------------
ksedst+001c          bl       ksedst1              000000000 ? 000000000 ?
ksedms+00b4          bl       ksedst               104C24078 ?
ksdxfdmp+0358        bl       _ptrgl              
ksdxcb+0500          bl       _ptrgl              
sspuser+0074         bl       _ptrgl              
000047DC             ?        00000000            
sskgpwwait+0034      bl       000D6B30            
skgpwwait+00bc       bl       sskgpwwait           7000000CB662768 ?
                                                   7000000CB6625A8 ?
                                                   7000000CB6624B8 ? 000000000 ?
                                                   000000000 ?
ksliwat+06c0         bl       skgpwwait            101248444 ? 0000493E0 ?
                                                   1037DB578 ? 0CA746D72 ?
                                                   1000D63B8 ?
kslwaitns_timed+002  bl       ksliwat              000000000 ? 000000000 ?
4                                                  FFFFFFFFFFF1DB0 ? 000000000 ?
                                                   000000000 ? 000000000 ?
                                                   000000000 ? 000000000 ?
kskthbwt+0280        bl       kslwaitns_timed      000000000 ? 000000C1E ?
                                                   104F15D54 ? 104F15D5C ?
                                                   104F15D44 ? 7000000CB6625A8 ?
                                                   D124E3FB1E21C9 ? 000000000 ?
kslwait+00f4         bl       kskthbwt             12C0000012C ? D2000000D2 ?
                                                   000000000 ? 00000000D ?
                                                   000000000 ? 000000005 ?
                                                   A00000000000A ?
                                                   38FEC78838FEC788 ?
kqrigt+05e8          bl       kslwait              204F1655C ? 7000000C8A00A50 ?
                                                   00000004E ? 000000058 ?
                                                   3FFC000000000000 ?
                                                   0000165C0 ?
kqrpre1+0968         bl       kqrigt               700000010017FA0 ? 00000FFFF ?
                                                   11045A818 ?
kqrpre+001c          bl       kqrpre1              DFFFF2AB8 ? 110C6B9F8 ?
                                                   FFFFFFFFFFF24A8 ? 1104A9A40 ?
                                                   1100099E0 ? 000000000 ?
                                                   1104763F8 ? 11046A2A8 ?
kdnuca+012c          bl       kqrpre               000000002 ? 110476400 ?
                                                   7000000AED0C9B0 ?
                                                   700000010020900 ?
                                                   7000000C4E0B278 ?
                                                   7000000AED0C9B0 ?
                                                   FFFFFFFFFFF2520 ?
kdnnxt+0098          bl       kdnuca               110C6B290 ? 000000002 ?
                                                   FFFFFFFFFFF26B0 ?
qersqPopulate+00a0   bl       03F385F4            
qersqRowProcedure+0  bl       qersqPopulate        110C6B210 ?
020                                               
qerfiFetch+00a8      bl       03F36AC8            
qersqFetch+00ac      bl       03F36AC8            
opifch2+13e4         bl       01FC3F54            
opiefn0+03e0         bl       opifch2              FFFFFFFFFFF3560 ? 11053F9C8 ?
                                                   FFFFFFFFFFF3478 ?
opipls+211c          bl       opiefn0              300000000 ? 000000000 ?
                                                   FFFFFFFFFFF3738 ?
                                                   2262000000000000 ?
                                                   000000000 ? 000000000 ?
                                                   000000000 ? 000000000 ?
opiodr+0b2c          bl       _ptrgl              
rpidrus+01dc         bl       opiodr               6600000000 ? 610C14188 ?
                                                   FFFFFFFFFFF66D0 ? 60000000C ?
skgmstack+00c8       bl       _ptrgl              
rpidru+0088          bl       skgmstack            FFFFFFFFFFF56F0 ?
                                                   10000011019C568 ? 000000002 ?
                                                   000000000 ? FFFFFFFFFFF5E80 ?
rpiswu2+0368         bl       _ptrgl              
rpidrv+097c          bl       rpiswu2              7000000C8A00A50 ? 11048E898 ?
                                                   11048E8D4 ? 11053FE80 ?
                                                   110509F70 ? 371045AA40 ?
                                                   000000000 ? 000000000 ?
psddr0+02dc          bl       01FC6C64            
psdnal+01d0          bl       psddr0               600000000 ? 66FFFF6850 ?
                                                   FFFFFFFFFFF66D0 ?
                                                   30FFFF7D68 ?
pevm_EXECC+01f8      bl       _ptrgl              
pfrinstr_EXECC+0070  bl       pevm_EXECC           10187D084 ? 110232BB8 ?
                                                   10187B754 ?
pfrrun_no_tool+005c  bl       _ptrgl              
pfrrun+1064          bl       pfrrun_no_tool       FFFFFFFFFFF6FD8 ? 110506850 ?
                                                   FFFFFFFFFFF6A30 ?
plsql_run+06e8       bl       pfrrun               110507A08 ?
peicnt+0244          bl       plsql_run            110507A08 ? 100007E588440 ?
                                                   000000000 ?
kkxexe+0250          bl       peicnt               FFFFFFFFFFF7D68 ? 110507A08 ?
opiexe+3024          bl       kkxexe               110506850 ?
kpoal8+0ef0          bl       opiexe               FFFFFFFFFFFB3E4 ?
                                                   FFFFFFFFFFFB138 ?
                                                   FFFFFFFFFFF9580 ?
opiodr+0b2c          bl       _ptrgl              
ttcpip+1020          bl       _ptrgl              
opitsk+117c          bl       01FC66D4            
opiino+09d0          bl       opitsk               0FFFFD3B0 ? 000000000 ?
opiodr+0b2c          bl       _ptrgl              
opidrv+04a4          bl       opiodr               3C10290FD8 ? 404C76C50 ?
                                                   FFFFFFFFFFFF370 ? 010290FD0 ?
sou2o+0090           bl       opidrv               3C02A2B3BC ? 4A0071E60 ?
                                                   FFFFFFFFFFFF370 ?
opimai_real+01bc     bl       01FC2B94            
main+0098            bl       opimai_real          000000000 ? 000000000 ?
__start+0070         bl       main                 000000000 ? 000000000 ?
……
PROCESS STATE
-------------
Process global information:
     process: 7000000cb6624b8, call: 7000000bd547820, xact: 7000000c0371d98, curses: 7000000c8a00a50, usrses: 7000000c8a00a50
  ----------------------------------------
  SO: 7000000cb6624b8, type: 2, owner: 0, flag: INIT/-/-/0x00
  (process) Oracle pid=21, calls cur/top: 7000000bd547820/7000000c8ab64e0, flag: (0) -
            int error: 0, call error: 0, sess error: 0, txn error 0
  (post info) last post received: 0 0 0
              last post received-location: No post
              last process to post me: none
              last post sent: 0 0 0
              last post sent-location: No post
              last process posted by me: none
    (latch info) wait_event=0 bits=0
    Process Group: DEFAULT, pseudo proc: 7000000cb757778
    O/S info: user: oracle, term: UNKNOWN, ospid: 11206794
    OSD pid info: Unix process pid: 11206794, image: oracle@aaa098
    (FOB) flags=2 fib=7000000c1db78b0 incno=0 pending i/o cnt=0
     fname=/dev/db030
     fno=32 lblksz=512 fsiz=1
    ----------------------------------------
    SO: 7000000b8318168, type: 83, owner: 7000000cb6624b8, flag: INIT/-/-/0x00
    freelist:[7000000b7b35980,7000000b7b35980]
      KFFMOP: hash link:[7000000b7b35970,7000000b7b35970] sobj link:[7000000b8318188,7000000b8318188]
        map kggrp:[0x7000000cab8fc58, 0, valid]  map id:15
        group:[2,2008082090] file:[328,745576843] extent:11683
        flags:0x0000 disk:29 au:34101 lock:0 proc:0x7000000cb6624b8
    busylist:[7000000b8318198,7000000b8318198]
    transistion:0x0
    (FOB) flags=512 fib=7000000c1dbc698 incno=0 pending i/o cnt=0
     fname=+DATA_DG/bbb/datafile/scrfval_data.328.745576843
     fno=11 lblksz=8192 fsiz=4096000
    ----------------------------------------
    SO: 7000000c8a00a50, type: 4, owner: 7000000cb6624b8, flag: INIT/-/-/0x00
    (session) sid: 1030 trans: 7000000c0371d98, creator: 7000000cb6624b8, flag: (8000041) USR/- BSY/-/-/-/-/-
              DID: 0001-0015-00000039, short-term DID: 0001-0015-0000003A
              txn branch: 0
              oct: 3, prv: 0, sql: 7000000c93c3318, psql: 7000000c9304dc8, user: 55/SCRFVAL
    service name: bbb.world
    O/S info: user: ksdl839, term: unknown, ospid: 1234, machine: USSBSOAPINT03
              program: JDBC Thin Client
    application name: JDBC Thin Client, hash value=2546894660
    waiting for 'row cache lock' wait_time=0, seconds since wait started=1899
                cache id=d, mode=0, request=5
                blocking sess=0x0 seq=1118
    Dumping Session Wait History
     for 'row cache lock' count=1 wait_time=2.929746 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929788 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929741 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929748 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929770 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929739 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929733 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929748 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929741 sec
                cache id=d, mode=0, request=5
     for 'row cache lock' count=1 wait_time=2.929776 sec
                cache id=d, mode=0, request=5
Sampled Session History of session 1030 serial 79
根据跟踪文件可以看出,该session经历了严重的row cache lock且正在等待
SELECT SHIP_EVENT_LOG_SEQ.NEXTVAL, SYSDATE FROM DUAL
而根据前面systemstate dump可以看出row cache lock正在等待dc_sequence,基本可以确定是该sequence惹的祸,其cache为0

于此同时第2个节点也出现了问题
查看其Alert log,发现从3月27号就一直出现问题
Tue Mar 27 13:25:28 EDT 2012
Process startup failed, error stack:
Tue Mar 27 13:25:28 EDT 2012
Errors in file /orasw/app/oracle/admin/BBB/bdump/bbb2_psp0_1986702.trc:
ORA-27300: OS system dependent operation:fork failed with status: 12
ORA-27301: OS failure message: Not enough space
ORA-27302: failure occurred at: skgpspawn3
Tue Mar 27 13:25:28 EDT 2012
ERROR: Failed to connect with connect string:(DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/orasw/app/oracle/product/11.1.0/asm/bin/oracle)(ARGV0=oracle+ASM2)(ENVS='ORACLE_HOME=/
orasw/app/oracle/product/11.1.0/asm,ORACLE_SID=+ASM2')(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))'))(enable=setuser))
Tue Mar 27 13:25:29 EDT 2012
Process J000 died, see its trace file
Tue Mar 27 13:25:29 EDT 2012
kkjcre1p: unable to spawn jobq slave process
Tue Mar 27 13:25:29 EDT 2012
Errors in file /orasw/app/oracle/admin/BBB/bdump/bbb2_cjq0_2220068.trc:
Tue Mar 27 13:25:29 EDT 2012—不能连接ASM
ERROR: Failed to connect with connect string:(DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/orasw/app/oracle/product/11.1.0/asm/bin/oracle)(ARGV0=oracle+ASM2)(ENVS='ORACLE_HOME=/
orasw/app/oracle/product/11.1.0/asm,ORACLE_SID=+ASM2')(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))'))(enable=setuser))
ERROR: Failed to connect with connect string:(DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/orasw/app/oracle/product/11.1.0/asm/bin/oracle)(ARGV0=oracle+ASM2)(ENVS='ORACLE_HOME=/
orasw/app/oracle/product/11.1.0/asm,ORACLE_SID=+ASM2')(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))'))(enable=setuser))
ERROR: Failed to connect with connect string:(DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/orasw/app/oracle/product/11.1.0/asm/bin/oracle)(ARGV0=oracle+ASM2)(ENVS='ORACLE_HOME=/
orasw/app/oracle/product/11.1.0/asm,ORACLE_SID=+ASM2')(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))'))(enable=setuser))
Tue Mar 27 13:25:30 EDT 2012
Errors in file /orasw/app/oracle/admin/BBB/bdump/bbb2_arc0_19370208.trc:
ORA-00313: open failed for members of log group 22 of thread 2
ORA-00312: online log 22 thread 2: '+REDO_DG2/bbb/onlinelog/group_22.281.741544481'
ORA-17503: ksfdopn:2 Failed to open file +REDO_DG2/bbb/onlinelog/group_22.281.741544481
ORA-15055: unable to connect to ASM instance
ORA-12549: TNS:operating system resource quota exceeded
ORA-15055: unable to connect to ASM instance
ORA-12549: TNS:operating system resource quota exceeded
ORA-00312: online log 22 thread 2: '+REDO_DG1/bbb/onlinelog/group_22.282.741544479'
ORA-17503: ksfdopn:2 Failed to open file +REDO_DG1/bbb/onlinelog/group_22.282.741544479
ORA-15055: unable to connect to ASM instance
ORA-12549: TNS:operating system resource quota exceeded
ORA-15055: unable to connect to ASM instance
ORA-12549: TNS:operating system resource quota exceeded
……………………………………..
Unexpected communication failure with ASM instance:
 error 1041 (ORA-01041: internal error. hostdef extension doesn't exist
)
NOTE: ASMB process state dumped to trace file /orasw/app/oracle/admin/BBB/bdump/bbb2_arc0_19370208.trc
Thu Mar 29 22:44:24 EDT 2012
Unexpected communication failure with ASM instance:
 error 1041 (ORA-01041: internal error. hostdef extension doesn't exist
)
NOTE: ASMB process state dumped to trace file /orasw/app/oracle/admin/BBB/bdump/bbb2_arc0_19370208.trc
Thu Mar 29 22:44:25 EDT 2012
Errors in file /orasw/app/oracle/admin/BBB/bdump/bbb2_arc0_19370208.trc:
ORA-00313: open failed for members of log group 22 of thread 2
ORA-00312: online log 22 thread 2: '+REDO_DG2/bbb/onlinelog/group_22.281.741544481'
ORA-17503: ksfdopn:2 Failed to open file +REDO_DG2/bbb/onlinelog/group_22.281.741544481
ORA-01041: internal error. hostdef extension doesn't exist
ORA-00312: online log 22 thread 2: '+REDO_DG1/bbb/onlinelog/group_22.282.741544479'
ORA-17503: ksfdopn:2 Failed to open file +REDO_DG1/bbb/onlinelog/group_22.282.741544479
ORA-01041: internal error. hostdef extension doesn't exist
查看跟踪文件
aaa099[]:/orasw/dba>more /orasw/app/oracle/admin/BBB/bdump/bbb2_arc1_18018544.trc
Dump file /orasw/app/oracle/admin/BBB/bdump/bbb2_arc1_18018544.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options
ORACLE_HOME = /orasw/app/oracle/product/10.2.0.5
System name:    AIX
Node name:      aaa099
Release:        1
Version:        6
Machine:        00CA36B54C00
Instance name: bbb2
Redo thread mounted by this instance: 2
Oracle process number: 26
Unix process pid: 18018544, image: oracle@aaa099 (ARC1)
*** 2012-03-27 11:20:22.367
*** SERVICE NAME:(SYS$BACKGROUND) 2012-03-27 11:20:22.366
*** SESSION ID:(1076.1) 2012-03-27 11:20:22.366
WARNING: kfnUseConn - failure to make a connection—MOS/google找不到一条记录,baidu居然能搜到两条记录,不过没有相应解释
WARNING: kfnUseConn - failure to make a connection
WARNING: kfnUseConn - failure to make a connection
WARNING: kfnUseConn - failure to make a connection
ORA-00313: open failed for members of log group 22 of thread 2
ORA-00312: online log 22 thread 2: '+REDO_DG2/bbb/onlinelog/group_22.281.741544481'
ORA-17503: ksfdopn:2 Failed to open file +REDO_DG2/bbb/onlinelog/group_22.281.741544481
ORA-15055: unable to connect to ASM instance
ORA-12549: TNS:operating system resource quota exceeded
ORA-15055: unable to connect to ASM instance
ORA-12549: TNS:operating system resource quota exceeded
ORA-00312: online log 22 thread 2: '+REDO_DG1/bbb/onlinelog/group_22.282.741544479'
ORA-17503: ksfdopn:2 Failed to open file +REDO_DG1/bbb/onlinelog/group_22.282.741544479
ORA-15055: unable to connect to ASM instance
ORA-12549: TNS:operating system resource quota exceeded
ORA-15055: unable to connect to ASM instance
ORA-12549: TNS:operating system resource quota exceeded
ORA-00313: open failed for members of log group 22 of thread 2
ORA-00312: online log 22 thread 2: '+REDO_DG2/bbb/onlinelog/group_22.281.741544481'
ORA-17503: ksfdopn:2 Failed to open file +REDO_DG2/bbb/onlinelog/group_22.281.741544481
ORA-15055: unable to connect to ASM instance
ORA-12549: TNS:operating system resource quota exceeded
ORA-15055: unable to connect to ASM instance
ORA-12549: TNS:operating system resource quota exceeded
ORA-00312: online log 22 thread 2: '+REDO_DG1/bbb/onlinelog/group_22.282.741544479'
ORA-17503: ksfdopn:2 Failed to open file +REDO_DG1/bbb/onlinelog/group_22.282.741544479
ORA-15055: unable to connect to ASM instance
ORA-12549: TNS:operating system resource quota exceeded
ORA-15055: unable to connect to ASM instance
ORA-12549: TNS:operating system resource quota exceeded
logfile 22 open failed:313
*** 2012-03-27 11:20:24.804 22384 kcrr.c—从3月27号就出现以下错误
ORA-16038: log 22 sequence# 1370 cannot be archived
ORA-00312: online log 22 thread 2: '+REDO_DG1/bbb/onlinelog/group_22.282.741544479'
ORA-00312: online log 22 thread 2: '+REDO_DG2/bbb/onlinelog/group_22.281.741544481'
*** 2012-03-27 11:20:40.329 logfile 22 open failed:313
做hanganalyze 3查看输出文件
==============
HANG ANALYSIS:
==============
Open chains found:
Chain 1 : :
    <1/1091/1/0xcb6604f8/7889148/rdbms ipc message>
 -- <1/950/34226/0xcb665c48/2396294/log file switch (archiving neede>
Other chains found:
Chain 2 : :
    <1/951/16693/0xc865d940/2535526/log file switch (archiving neede>
Chain 3 : :
    <1/954/5565/0xcb6624b8/213064/log file switch (archiving neede>
 -- <1/967/13888/0xc865b190/27140236/row cache lock>
Chain 4 : :
    <1/958/23461/0xc865f110/2371616/log file switch (archiving neede>
Chain 5 : :
    <1/1012/27628/0xc86599c0/794856/Streams AQ: qmn slave idle wait>
Chain 6 : :
    <1/1017/26902/0xcb664c68/6947064/No Wait>
Chain 7 : :
    <1/1062/1/0xc865d150/17821858/Streams AQ: waiting for time man>
Chain 8 : :
    <1/1074/1/0xcb663c88/1941564/Streams AQ: qmn coordinator idle>
Chain 9 : :
    <1/1082/1255/0xcb6683f8/954558/log file switch (archiving neede>
 -- <1/1086/1/0xc86581f0/1982594/buffer busy waits>
Chain 10 : :
    <1/1089/1/0xcb660ce8/1564852/buffer busy waits>
Chain 11 : :
    <1/1104/1/0xcb65dd48/20168766/DIAG idle wait>
Extra information that will be dumped at higher levels:
[level  4] :   1 node dumps -- [REMOTE_WT] [LEAF] [LEAF_NW]
[level  5] :   5 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]
[level  6] :   8 node dumps -- [NLEAF]
[level 10] :  30 node dumps -- [IGN]
发现很多log file switch(archiving needed)等待,
登陆ASM实例查看,diskgroup还有很多空余
SQL> select GROUP_NUMBER,NAME,FREE_MB from v$asm_diskgroup;
GROUP_NUMBER NAME                              FREE_MB
------------ ------------------------------ ----------
           1 ARCH_DG                           1048611
           2 DATA_DG                           1567056
           3 FRA_DG                             810885
           4 REDO_DG1                            31852
           5 REDO_DG2                            31876
           6 TEMP_DG                           1821433
该数据库把归档日志都放在了db_recovery_file_dest 路径下,当该路径用完时,也会导致无法归档
SQL> archive log list;
Database log mode              Archive Mode
Automatic archival             Enabled
Archive destination            USE_DB_RECOVERY_FILE_DEST
Oldest online log sequence     1379
Next log sequence to archive   1381
Current log sequence           1381
SQL> show parameter db_re
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_recovery_file_dest                string      +FRA_DG
db_recovery_file_dest_size           big integer 1050G
db_recycle_cache_size                big integer 0
但是alertlog中并没有db_recovery_file_dest爆满的记录,相应视图显示结果也很正常
SQL> select * from V$FLASH_RECOVERY_AREA_USAGE;
FILE_TYPE    PERCENT_SPACE_USED PERCENT_SPACE_RECLAIMABLE NUMBER_OF_FILES
------------ ------------------ ------------------------- ---------------
CONTROLFILE                   0                         0               0
ONLINELOG                     0                         0               0
ARCHIVELOG                 3.46                         0              67
BACKUPPIECE                41.6                         0              80
IMAGECOPY                     0                         0               0
FLASHBACKLOG                  0                         0               0
此时大致推测应该是arch进程出现了问题
SQL> show parameter log_archive_max_processes
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
log_archive_max_processes            integer     2
arch进程只有两个,将其调大至4,然后等待几分钟,数据库自动回复正常
节点2的alert再没有出现error记录,也可以正常执行alter system switch logfile;
此时再去看节点1,row cache lock消失了,而且查看v$视图也可以立即返回结果
小结:
3节点RAC有两个节点出现问题,节点1是由于row cache lock导致的hang,节点2则是因为不能归档而hang;
节点1是由于sequence的cache设置为0造成的,以往也有类似情况发生,但是查询v$视图则可很快返回结果,这次显得很诡异;
节点2出现问题好几天了,先是alert不断记录ora-27302 & skgpspawn3,应该是swap分区不足造成的(560309.1),不过系统没有安装osw,找不到当时的内存使用情况,后来出现无法连接ASM实例以及一系列错误,
Redo log不能归档导致系统hang,查看归档路径使用情况后,最后尝试增加arch进程数目,系统恢复正常;
更诡异的是,节点2恢复正常后节点1也正常了,不知道两者是否有什么内在联系

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/15480802/viewspace-719940/,如需转载,请注明出处,否则将追究法律责任。

下一篇: 11g AMM和/dev/shm
请登录后发表评论 登录
全部评论

注册时间:2010-03-18

  • 博文量
    375
  • 访问量
    3095008