oracle exfsys 下 rlm$evtcleanup,记一次数据库无法增删改趋于HANG住状态的故障诊断和处理 -电脑资料...

[165]/0/166/1/0x83b8bfc8/3044/IGN/59/60//none

[166]/0/167/1/0x83b8d530/3042/IGN/61/62//none

[167]/0/168/1/0x83b8ea98/3040/IGN/63/64//none

[168]/0/169/1/0x83b90000/3038/IGN/65/66//none

[169]/0/170/1/0x83b91568/3036/IGN/67/68//none

做了SYSTEMSTATE DUMP:用ass对SYSTEMSTATE处理以后:System State 1

~~~~~~~~~~~~~~~~

1:

2: waiting for 'pmon timer' wait

3: waiting for 'rdbms ipc message' wait

4: waiting for 'rdbms ipc message' wait

5: waiting for 'rdbms ipc message' wait

6: waiting for 'rdbms ipc message' wait

7: waiting for 'rdbms ipc message' wait

8: waiting for 'rdbms ipc reply' wait

9: waiting for 'rdbms ipc message' wait

10: waiting for 'rdbms ipc message' wait

11: waiting for 'log file switch (checkpoint incomplete)' wait

12: waiting for 'rdbms ipc message' wait

13:

14:

15: waiting for 'switch logfile command' wait

16: waiting for 'rdbms ipc message' wait

17: waiting for 'rdbms ipc message' wait

18: waiting for 'Streams AQ: qmn coordinator idle wait' wait

19: waiting for 'log file switch (checkpoint incomplete)' wait

Cmd: Insert

20: for 'Streams AQ: waiting for time management or cleanup tasks' wait

21: waiting for 'Streams AQ: qmn slave idle wait' wait

22: waiting for 'enq: CI - contention' [Enqueue CI-00000001-00000005] wait

23: waiting for 'enq: WF - contention' [Enqueue WF-00000000-00000000] wait

Cmd: PL/SQL Execute

24: waiting for 'SQL*Net message from client' wait

25: waiting for 'buffer busy waits' (2,9,11) wait

Cmd: Select

26: waiting for 'enq: TX - row lock contention'[Enqueue TX-0009001E-00000299] wait

27: waiting for 'log file switch (checkpoint incomplete)' wait

Cmd: Insert

28: waiting for 'log file switch (checkpoint incomplete)' wait

29: waiting for 'library cache lock' [LOCK: handle=7ef56d78] wait

30: waiting for 'buffer busy waits' (1,2ba2,1) wait

31: waiting for 'library cache lock' [LOCK: handle=7ef56f88] wait

32: waiting for 'library cache lock' [LOCK: handle=7ef56d78] wait

33: waiting for 'library cache lock' [LOCK: handle=7ef56d78] wait

34: waiting for 'library cache lock' [LOCK: handle=7ef56f88] wait

35: waiting for 'library cache lock' [LOCK: handle=7ef56f88] wait

36: waiting for 'library cache lock' [LOCK: handle=7ef56d78] wait

37: last wait for 'ksdxexeotherwait'

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

Enqueue CI-00000001-00000005 8: waiting for 'rdbms ipc reply'

Enqueue WF-00000000-00000000 22: 22: is waiting for 8:

Enqueue TX-0009001E-00000299 22: 22: is waiting for 8:

LOCK: handle=7ef56d78 28: waiting for 'log file switch (checkpoint incomplete)'

LOCK: handle=7ef56f88 30: waiting for 'buffer busy waits' (1,2ba2,1)

Object Names

~~~~~~~~~~~~

Enqueue CI-00000001-00000005

Enqueue WF-00000000-00000000

Enqueue TX-0009001E-00000299

LOCK: handle=7ef56d78 TABL:EXFSYS.RLM$SCHDNEGACTION

LOCK: handle=7ef56f88 TABL:EXFSYS.RLM$EVTCLEANUP

System State 2

~~~~~~~~~~~~~~~~

1:

2: waiting for 'pmon timer' wait

3: waiting for 'rdbms ipc message' wait

4: waiting for 'rdbms ipc message' wait

5: waiting for 'rdbms ipc message' wait

6: waiting for 'rdbms ipc message' wait

7: waiting for 'rdbms ipc message' wait

8: waiting for 'rdbms ipc reply' wait

9: waiting for 'rdbms ipc message' wait

10: waiting for 'rdbms ipc message' wait

11: waiting for 'log file switch (checkpoint incomplete)' wait

12: waiting for 'rdbms ipc message' wait

13:

14:

15: waiting for 'switch logfile command' wait

16: waiting for 'rdbms ipc message' wait

17: waiting for 'rdbms ipc message' wait

18: waiting for 'Streams AQ: qmn coordinator idle wait' wait

19: waiting for 'log file switch (checkpoint incomplete)' wait

Cmd: Insert

20: for 'Streams AQ: waiting for time management or cleanup tasks' wait

21: waiting for 'Streams AQ: qmn slave idle wait' wait

22: waiting for 'enq: CI - contention' [Enqueue CI-00000001-00000005] wait

23: waiting for 'enq: WF - contention' [Enqueue WF-00000000-00000000] wait

Cmd: PL/SQL Execute

24: waiting for 'SQL*Net message from client' wait

25: waiting for 'buffer busy waits' (2,9,11) wait

Cmd: Select

26: waiting for 'enq: TX - row lock contention'[Enqueue TX-0009001E-00000299] wait

27: waiting for 'log file switch (checkpoint incomplete)' wait

Cmd: Insert

28: waiting for 'log file switch (checkpoint incomplete)' wait

29: waiting for 'library cache lock' [LOCK: handle=7ef56d78] wait

30: waiting for 'buffer busy waits' (1,2ba2,1) wait

31: waiting for 'library cache lock' [LOCK: handle=7ef56f88] wait

32: waiting for 'library cache lock' [LOCK: handle=7ef56d78] wait

33: waiting for 'library cache lock' [LOCK: handle=7ef56d78] wait

34: waiting for 'library cache lock' [LOCK: handle=7ef56f88] wait

35: waiting for 'library cache lock' [LOCK: handle=7ef56f88] wait

36: waiting for 'library cache lock' [LOCK: handle=7ef56d78] wait

37: last wait for 'ksdxexeotherwait'

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

Enqueue CI-00000001-00000005 8: waiting for 'rdbms ipc reply'

Enqueue WF-00000000-00000000 22: 22: is waiting for 8:

Enqueue TX-0009001E-00000299 22: 22: is waiting for 8:

LOCK: handle=7ef56d78 28: waiting for 'log file switch (checkpoint incomplete)'

LOCK: handle=7ef56f88 30: waiting for 'buffer busy waits' (1,2ba2,1)

Object Names

~~~~~~~~~~~~

Enqueue CI-00000001-00000005

Enqueue WF-00000000-00000000

Enqueue TX-0009001E-00000299

LOCK: handle=7ef56d78 TABL:EXFSYS.RLM$SCHDNEGACTION

LOCK: handle=7ef56f88 TABL:EXFSYS.RLM$EVTCLEANUP

List of Processes That May Be Stuck

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

8: waiting for 'rdbms ipc reply' wait

11: waiting for 'log file switch (checkpoint incomplete)' wait

15: waiting for 'switch logfile command' wait

18: waiting for 'Streams AQ: qmn coordinator idle wait' wait

19: waiting for 'log file switch (checkpoint incomplete)' wait

20: for 'Streams AQ: waiting for time management or cleanup tasks' wait

21: waiting for 'Streams AQ: qmn slave idle wait' wait

22: waiting for 'enq: CI - contention' wait

23: waiting for 'enq: WF - contention' wait

24: waiting for 'SQL*Net message from client' wait

25: waiting for 'buffer busy waits' (2,9,11) wait

26: waiting for 'enq: TX - row lock contention' wait

27: waiting for 'log file switch (checkpoint incomplete)' wait

28: waiting for 'log file switch (checkpoint incomplete)' wait

29: waiting for 'library cache lock' wait

30: waiting for 'buffer busy waits' (1,2ba2,1) wait

31: waiting for 'library cache lock' wait

32: waiting for 'library cache lock' wait

33: waiting for 'library cache lock' wait

34: waiting for 'library cache lock' wait

35: waiting for 'library cache lock' wait

36: waiting for 'library cache lock' wait

SO: 0x83b5fd60, type: 4, owner: 0x83a69028, flag: INIT/-/-/0x00

(session) sid: 133 trans: 0x822d5790, creator: 0x83a69028, flag: (41) USR/- BSY/-/-/-/-/-

DID: 0001-001C-00000002, short-term DID: 0000-0000-00000000

txn branch: (nil)

oct: 0, prv: 0, sql: (nil), psql: (nil), user: 0/SYS

service name: SYS$USERS

O/S info: user: oracle, term: UNKNOWN,ospid: 4790, machine: ora10g

program: oracle@ora10g (J001)

waiting for 'log file switch (checkpoint incomplete)' blocking sess=0x(nil) seq=1 wait_time=0 seconds since wait started=12130

=0, =0, =0

Dumping Session Wait History

for 'log file switch (checkpoint incomplete)' count=1 wait_time=1107898

=0, =0, =0

for 'log file switch (checkpoint incomplete)' count=1 wait_time=336 ...

PROCESS 8:

----------------------------------------

SO: 0x83a5f208, type: 2, owner: (nil), flag: INIT/-/-/0x00

(process) Oracle pid=8, calls cur/top: 0x83ba9a28/0x83ba9a28, flag: (16) SYSTEM

int error: 0, call error: 0, sess error: 0, txn error 0

(post info) last post received: 0 0 33

last post received-location: ksrpublish

last process to post me: 83a68840 1 0

last post sent: 0 0 24

last post sent-location: ksasnd

last process posted by me: 83a5ea20 1 6

(latch info) wait_event=0 bits=0

Process Group: DEFAULT, pseudo proc: 0x83aa67e8

O/S info: user: oracle, term: UNKNOWN, ospid: 3048

OSD pid info: Unix processpid: 3048, image: oracle@ora10g (SMON)

Short stack dump: ...

PROCESS 22:

----------------------------------------

SO: 0x83a660b8, type: 2, owner: (nil), flag: INIT/-/-/0x00

(process) Oracle pid=22, calls cur/top: 0x83bafe00/0x83bafb40, flag: (2) SYSTEM

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 24

last post sent-location: ksasnd

last process posted by me: 83a5e238 1 6

(latch info) wait_event=0 bits=0

Process Group: DEFAULT, pseudo proc: 0x83aa67e8

O/S info: user: oracle, term: UNKNOWN, ospid:4402

OSD pid info: Unix process pid: 4402, image: oracle@ora10g (m000)

Short stack dump:

自此,把注意力转移至SMON进程，首先检查SMON的trace文件： /u01/app/oracle/admin/ora10g/bdump/ora10g_smon_3048.trc

Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options

ORACLE_HOME = /u01/app/oracle/product/10.2.0

System name: Linux

Node name: ora10g

Release: 2.6.18-194.el5

Version: #1 SMP Tue Mar 16 21:52:39 EDT 2010

Machine: x86_64

Instance name: ora10g

Redo thread mounted by this instance: 1

Oracle process number: 8

Unix process pid: 3048, image: oracle@ora10g (SMON)

*** 2015-03-21 17:34:17.611

*** SERVICE NAME:(SYS$BACKGROUND) 2015-03-21 17:34:17.611

*** SESSION ID:(164.1) 2015-03-21 17:34:17.611

Waited for detached process: CKPT for 300 seconds:

*** 2015-03-21 17:34:17.611

Dumping diagnostic information for CKPT:

OS pid = 3046

loadavg : 0.00 0.00 0.00

memory info: free memory = 0.00M

swap info: free = 0.00M alloc = 0.00M total = 0.00M

F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD

0 S oracle30461 0 75 0 - 184266 - 17:24 ? 00:00:00 ora_ckpt_ora10g

[Thread debugging using libthread_db enabled]

0x00000035cc2d517a in semtimedop () from /lib64/libc.so.6

#0 0x00000035cc2d517a in semtimedop () from /lib64/libc.so.6

#1 0x0000000003be9b09 in sskgpwwait ()

#2 0x0000000003bccdf0 in skgpwwait ()

#3 0x0000000000855f4a in ksdxsus ()

#4 0x0000000000857118 in ksdxffrz ()

#5 0x0000000000853003 in ksdxcb ()

#6 0x0000000001ebd0cf in sspuser ()

#7

#8 0x00000035cc2d517a in semtimedop () from /lib64/libc.so.6

#9 0x0000000003be9b09 in sskgpwwait ()

#10 0x0000000003bccdf0 in skgpwwait ()

#11 0x0000000000798319 in kslwaitns_timed ()

#12 0x00000000008c3b1d in kskthbwt ()

#13 0x0000000000797e54 in kslwait ()

#14 0x00000000029f3f3b in ksarcv ()

#15 0x000000000082e8bf in ksbabs ()

#16 0x0000000000835822 in ksbrdp ()

#17 0x0000000002f4d840 in opirip ()

#18 0x000000000132b016 in opidrv ()

#19 0x0000000001eb3146 in sou2o ()

#20 0x0000000000723245 in opimai_real ()

#21 0x00000000007230fc in main ()

A debugging session is active.

Inferior 1 [process 3046] will be detached.

Quit anyway? (y or n) [answered Y; input not from terminal]

*** 2015-03-21 17:34:19.125

*** 2015-03-21 17:34:29.129

Waited for detached process: CKPT for 310 seconds:

*** 2015-03-21 17:34:29.129

Dumping diagnostic information for CKPT:

OS pid = 3046

loadavg : 0.07 0.02 0.00

memory info: free memory = 0.00M

swap info: free = 0.00M alloc = 0.00M total = 0.00M

F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD

0 S oracle 3046 1 0 75 0 - 184266 - 17:24 ? 00:00:00 ora_ckpt_ora10g

[Thread debugging using libthread_db enabled]

0x00000035cc2d517a in semtimedop () from /lib64/libc.so.6

#0 0x00000035cc2d517a in semtimedop () from /lib64/libc.so.6

#1 0x0000000003be9b09 in sskgpwwait ()

#2 0x0000000003bccdf0 in skgpwwait ()

#3 0x0000000000855f4a in ksdxsus ()

#4 0x0000000000857118 in ksdxffrz ()

#5 0x0000000000853003 in ksdxcb ()

#6 0x0000000001ebd0cf in sspuser ()

#7

#8 0x00000035cc2d517a in semtimedop () from /lib64/libc.so.6

#9 0x0000000003be9b09 in sskgpwwait ()

#10 0x0000000003bccdf0 in skgpwwait ()

#11 0x0000000000798319 in kslwaitns_timed ()

#12 0x00000000008c3b1d in kskthbwt ()

#13 0x0000000000797e54 in kslwait ()

#14 0x00000000029f3f3b in ksarcv ()

#15 0x000000000082e8bf in ksbabs ()

#16 0x0000000000835822 in ksbrdp ()

#17 0x0000000002f4d840 in opirip ()

#18 0x000000000132b016 in opidrv ()

#19 0x0000000001eb3146 in sou2o ()

#20 0x0000000000723245 in opimai_real ()

#21 0x00000000007230fc in main ()

A debugging session is active.

Inferior 1 [process 3046] will be detached.

Quit anyway? (y or n) [answered Y; input not from terminal]

*** 2015-03-21 17:34:29.895

*** 2015-03-21 17:34:39.899

Waited for detached process: CKPT for 320 seconds:

*** 2015-03-21 17:34:39.899

Dumping diagnostic information for CKPT:

OS pid = 3046

loadavg : 0.06 0.01 0.00

memory info: free memory = 0.00M

swap info: free = 0.00M alloc = 0.00M total = 0.00M

F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD

0 S oracle 3046 1 0 75 0 - 184266 - 17:24 ? 00:00:00 ora_ckpt_ora10g

[Thread debugging using libthread_db enabled]

0x00000035cc2d517a in semtimedop () from /lib64/libc.so.6

#0 0x00000035cc2d517a in semtimedop () from /lib64/libc.so.6

#1 0x0000000003be9b09 in sskgpwwait ()

#2 0x0000000003bccdf0 in skgpwwait ()

#3 0x0000000000855f4a in ksdxsus ()

#4 0x0000000000857118 in ksdxffrz ()

#5 0x0000000000853003 in ksdxcb ()

#6 0x0000000001ebd0cf in sspuser ()

#7

#8 0x00000035cc2d517a in semtimedop () from /lib64/libc.so.6

#9 0x0000000003be9b09 in sskgpwwait ()

#10 0x0000000003bccdf0 in skgpwwait ()

#11 0x0000000000798319 in kslwaitns_timed ()

#12 0x00000000008c3b1d in kskthbwt ()

#13 0x0000000000797e54 in kslwait ()

#14 0x00000000029f3f3b in ksarcv ()

#15 0x000000000082e8bf in ksbabs ()

#16 0x0000000000835822 in ksbrdp ()

#17 0x0000000002f4d840 in opirip ()

#18 0x000000000132b016 in opidrv ()

#19 0x0000000001eb3146 in sou2o ()

#20 0x0000000000723245 in opimai_real ()

#21 0x00000000007230fc in main ()

A debugging session is active.

Inferior 1 [process 3046] will be detached.

Quit anyway? (y or n) [answered Y; input not from terminal]

*** 2015-03-21 17:34:40.598

从日志文件看出，SMON进程在等待与CKPT进程通信，难道CKPT进程异常吗?再将注意力转移至CKPT，查看CKPT的trace文件： *** 2015-03-21 17:26:15.972

*** SERVICE NAME:(SYS$BACKGROUND) 2015-03-21 17:26:15.972

*** SESSION ID:(165.1) 2015-03-21 17:26:15.972

Received ORADEBUG command 'suspend' from process Unix process pid: 3062, image: <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<

Received ORADEBUG command 'tracefile_name' from process Unix process pid: 3062, image:

自此,我们就明白了事情的缘由经过:

1. 由于CKPT进程被挂起，使得检查点无法完成、SMON进程长时间持有资源Enqueue CI-00000001-00000005，最后导致数据库HANG住;2. 随着资源Enqueue CI-00000001-00000005被SMON进程持有，导致一系列等待事件library cache lock，enq: CI - contention，log file switch (checkpoint incomplete)的出现

重新把CKPT进程恢复:

SQL> oradebug setospid 3046

Oracle pid: 7, Unix process pid: 3046, image: oracle@ora10g (CKPT)

SQL> oradebug resume;

Statement processed. SQL> select sid,event,p1,p2,p3,wait_time,seconds_in_wait,state from v$session_wait where wait_class <> 'Idle';

SID EVENT P1 P2 P3 WAIT_TIME SECONDS_IN_WAIT STATE

---------- ---------------------------------------------------------------- ---------- ---------- ---------- ---------- --------------- -------------------

到此，数据库恢复正常