Skip to content

Ora-00494 / Aiowait timeout cause instance crashed.(SYSTEM DUMP分析案例)

报错如下:

Wed Oct 21 03:06:22 2015
Thread 1 advanced to log sequence 254206 (LGWR switch)
  Current log# 9 seq# 254206 mem# 0: /boss_sysdata/oradata/dtvboss/redo09.log
Wed Oct 21 03:17:10 2015
WARNING: aiowait timed out 1 times
Wed Oct 21 03:22:11 2015
Errors in file /oracle/admin/dtvboss/bdump/dtvboss_arc0_404.trc:
ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by 'inst 1, osid 367'
Wed Oct 21 03:22:17 2015
System State dumped to trace file /oracle/admin/dtvboss/bdump/dtvboss_arc0_404.trc
Wed Oct 21 03:22:50 2015
Errors in file /oracle/admin/dtvboss/bdump/dtvboss_lgwr_365.trc:
ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by 'inst 1, osid 367'
Wed Oct 21 03:22:55 2015
Killing enqueue blocker (pid=367) on resource CF-00000000-00000000
 by killing session 1648.1
Wed Oct 21 03:22:55 2015
Errors in file /oracle/admin/dtvboss/bdump/dtvboss_lgwr_365.trc:
ORA-07445: exception encountered: core dump [ksuklms()+672] [SIGSEGV] [Address not mapped to object] [0x000000062] [] []
Wed Oct 21 03:23:18 2015
Errors in file /oracle/admin/dtvboss/bdump/dtvboss_pmon_343.trc:
ORA-00470: LGWR process terminated with error
Wed Oct 21 03:23:18 2015
PMON: terminating instance due to error 470
Wed Oct 21 03:23:18 2015
ORA-470 encountered when generating server alert SMG-3503
Wed Oct 21 03:23:18 2015
Errors in file /oracle/admin/dtvboss/bdump/dtvboss_j006_22335.trc:
ORA-00604: error occurred at recursive SQL level 1
ORA-00470: LGWR process terminated with error
Wed Oct 21 03:23:22 2015
Termination issued to instance processes. Waiting for the processes to exit
Wed Oct 21 03:23:28 2015
Instance termination failed to kill one or more processes
Wed Oct 21 03:23:58 2015
Instance terminated by PMON, pid = 343
Wed Oct 21 03:24:06 2015
Shutting down instance (abort)
Wed Oct 21 03:25:18 2015
WARNING: inbound connection timed out (ORA-3136)
Wed Oct 21 03:25:18 2015
WARNING: inbound connection timed out (ORA-3136)
Wed Oct 21 03:25:18 2015

1.宕机的起因分析:

告警日志分析:
Wed Oct 21 03:06:22 2015
Thread 1 advanced to log sequence 254206 (LGWR switch)
Current log# 9 seq# 254206 mem# 0: /boss_sysdata/oradata/dtvboss/redo09.log
Wed Oct 21 03:17:10 2015
WARNING: aiowait timed out 1 times –该时间段系统出现aio等待的告警,该告警由_iowait_timeouts隐含参数控制,超过该参数设置的值后会导致系统宕机,这里并未超过系统设置值。但是提示我们当时系统在io调度上出现了问题。
Wed Oct 21 03:22:11 2015
Errors in file /oracle/admin/dtvboss/bdump/dtvboss_arc0_404.trc:
ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by ‘inst 1, osid 367’ –22分17秒系统抛错,进程367持有controlfile的enqueue lock时间被其他进程(arc0)等待超时,该enqueue lock持有时间由隐含参数_controlfile_enqueue_timeout控制,默认为900秒
Wed Oct 21 03:22:17 2015
System State dumped to trace file /oracle/admin/dtvboss/bdump/dtvboss_arc0_404.trc
Wed Oct 21 03:22:50 2015
Errors in file /oracle/admin/dtvboss/bdump/dtvboss_lgwr_365.trc:
ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by ‘inst 1, osid 367’ –22分50秒,进程367持有的controlfile的enqueue lock时间被其他进程(lgwr)等待超时抛错
Wed Oct 21 03:22:55 2015
Killing enqueue blocker (pid=367) on resource CF-00000000-00000000 –LGWR进程发现异常查杀持有controlfile equeue lock的进程367
by killing session 1648.1
Wed Oct 21 03:22:55 2015
Errors in file /oracle/admin/dtvboss/bdump/dtvboss_lgwr_365.trc:
ORA-07445: exception encountered: core dump [ksuklms()+672] [SIGSEGV] [Address not mapped to object] [0x000000062] [] []
Wed Oct 21 03:23:18 2015
Errors in file /oracle/admin/dtvboss/bdump/dtvboss_pmon_343.trc: –后续一系列报错宕机开始
ORA-00470: LGWR process terminated with error
Wed Oct 21 03:23:18 2015
PMON: terminating instance due to error 470
Wed Oct 21 03:23:18 2015
ORA-470 encountered when generating server alert SMG-3503
Wed Oct 21 03:23:18 2015
Errors in file /oracle/admin/dtvboss/bdump/dtvboss_j006_22335.trc:
ORA-00604: error occurred at recursive SQL level 1
ORA-00470: LGWR process terminated with error
Wed Oct 21 03:23:22 2015
Termination issued to instance processes. Waiting for the processes to exit
Wed Oct 21 03:23:28 2015
Instance termination failed to kill one or more processes

Trace文件分析(trace过长摘取关键部分):
*** SERVICE NAME:(SYS$BACKGROUND) 2015-10-21 03:22:11.264
*** SESSION ID:(1646.3) 2015-10-21 03:22:11.264
*** 2015-10-21 03:22:11.264
Unable to get enqueue on resource CF-00000000-00000000 (ges mode req=3 held=6)
Possible local blocker ospid=367 sid=1648 sser=1 time_held=37 secs (ges mode req=6 held=4)
DUMP LOCAL BLOCKER: initiate state dump for KILL BLOCKER
possible owner[17.367] on resource CF-00000000-00000000
Dumping process info of pid[17.367] requested by pid[23.404]
ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by ‘inst 1, osid 367’

——————————————————————————-
ENQUEUE [CF] HELD FOR TOO LONG

enqueue holder: ‘inst 1, osid 367’

Process ‘inst 1, osid 367’ is holding an enqueue for maximum allowed time.
The process will be terminated.

Oracle Support Services triaging information: to find the root-cause, look
at the call stack of process ‘inst 1, osid 367’ located below. Ask the
developer that owns the first NON-service layer in the stack to investigate.
Common service layers are enqueues (ksq), latches (ksl), library cache
pins and locks (kgl), and row cache locks (kqr).

Dumping process 17.367 info:
*** 2015-10-21 03:22:11.300
Dumping diagnostic information for ospid 367:
OS pid = 367
loadavg : 0.44 0.62 1.82
swap info: free_mem = 1435.35M rsv = 59461.24M
alloc = 55941.14M avail = 55124.91 swap_free = 58645.01M
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
0 S oracle 367 1 0 39 20 ? 4116160 ? Mar 30 ? 498:14 ora_ckpt_dtvboss — 整个系统当时的空闲内存和swap还留有余地,足够当时系统的使用,所以内存不足的原因可以排除。这里提示进程367为oracle ckpt进程,可以确认当时持有controlfile enqueue lock的进程为oracle ckpt进程

PROCESS 23: –该进程为arc0 归档进程,trace信息显示在等待controlfile enqueue 队列锁。等待事件为enq: CF – contention
—————————————-
SO: 8a9004f88, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=23, calls cur/top: 8a95c6650/8a95c6650, flag: (2) SYSTEM
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 24
last post received-location: ksasnd
last process to post me: b66002018 1 6
last post sent: 0 0 24
last post sent-location: ksasnd
last process posted by me: b66005770 1 2
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 5eb3388f0
O/S info: user: oracle, term: UNKNOWN, ospid: 404
OSD pid info: Unix process pid: 404, image: oracle@hzboss-ora1 (ARC0)
Dump of memory from 0x00000005F033B1F0 to 0x00000005F033B3F8
5F033B1F0 0000000C 00000000 00000008 AF739C70 [………….s.p]
5F033B200 00000006 000313A7 00000008 A95D1620 [………….]. ]
5F033B210 00000005 000313A7 00000008 AF739C70 [………….s.p]
5F033B220 00000006 000313A7 00000008 AF739C70 [………….s.p]
5F033B230 00000006 000313A7 00000008 A95D1FB8 [………….]..]
5F033B240 00000005 000313A7 00000008 AF739C70 [………….s.p]
5F033B250 00000006 000313A7 00000008 AF739C70 [………….s.p]
5F033B260 00000006 000313A7 00000008 A95D1FB8 [………….]..]
5F033B270 00000005 000313A7 00000008 AF739C70 [………….s.p]
5F033B280 00000006 000313A7 00000008 AF739C70 [………….s.p]
5F033B290 00000006 000313A7 00000008 A95D1FB8 [………….]..]
5F033B2A0 00000005 000313A7 00000008 AF739C70 [………….s.p]
5F033B2B0 00000006 000313A7 00000008 A95D17E8 [………….]..]
5F033B2C0 00000005 000313A7 00000008 AF739C70 [………….s.p]
5F033B2D0 00000006 000313A7 00000008 AF739C70 [………….s.p]
5F033B2E0 00000006 000313A7 00000008 A95D1880 [………….]..]
5F033B2F0 00000005 000313A7 00000008 AF739C70 [………….s.p]
5F033B300 00000006 000313A7 00000008 AF739C70 [………….s.p]
5F033B310 00000006 000313A7 00000008 A95D16B8 [………….]..]
5F033B320 00000005 000313A7 00000008 AF739C70 [………….s.p]
5F033B330 00000006 000313A7 00000008 AF739C70 [………….s.p]
5F033B340 00000006 000313A7 00000008 A95D1880 [………….]..]
5F033B350 00000005 000313A7 00000008 AF739C70 [………….s.p]
5F033B360 00000006 000313A7 00000008 AF739C70 [………….s.p]
5F033B370 00000006 000313A7 00000008 A95D16B8 [………….]..]
5F033B380 00000005 000313A7 00000008 AF739C70 [………….s.p]
5F033B390 00000006 000313A7 00000008 AF739C70 [………….s.p]
5F033B3A0 00000006 000313A7 00000008 A95D17E8 [………….]..]
5F033B3B0 00000005 000313A7 00000008 AF739C70 [………….s.p]
5F033B3C0 00000006 000313A7 00000008 AF739C70 [………….s.p]
5F033B3D0 00000006 000313A7 00000008 A95D17E8 [………….]..]
5F033B3E0 00000005 000313A7 00000008 AF739C70 [………….s.p]
5F033B3F0 00000006 000313A7 [……..]
(FOB) flags=2 fib=8af713780 incno=0 pending i/o cnt=0
fname=/boss_sysdata/oradata/dtvboss/control03.ctl
fno=2 lblksz=16384 fsiz=1308
(FOB) flags=2 fib=8af7133e0 incno=0 pending i/o cnt=0
fname=/boss_sysdata/oradata/dtvboss/control02.ctl
fno=1 lblksz=16384 fsiz=1308
(FOB) flags=2 fib=8af713040 incno=0 pending i/o cnt=0
fname=/boss_sysdata/oradata/dtvboss/control01.ctl
fno=0 lblksz=16384 fsiz=1308
—————————————-
SO: 8a9778500, type: 11, owner: 8a9004f88, flag: INIT/-/-/0x00
(broadcast handle) flag: (2) ACTIVE SUBSCRIBER, owner: 8a9004f88,
event: 21, last message event: 21,
last message waited event: 21, messages read: 0
channel: (5eb52cc20) scumnt mount lock
scope: 1, event: 22, last mesage event: 20,
publishers/subscribers: 0/20,
messages published: 1
—————————————-
SO: 8a95b7328, type: 4, owner: 8a9004f88, flag: INIT/-/-/0x00
(session) sid: 1646 trans: 0, creator: 8a9004f88, flag: (51) USR/- BSY/-/-/-/-/-
DID: 0001-0017-0000000D, short-term DID: 0000-0000-00000000
txn branch: 0
oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS
service name: SYS$BACKGROUND
last wait for ‘enq: CF – contention’ blocking sess=0x0 seq=43322 wait_time=2929723 seconds since wait started=36
name|mode=43460004, 0=0, operation=0
Dumping Session Wait History
for ‘enq: CF – contention’ count=1 wait_time=2929723
name|mode=43460004, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929725
name|mode=43460004, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929726
name|mode=43460004, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929726
name|mode=43460004, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929725
name|mode=43460004, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929723
name|mode=43460004, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929725
name|mode=43460004, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929726
name|mode=43460004, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929724
name|mode=43460004, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929750
name|mode=43460004, 0=0, operation=0

SO: 8a95d1fb8, type: 5, owner: 8a95c6650, flag: INIT/-/-/0x00
(enqueue) CF-00000000-00000000 DID: 0001-0017-0000000D
lv: 00 79 4a fb 00 00 00 00 00 00 00 00 00 00 00 00 res_flag: 0x2
res: 0x5eb40f608, lock_flag: 0x0
own: 0x8a95b7328, sess: 0x8a95b7328, prv: 0x8a95d1fe8 –这里说明arc0在申请0x5eb40f608的队列锁资源。而在process 17号的ckpt中可以看到0x5eb40f608资源被ckpt持有

process 17(ckpt进程)中的句柄:

SO: 8a95b9df8, type: 4, owner: 8a90037d0, flag: INIT/-/-/0x00
(session) sid: 1648 trans: 0, creator: 8a90037d0, flag: (51) USR/- BSY/-/-/-/-/-
DID: 0001-0011-00000005, short-term DID: 0000-0000-00000000
txn branch: 0
oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS
service name: SYS$BACKGROUND
waiting for ‘direct path write’ blocking sess=0x0 seq=39369 wait_time=0 seconds since wait started=37
file number=72, first dba=1, block cnt=1
Dumping Session Wait History
for ‘direct path write’ count=1 wait_time=0
file number=73, first dba=1, block cnt=1
for ‘direct path write’ count=1 wait_time=0
file number=74, first dba=1, block cnt=1
for ‘direct path write’ count=1 wait_time=0
file number=75, first dba=1, block cnt=1
for ‘direct path write’ count=1 wait_time=0
file number=76, first dba=1, block cnt=1
for ‘direct path write’ count=1 wait_time=309
file number=77, first dba=1, block cnt=1
for ‘direct path read’ count=1 wait_time=1
file number=8b, first dba=1, block cnt=1
for ‘direct path read’ count=1 wait_time=0
file number=8a, first dba=1, block cnt=1
for ‘direct path read’ count=1 wait_time=0
file number=89, first dba=1, block cnt=1
for ‘direct path read’ count=1 wait_time=1
file number=88, first dba=1, block cnt=1
for ‘direct path read’ count=1 wait_time=1
file number=87, first dba=1, block cnt=1
temporary object counter: 0
—————————————-
SO: 8a95d1cc0, type: 5, owner: 8a95c5df8, flag: INIT/-/-/0x00
(enqueue) CF-00000000-00000000 DID: 0001-0011-00000005
lv: 00 79 4a fb 00 00 00 00 00 00 00 00 00 00 00 00 res_flag: 0x2
res: 0x5eb40f608, mode: SSX, lock_flag: 0x0 —————-ckpt以ssx的方式持有了该资源
own: 0x8a95b9df8, sess: 0x8a95b9df8, proc: 0x8a90037d0, prv: 0x5eb40f618

PROCESS 10: LGWR进程
—————————————-
SO: b66002018, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=10, calls cur/top: b665c6de0/b665c6de0, flag: (6) SYSTEM
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 24
last post received-location: ksasnd
last process to post me: 8a9000860 1 6
last post sent: 109 0 4
last post sent-location: kslpsr
last process posted by me: 8a902ef90 105 0
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 5eb3388f0
O/S info: user: oracle, term: UNKNOWN, ospid: 365
OSD pid info: Unix process pid: 365, image: oracle@hzboss-ora1 (LGWR)

SO: b665bf398, type: 4, owner: b66002018, flag: INIT/-/-/0x00
(session) sid: 824 trans: 0, creator: b66002018, flag: (51) USR/- BSY/-/-/-/-/-
DID: 0001-000A-00000006, short-term DID: 0000-0000-00000000
txn branch: 0
oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS
service name: SYS$BACKGROUND
waiting for ‘enq: CF – contention’ blocking sess=0x8a95b9df8 seq=61266 wait_time=0 seconds since wait started=0 0x8a95b9df8该句柄持有者为process 17的ckpt进程
name|mode=43460005, 0=0, operation=0
Dumping Session Wait History
for ‘enq: CF – contention’ count=1 wait_time=2929719
name|mode=43460005, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929716
name|mode=43460005, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929716
name|mode=43460005, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929718
name|mode=43460005, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929719
name|mode=43460005, 0=0, operation=0
for ‘enq: CF – contention’ count=1 wait_time=2929719

—————————————-
SO: b665c6de0, type: 3, owner: b66002018, flag: INIT/-/-/0x00
(call) sess: cur b665bf398, rec 0, usr b665bf398; depth: 0
—————————————-
SO: b665cce90, type: 5, owner: b665c6de0, flag: INIT/-/-/0x00
(enqueue) CF-00000000-00000000 DID: 0001-000A-00000006
lv: 00 79 4a fb 00 00 00 00 00 00 00 00 00 00 00 00 res_flag: 0x2
res: 0x5eb40f608, req: SSX, lock_flag: 0x0 ————前面已经说明了,该5eb40f608的资源队列锁已经被ckpt进程持有,而lgwr正在申请以ssx的方式持有。
own: 0xb665bf398, sess: 0xb665bf398, proc: 0xb66002018, prv: 0x5eb40f628

综上可以得出结论,由于arc0进程要写日志需要等待控制文件CF锁,lgwr估计要写日志或者切换也在等待控制文件CF锁,而ckpt进程持有controlfile enqueue lock时间过长,arch0等待超过900秒,导致oracle数据库系统判断异常。
此时oracle数据库系统会通知lgwr进程kill持有controlfile enqueue lock的进程,相当于lgwr进程杀了ckpt进程,而ckpt进程又为oracle关键进程,连锁反应,引起宕机。

Oracle Rac hang 案例分析一则(WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK)

LOG FILE
————–
Filename=zsinsraca1_151006_0000.nmon.xlsx
See the following:

+++ CPU_ALL ========> CPU usage is NOT high

CPU Total zsinsraca1 User% Sys% Wait% Idle% CPU% Logical CPUs (SMTmode=4)
10/6/15 10:30 AM 5.2 1.7 0.2 92.9 6.9 48
10/6/15 10:31 AM 4.3 1.6 0.1 94 5.9 48
10/6/15 10:32 AM 7.6 1.5 0.2 90.6 9.1 48
10/6/15 10:33 AM 8.6 1.7 0 89.7 10.3 48
10/6/15 10:34 AM 8.8 1.8 0 89.3 10.6 48
10/6/15 10:35 AM 10.7 2 0.1 87.2 12.7 48
10/6/15 10:36 AM 9.3 2.1 0.1 88.6 11.4 48
10/6/15 10:37 AM 9.4 2.1 0.1 88.4 11.5 48
10/6/15 10:38 AM 10.7 2.5 0.2 86.6 13.2 48
10/6/15 10:39 AM 10.2 2.4 0.1 87.3 12.6 48
10/6/15 10:40 AM 9.6 1.8 0 88.5 11.4 48
10/6/15 10:41 AM 9.6 2.1 0 88.2 11.7 48
10/6/15 10:42 AM 9 2.2 0.1 88.7 11.2 48
10/6/15 10:43 AM 9.2 1.7 0 89 10.9 48
10/6/15 10:44 AM 11 1.8 0 87.2 12.8 48
10/6/15 10:45 AM 10.7 1.9 0.1 87.3 12.6 48
10/6/15 10:46 AM 12.9 2.1 0.1 84.9 15 48
10/6/15 10:47 AM 9.4 1.5 0 89 10.9 48
10/6/15 10:48 AM 11.3 1.6 0.1 87.1 12.9 48
10/6/15 10:49 AM 11.8 2.4 0.1 85.7 14.2 48
10/6/15 10:50 AM 12.2 1.8 0 85.9 14 48
10/6/15 10:51 AM 13.2 1.9 0.1 84.8 15.1 48
10/6/15 10:52 AM 12.4 1.3 0.1 86.3 13.7 48
10/6/15 10:53 AM 12.7 1.8 0 85.5 14.5 48
10/6/15 10:54 AM 11.9 1.9 0.1 86.2 13.8 48
10/6/15 10:55 AM 10.2 2 0.1 87.6 12.2 48
10/6/15 10:56 AM 11.5 2.4 0.2 85.9 13.9 48
10/6/15 10:57 AM 11.4 1.8 0.1 86.6 13.2 48
10/6/15 10:58 AM 11.9 1.7 0 86.3 13.6 48
10/6/15 10:59 AM 10.3 1.6 0 88.1 11.9 48
10/6/15 11:00 AM 12.3 1.5 0.2 86 13.8 48
10/6/15 11:01 AM 12.1 1.7 0.1 86.2 13.8 48
10/6/15 11:02 AM 10.6 1.6 0.1 87.8 12.2 48
10/6/15 11:03 AM 13.8 2.4 0.1 83.7 16.2 48
10/6/15 11:04 AM 12.5 2.6 0.1 84.9 15.1 48
10/6/15 11:05 AM 11.4 1.8 0.1 86.7 13.2 48
10/6/15 11:06 AM 10.1 2.3 0.1 87.5 12.4 48
10/6/15 11:07 AM 9.7 2.1 0.1 88.2 11.8 48
10/6/15 11:08 AM 10.5 2 0 87.5 12.5 48
10/6/15 11:09 AM 11.3 1.1 0.1 87.5 12.4 48
10/6/15 11:10 AM 11.6 1.8 0.1 86.6 13.4 48
10/6/15 11:11 AM 9.5 1.4 0.1 89 10.9 48
10/6/15 11:12 AM 8.4 1.4 0 90.2 9.8 48
10/6/15 11:13 AM 9 1.6 0 89.3 10.6 48
10/6/15 11:14 AM 10.1 1.9 0 87.9 12 48
10/6/15 11:15 AM 11.7 2.2 0.1 86.1 13.9 48
10/6/15 11:16 AM 10.5 1.9 0.1 87.6 12.4 48
10/6/15 11:17 AM 11 1.2 0.1 87.8 12.2 48
10/6/15 11:18 AM 12.6 2.2 0.1 85.2 14.8 48
10/6/15 11:19 AM 9.9 1.6 0.1 88.4 11.5 48
10/6/15 11:20 AM 11.3 2.1 0.1 86.5 13.4 48
10/6/15 11:21 AM 11.4 1.3 0.1 87.3 12.7 48
10/6/15 11:22 AM 11.6 1.5 0.1 86.8 13.1 48
10/6/15 11:23 AM 12.7 3.2 0.1 84 15.9 48
10/6/15 11:24 AM 11.8 3.1 0.1 85.1 14.9 48
10/6/15 11:25 AM 9.1 1.5 0 89.3 10.6 48
10/6/15 11:26 AM 11.1 1.9 0.1 86.9 13 48
10/6/15 11:27 AM 13.3 3.9 0.4 82.4 17.2 48
10/6/15 11:28 AM 10.3 2 0.8 86.9 12.3 48
10/6/15 11:29 AM 10.2 1.2 0 88.6 11.4 48
10/6/15 11:30 AM 11.3 1.7 0 87 13 48
10/6/15 11:31 AM 13.9 2.8 0.1 83.2 16.7 48
10/6/15 11:32 AM 13.2 3.1 0.1 83.6 16.3 48
10/6/15 11:33 AM 10.9 2.2 0.1 86.8 13.1 48
10/6/15 11:34 AM 10.6 2.6 0.1 86.8 13.2 48
10/6/15 11:35 AM 12 2.6 0 85.4 14.6 48
10/6/15 11:36 AM 14.5 5.3 0.1 80.1 19.8 48
10/6/15 11:37 AM 11.4 1.6 0.1 86.9 13 48
10/6/15 11:38 AM 10.8 1.7 0 87.5 12.5 48
10/6/15 11:39 AM 9.7 1.6 0 88.6 11.3 48
10/6/15 11:40 AM 13.2 1.9 0 84.9 15.1 48
10/6/15 11:41 AM 10.6 1.3 0 88.2 11.9 48
10/6/15 11:42 AM 12.1 4 0.2 83.7 16.1 48
10/6/15 11:43 AM 11.9 4.4 0 83.6 16.3 48
10/6/15 11:44 AM 10.1 1.6 0 88.3 11.7 48
10/6/15 11:45 AM 12.4 2.4 0.4 84.8 14.8 48
10/6/15 11:46 AM 15.3 6.5 1.3 77 21.8 48
10/6/15 11:47 AM 13.4 4.4 1 81.2 17.8 48
10/6/15 11:48 AM 16.5 6.8 0.1 76.6 23.3 48
10/6/15 11:49 AM 15.9 5.1 0.1 78.9 21 48
10/6/15 11:50 AM 8.5 4.8 0.2 86.5 13.3 48

+++ MEM =========> free memory 在11:50时仍有3GB free

Memory zsinsraca1 Real Free % Virtual free % Real free(MB) Virtual free(MB) Real total(MB) Virtual total(MB)
10/6/15 10:30 AM 7.6 88 7476.4 28845 98304 32768
10/6/15 10:31 AM 7.6 88 7472.8 28845 98304 32768
10/6/15 10:32 AM 7.6 88 7454.3 28845 98304 32768
10/6/15 10:33 AM 7.5 88 7412.8 28845 98304 32768
10/6/15 10:34 AM 7.5 88 7374.2 28845.5 98304 32768
10/6/15 10:35 AM 7.4 88 7303.3 28845.5 98304 32768
10/6/15 10:36 AM 7.3 88 7147.1 28845.5 98304 32768
10/6/15 10:37 AM 7.3 88 7210.1 28845.5 98304 32768
10/6/15 10:38 AM 7.3 88 7170 28845.5 98304 32768
10/6/15 10:39 AM 7.3 88 7128 28845.5 98304 32768
10/6/15 10:40 AM 7.2 88 7126.4 28845.5 98304 32768
10/6/15 10:41 AM 7.2 88 7104.1 28845.5 98304 32768
10/6/15 10:42 AM 7.2 88 7052 28845.5 98304 32768
10/6/15 10:43 AM 7 88 6888.5 28845.6 98304 32768
10/6/15 10:44 AM 7.1 88 7028.3 28845.6 98304 32768
10/6/15 10:45 AM 7 88 6914.8 28845 98304 32768
10/6/15 10:46 AM 7 88 6917.3 28844.5 98304 32768
10/6/15 10:47 AM 7 88 6886.8 28844.1 98304 32768
10/6/15 10:48 AM 6.9 88 6822.9 28843.3 98304 32768
10/6/15 10:49 AM 6.8 88 6668 28842 98304 32768
10/6/15 10:50 AM 6.7 88 6602.4 28841.1 98304 32768
10/6/15 10:51 AM 6.6 88 6463.4 28840 98304 32768
10/6/15 10:52 AM 6.3 88 6235.7 28838.4 98304 32768
10/6/15 10:53 AM 6.5 88 6397.8 28837.6 98304 32768
10/6/15 10:54 AM 6.5 88 6384.6 28837.4 98304 32768
10/6/15 10:55 AM 6.5 88 6340.9 28836.2 98304 32768
10/6/15 10:56 AM 6.2 88 6123.9 28836.2 98304 32768
10/6/15 10:57 AM 6.3 88 6228.7 28835.8 98304 32768
10/6/15 10:58 AM 6.2 88 6143.9 28834.9 98304 32768
10/6/15 10:59 AM 6.2 88 6111.3 28834.2 98304 32768
10/6/15 11:00 AM 6.1 88 6017.9 28833.1 98304 32768
10/6/15 11:01 AM 5.9 88 5837.6 28832.9 98304 32768
10/6/15 11:02 AM 6 88 5888.8 28832 98304 32768
10/6/15 11:03 AM 5.9 88 5848.5 28831.3 98304 32768
10/6/15 11:04 AM 5.7 88 5606.2 28827.8 98304 32768
10/6/15 11:05 AM 5.7 88 5555.2 28827.1 98304 32768
10/6/15 11:06 AM 5.6 88 5503.2 28826.3 98304 32768
10/6/15 11:07 AM 5.4 88 5271.7 28825.5 98304 32768
10/6/15 11:08 AM 5.5 88 5388.1 28824.7 98304 32768
10/6/15 11:09 AM 5.3 88 5239.6 28824.7 98304 32768
10/6/15 11:10 AM 5.5 88 5391.1 28824.1 98304 32768
10/6/15 11:11 AM 5.4 88 5312.4 28823.9 98304 32768
10/6/15 11:12 AM 5.4 88 5276.5 28823.4 98304 32768
10/6/15 11:13 AM 5.4 88 5325.3 28823.3 98304 32768
10/6/15 11:14 AM 5.3 88 5231.7 28822.8 98304 32768
10/6/15 11:15 AM 5.2 88 5157.4 28821.8 98304 32768
10/6/15 11:16 AM 5.1 88 5054 28820.6 98304 32768
10/6/15 11:17 AM 5.1 88 5017.2 28820.5 98304 32768
10/6/15 11:18 AM 5 88 4928.5 28819.5 98304 32768
10/6/15 11:19 AM 5.1 88 5049.6 28821.2 98304 32768
10/6/15 11:20 AM 5.1 88 5015.3 28820.4 98304 32768
10/6/15 11:21 AM 5 88 4935.5 28819.6 98304 32768
10/6/15 11:22 AM 4.9 87.9 4815.3 28818.4 98304 32768
10/6/15 11:23 AM 4.7 87.9 4594.5 28816 98304 32768
10/6/15 11:24 AM 4.6 87.9 4528.6 28815.4 98304 32768
10/6/15 11:25 AM 4.6 87.9 4550.3 28814.9 98304 32768
10/6/15 11:26 AM 4.6 87.9 4486.5 28814.3 98304 32768
10/6/15 11:27 AM 4.4 87.9 4361.3 28813.4 98304 32768
10/6/15 11:28 AM 4.4 87.9 4287 28812.4 98304 32768
10/6/15 11:29 AM 4.3 87.9 4251.7 28811.8 98304 32768
10/6/15 11:30 AM 4.3 87.9 4187.3 28811 98304 32768
10/6/15 11:31 AM 4.2 87.9 4097.9 28810.4 98304 32768
10/6/15 11:32 AM 4.2 87.9 4101.4 28809.9 98304 32768
10/6/15 11:33 AM 4.1 87.9 4062.2 28809.6 98304 32768
10/6/15 11:34 AM 4 87.9 3960.2 28808.4 98304 32768
10/6/15 11:35 AM 3.9 87.9 3858.5 28806.8 98304 32768
10/6/15 11:36 AM 3.9 87.9 3790.8 28805.9 98304 32768
10/6/15 11:37 AM 3.8 87.9 3774.6 28805.7 98304 32768
10/6/15 11:38 AM 3.6 87.9 3586.9 28805.1 98304 32768
10/6/15 11:39 AM 3.9 87.9 3838.9 28804.7 98304 32768
10/6/15 11:40 AM 3.8 87.9 3763 28804.7 98304 32768
10/6/15 11:41 AM 3.7 87.9 3661.5 28804 98304 32768
10/6/15 11:42 AM 3.8 88.1 3763 28864.2 98304 32768
10/6/15 11:43 AM 3.8 88.1 3753.1 28864.3 98304 32768
10/6/15 11:44 AM 3.7 88.1 3676.4 28864.3 98304 32768
10/6/15 11:45 AM 3.5 88.1 3405.6 28864.3 98304 32768
10/6/15 11:46 AM 3.5 88.1 3484.2 28864.4 98304 32768
10/6/15 11:47 AM 3.5 88.1 3477 28864.5 98304 32768
10/6/15 11:48 AM 3.6 88.1 3570.6 28864.5 98304 32768
10/6/15 11:49 AM 4.7 88.1 4646.2 28868.9 98304 32768
10/6/15 11:50 AM 34.5 98 33959.3 32123.8 98304 32768

LOG FILE
————–
Filename=alert_zsiims1.log
See the following:

Tue Oct 6 02:34:52 2015
Thread 1 advanced to log sequence 37413 (LGWR switch)
Current log# 1 seq# 37413 mem# 0: +V5DATA/zsiims/onlinelog/group_1.9844.799569609
Tue Oct 6 10:50:38 2015
ALTER SYSTEM ARCHIVE LOG
Tue Oct 6 10:50:39 2015
Thread 1 advanced to log sequence 37414 (LGWR switch)
Current log# 3 seq# 37414 mem# 0: +V5DATA/zsiims/onlinelog/group_3.9851.799569423
Tue Oct 6 11:21:49 2015
Errors in file /oracle/admin/zsiims/bdump/zsiims1_j001_10027156.trc:
ORA-12012: error on auto execute of job 54375
ORA-27468: “EXFSYS.RLM$SCHDNEGACTION” is locked by another process
Tue Oct 6 11:23:07 2015
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=142
System State dumped to trace file /oracle/admin/zsiims/udump/zsiims1_ora_20971728.trc
Tue Oct 6 11:25:43 2015
Errors in file /oracle/admin/zsiims/bdump/zsiims1_j002_6815818.trc:
ORA-12012: error on auto execute of job 54374
ORA-27468: “EXFSYS.RLM$EVTCLEANUP” is locked by another process
Tue Oct 6 11:26:57 2015
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=28
System State dumped to trace file /oracle/admin/zsiims/bdump/zsiims1_smon_15335466.trc
Tue Oct 6 11:35:26 2015
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=193
System State dumped to trace file /oracle/admin/zsiims/udump/zsiims1_ora_32309462.trc
Tue Oct 6 11:41:27 2015
Shutting down instance: further logons disabled

LOG FILE
————–
Filename=alert_zsiims2.log
See the following:
Tue Oct 6 10:50:40 2015
Thread 2 advanced to log sequence 25153 (LGWR switch)
Current log# 5 seq# 25153 mem# 0: +V5DATA/zsiims/onlinelog/group_5.9853.799569371
Tue Oct 6 11:45:06 2015
IPC Send timeout detected.Sender: ospid 7798804
Receiver: inst 1 binc 4 ospid 6881304
Tue Oct 6 11:45:08 2015
Trace dumping is performing id=[cdmp_20151006114508]
Tue Oct 6 11:48:58 2015
Shutting down instance (abort)
License high water mark = 450
Instance terminated by USER, pid = 20578736
Tue Oct 6 11:49:50 2015
Starting ORACLE instance (normal)
sskgpgetexecname failed to get name
LICENSE_MAX_SESSION = 0

Filename=zsiims1_ora_20971728A.trc ===> 发生问题后产生的第一个systemstate dump, 在Oct 6 11:23:07AM产生的,此时数据库的状况应该已经很糟糕了
See the following:

50几个session在等待latch: row cache objects

33: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=45472
37: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=18549
68: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=13886
71: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=46595
81: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=48525
106: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11855
118: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11183
122: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8913
132: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=12194
140: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=12643
149: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=12173
154: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=15022
156: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=12143
160: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=20615
173: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11470
174: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11668
177: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11249
183: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=10725
184: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11485
200: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=9970
204: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11019
207: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8356
208: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8811
215: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8914
219: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=10169
230: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=9156
241: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=7911
244: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8785
249: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=17542
255: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=9209
264: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=9247
276: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8368
288: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8211
310: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=7413
317: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=17869
331: waiting for ‘latch: row cache objects'[Rcache object=700000418a9adf8,] seq=5309
352: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=2625
353: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=10183
361: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=5948
364: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=5303
366: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=5300
378: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=760
381: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=4788
394: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=4758
401: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=109
424: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=2924
429: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=3120
432: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=2426
454: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=1861
457: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=1579
463: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=1603
468: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=1016
470: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=1076
486: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=501
576: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=16368
606: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=30065

还有很多session在等待row cache lock

28: waiting for ‘row cache lock’ [Rcache object=70000064a573ef8,] seq=40578
40: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=59768
93: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=2938
98: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=2777
193: waiting for ‘row cache lock’ [Rcache object=700000621252470,] seq=966
199: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=107
214: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=3501
220: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=86
232: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1148
239: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=12734
252: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=2908
259: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1134
260: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=65
266: waiting for ‘row cache lock’ [Rcache object=700000550af2690,] seq=1791
268: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1288
274: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=821
278: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1357
287: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=637
289: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=22
293: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=3363
302: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=27
319: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=98
320: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=366
323: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=2618
327: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=167
328: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1137
330: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=31
332: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=53
333: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=28
334: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=368
337: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=202
341: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=56
342: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=18
343: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=28
345: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=359
349: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=562
350: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=24
351: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=407
358: waiting for ‘row cache lock’ [Rcache object=70000078b3d6290,] seq=28
359: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=32
363: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=32
365: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=27
371: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=29
373: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=28
375: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=89
379: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=605
383: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=523
385: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=595
387: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=243
390: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=28
391: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=355
393: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=20
395: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=28
397: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1080
404: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=29
409: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=22
410: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=60
411: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1101
413: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=95
414: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=948
416: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=315
417: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=516
419: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=102
420: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=607
421: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=831
426: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=42
433: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=58
437: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=421
442: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=44
445: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=185
447: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=35
450: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=55
456: waiting for ‘row cache lock’ [Rcache object=700000789bc8cc8,] seq=349
459: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=127
465: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=234
474: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=52
475: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=25
478: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=41
490: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=49
610: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=15070

分析发生问题时候的systemstate dump trace zsiims1_ora_20971728A.trc:

50几个session在等待latch: row cache objects, 大部分是和700000768fd8ea8有关的

33: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=45472
37: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=18549
68: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=13886
71: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=46595
81: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=48525
106: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11855
118: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11183
122: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8913
132: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=12194
140: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=12643
149: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=12173
154: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=15022
156: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=12143
160: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=20615
173: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11470
174: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11668
177: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11249
183: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=10725
184: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11485
200: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=9970
204: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=11019
207: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8356
208: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8811
215: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8914
219: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=10169
230: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=9156
241: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=7911
244: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8785
249: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=17542
255: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=9209
264: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=9247
276: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8368
288: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=8211
310: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=7413
317: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=17869
331: waiting for ‘latch: row cache objects'[Rcache object=700000418a9adf8,] seq=5309
352: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=2625
353: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=10183
361: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=5948
364: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=5303
366: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=5300
378: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=760
381: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=4788
394: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=4758
401: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=109
424: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=2924
429: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=3120
432: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=2426
454: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=1861
457: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=1579
463: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=1603
468: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=1016
470: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=1076
486: waiting for ‘latch: row cache objects'[Latch 70000075f1cd020] seq=501
576: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=16368
606: waiting for ‘latch: row cache objects'[Latch 700000768fd8ea8] seq=30065

以其中一个比较典型的process为例:

PROCESS 576:
—————————————-
SO: 70000078326f638, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=576, calls cur/top: 70000039983fd08/70000039983f788, flag: (0) –
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 109 0 4
last post received-location: kslpsr
last process to post me: 700000786279d80 1 6
last post sent: 0 0 24
last post sent-location: ksasnd
last process posted by me: 700000786279d80 1 6
(latch info) wait_event=0 bits=0
Location from where call was made: kghfrunp: clatch: wait:
waiting for 700000768fd8ea8 Child row cache objects level=4 child#=9
Location from where latch is held: kghfrunp: clatch: wait: ===============> 可以看到这个latch是因为kghfrunp相关的功能发起的,而这个功能是需要从shared pool中释放空间有关
Context saved from call: 0 ===========================>kghfrunp: (KGH: Ask client to free unpinned space)
state=busy, wlstate=free
waiters [orapid (seconds since: put on list, posted, alive check)]:
207 (5, 1444101815, 2)
174 (5, 1444101815, 2)
322 (5, 1444101815, 2)

还有很多session在等待row cache lock, 最多的对象70000078e9f0d28

28: waiting for ‘row cache lock’ [Rcache object=70000064a573ef8,] seq=40578
40: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=59768
93: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=2938
98: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=2777
193: waiting for ‘row cache lock’ [Rcache object=700000621252470,] seq=966
199: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=107
214: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=3501
220: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=86
232: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1148
239: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=12734
252: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=2908
259: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1134
260: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=65
266: waiting for ‘row cache lock’ [Rcache object=700000550af2690,] seq=1791
268: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1288
274: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=821
278: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1357
287: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=637
289: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=22
293: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=3363
302: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=27
319: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=98
320: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=366
323: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=2618
327: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=167
328: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1137
330: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=31
332: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=53
333: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=28
334: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=368
337: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=202
341: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=56
342: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=18
343: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=28
345: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=359
349: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=562
350: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=24
351: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=407
358: waiting for ‘row cache lock’ [Rcache object=70000078b3d6290,] seq=28
359: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=32
363: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=32
365: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=27
371: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=29
373: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=28
375: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=89
379: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=605
383: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=523
385: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=595
387: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=243
390: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=28
391: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=355
393: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=20
395: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=28
397: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1080
404: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=29
409: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=22
410: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=60
411: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=1101
413: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=95
414: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=948
416: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=315
417: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=516
419: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=102
420: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=607
421: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=831
426: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=42
433: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=58
437: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=421
442: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=44
445: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=185
447: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=35
450: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=55
456: waiting for ‘row cache lock’ [Rcache object=700000789bc8cc8,] seq=349
459: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=127
465: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=234
474: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=52
475: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=25
478: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=41
490: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=49
610: waiting for ‘row cache lock’ [Rcache object=70000078e9f0d28,] seq=15070

以其中的process 610为例:

PROCESS 610:
—————————————-
SO: 700000784271270, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=610, calls cur/top: 700000387cb3b58/700000387cb35d8, flag: (0) –
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 109 0 4
last post received-location: kslpsr
last process to post me: 700000786279d80 1 6
last post sent: 0 0 24
last post sent-location: ksasnd
last process posted by me: 700000786279d80 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 7000007852bdfc8
O/S info: user: oracle, term: UNKNOWN, ospid: 39321988
OSD pid info: Unix process pid: 39321988, image: oracle@zsinsraca1
Short stack dump:
ksdxfstk+002c< -ksdxcb+04e4<-sspuser+0074<-000047DC<-sskgpwwait+0034<-skgpwwait+00bc<-ksliwat+06c0<-kslwaitns_timed+0024<-kskthbwt+022c<-kslwait+00f4<-kqrigt+05e0<-kqrpre1+0960<-kqrpre+001c<-ktusmous_online_undoseg+05f4<-ktusmaus_add_us+0300<-ktubnd+04ac<-ktuchg+055c<-ktbchg2+01f0<-kdtchg+0524<-kdtwrp+2540<-kdtInsRow+0a20<-insrow+043c<-insdrv+0428<-inscovexe+02b8<-insExecStmtExecIniEngine+005c<-insexe+02f8<-opiexe+2738<-opipls+185c<-opiodr+0ae0<-rpidrus+01bc<-skgmstack+00c8<-rpidru+0088<-rpiswu2+034c<-rpidrv+095c<-psddr0+02bc<-psdnal+01d0<-pevm_EXECC+01f8<-pfrinstr_EXECC+0070<-pfrrun_no_tool+005c<-pfrrun+1014<-plsql_run+06b4<-pricar+042c<-pricbr+0258<-prient2+03a8<-prient+0b0c<-kkxrpc+0250<-kporpc+01d4<-opiodr+0ae0<-ttcpip+1020<-opitsk+1124<-opiino+0990<-opiodr+0ae0<-opidrv+0484<-sou2o+0090<-opimai_real+01bc<-main+0098<-__start+0070 ---------------------------------------- SO: 70000078f2c84a0, type: 4, owner: 700000784271270, flag: INIT/-/-/0x00 (session) sid: 236 trans: 7000007619fcf08, creator: 700000784271270, flag: (100041) USR/- BSY/-/-/-/-/- DID: 0001-025F-00004ADB, short-term DID: 0001-0262-00000005 txn branch: 700000760262cd0 oct: 2, prv: 0, sql: 70000043a39dda8, psql: 7000006feac35a8, user: 88/ZSCLMINTF service name: zsiims O/S info: user: oracle, term: , ospid: 10027038, machine: zsinsraca2 program: oracle@zsinsraca2 (TNS V1-V3) application name: oracle@zsinsraca2 (TNS V1-V3), hash value=450405937 waiting for 'row cache lock' blocking sess=0x0 seq=15070 wait_time=0 seconds since wait started=1605 cache id=3, mode=0, request=3 ============> cache id为3, 即dc_rollback_segments上的争用
Dumping Session Wait History
for ‘row cache lock’ count=1 wait_time=1388976
cache id=3, mode=0, request=3

此时我们并不能简单的认为,这个问题和rollback/undo有关
因为此时LCK0进程也在等待和kghfrunp(释放shared pool中内存)有关的latch,而在RAC环境里, row cache lock/library cache lock这样的instance lock的获取和释放必须经过LCK0进程,如果LCK0异常,那么就会发生row cache lock的问题.

PROCESS 33:
—————————————-
SO: 70000078627a560, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=33, calls cur/top: 7000007853a1520/7000007853a1520, flag: (6) 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: 700000782261488 12 0
last post sent: 0 0 21
last post sent-location: ksbria
last process posted by me: 70000078627a560 1 6
(latch info) wait_event=0 bits=0
Location from where call was made: kqrbip:
waiting for 70000075f1cd020 Child row cache objects level=4 child#=16
Location from where latch is held: kghfrunp: clatch: nowait:
Context saved from call: 0
state=busy, wlstate=free
waiters [orapid (seconds since: put on list, posted, alive check)]:
33 (3, 3, 3)
431 (3, 1444101789, 3)
486 (3, 1444101789, 3)
492 (3, 1444101789, 3)
468 (3, 1444101789, 3)
321 (3, 1444101789, 3)
470 (3, 1444101789, 3)
66 (3, 1444101789, 3)
276 (3, 1444101789, 3)
388 (3, 1444101789, 3)
207 (3, 1444101789, 3)
205 (3, 1444101789, 3)
443 (3, 1444101789, 3)
waiter count=13
gotten 1588533458 times wait, failed first 46002888 sleeps 3053343
gotten 2849791 times nowait, failed: 4267742
possible holder pid = 75 ospid=32440736
on wait list for 70000075f1cd020
Process Group: DEFAULT, pseudo proc: 7000007852bdfc8
O/S info: user: oracle, term: UNKNOWN, ospid: 6881304
OSD pid info: Unix process pid: 6881304, image: oracle@zsinsraca1 (LCK0)
Short stack dump:
ksdxfstk+002c< -ksdxcb+04e4<-sspuser+0074<-000047DC<-sskgpwwait+0034<-skgpwwait+00bc<-kslges+054c<-kslgetl+033c<-kqrbip+03c8<-kqrbfr+01ec<-kqrbtm+00c8<-ksbcti+03c8<-ksbabs+03fc<-kclabs+00d8<-ksbrdp+04b4<-opirip+03fc<-opidrv+0458<-sou2o+0090<-opimai_real+0150<-main+0098<-__start+0070 ---------------------------------------- SO: 70000078f366290, type: 4, owner: 70000078627a560, flag: INIT/-/-/0x00 (session) sid: 1062 trans: 0, creator: 70000078627a560, flag: (51) USR/- BSY/-/-/-/-/- DID: 0000-0021-00000003, short-term DID: 0000-0000-00000000 txn branch: 0 oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS service name: SYS$BACKGROUND waiting for 'latch: row cache objects' blocking sess=0x0 seq=45472 wait_time=0 seconds since wait started=0 address=70000075f1cd020, number=c8, tries=1 Dumping Session Wait History for 'latch: row cache objects' count=1 wait_time=906249 address=70000075f1cd020, number=c8, tries=0 for 'latch: row cache objects' count=1 wait_time=27503 address=70000075f1cd020, number=c8, tries=2 for 'latch: row cache objects' count=1 wait_time=292982 address=70000075f1cd020, number=c8, tries=1 综合考虑,从现在得到的信息来看,很可能发生问题时shared pool的使用出现了问题,但是因为我们没有更具体的dba_hist_active_sess_history数据,并且并没有在发生问题的第一时间收集systemstate dump,我们可能无法更进一步的确认它了. LOG FILE -------------- Filename=awrrpt_1_25919_25920.html ===> 发生问题前1个小时的AWR report
See the following:

Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 25919 06-Oct-15 09:00:26 224 6.6
End Snap: 25920 06-Oct-15 10:00:36 233 6.3
Elapsed: 60.17 (mins)
DB Time: 18.51 (mins)

Cache Sizes

Begin End
Buffer Cache: 21,776M 21,776M Std Block Size: 8K
Shared Pool Size: 8,752M 8,752M Log Buffer: 30,672K

SGA breakdown difference
ordered by Pool, Name
N/A value for Begin MB or End MB indicates the size of that Pool/Name was insignificant, or zero in that snapshot
Pool Name Begin MB End MB % Diff
shared CCursor 302.83 323.98 6.98
shared Cursor Stats 222.80 222.80 0.00
shared KGH: NO ACCESS 6,056.99 6,056.99 0.00 ===========> 将近6个GB是被KGH: NO ACCESS所使用
shared PCursor 252.15 274.83 9.00
shared free memory 5,239.86 4,815.81 -8.09
shared gcs resources 418.68 418.68 0.00
shared gcs shadows 384.49 384.49 0.00
shared kglsim heap 245.99 245.99 0.00
shared kglsim object batch 416.87 416.87 0.00
shared library cache 251.35 258.46 2.83
shared sql area 382.75 764.75 99.80

1. 发生问题前的awr report显示shared pool中大部分的内存都被KGH: NO ACCESS占用
2. 而发生问题后的systemstate dump显示非常多的进程都在等待跟kghfrunp功能有关的latch (LCK0也在等这样的latch, 导致了系统出现严重的row cache enqueue/row cache lock问题)
而这个kghfrunp功能是要从shared pool中释放空间,这说明shared pool当时不够用

8666117.8, patch 8666117 可以优化lck0在shared pool有压力下的工作,可以减缓row cache lock的问题
note 801787.1里 ,有以下的三个方式可以减少 KGH: NO ACCESS的大小:

a). 设置最小的buffer cache及shared pool的值
b). 减少shared pool resize的频率:设置 _memory_broker_stat_interval
c). 打patch 7189722

Aix clone cause the user process limit value changed

aix 5以及aix6系统在克隆以后,导致oracle用户的process数量限制初始化为128.在一切ha搭建或者主备机切换过程会导致监听以及中间件,客户端时而可连时而不可连接的状况。

在实施oracle要求中这个参数应该设置为65536或者大于65536.可以通过在root用户中进去smit chgsys修改,当然也可以用命令 chdev -l sys0 -a maxuproc ‘65536’来修改。

最近几个客户在克隆系统后,都遭遇了此类问题。希望对大伙有帮助,能引起注意。

感谢那些信任我的朋友们

10月1日收到邮件,准确的说应该是美国的9月30号发出,收到Oracle 授予了ace项目组相关的荣誉的通知.感谢朋友们的支持,也感谢oracle的认可.

开始从事oracle相关工作的时候就对ace无比神往,可是多年下来,接触了不少带有这个头衔的工程师,有些许的技术让我对此有所失望,甚至十分失望.但愿我持续的努力能不负此荣誉.只碍于时间有限,能做的事情太有限.

此时感觉没有预想中的那样里程碑式的松一口气,反而更加担心自己是否有足够的精力来做一些对数据库技术有意义的事情.才认识到此时才是蹒跚起步阶段.

在此衷心的感谢那些不断支持和信任我的小伙伴们.

浅谈Oracle数据库坏块( Database corruption part 1 )

关于坏块这一类的故障,从业这些年遇见得比较多,有的数据还能抢救,有的数据直接就丢了,更甚者数据库因此报废了. 一旦碰到,虽说不一定棘手,但是不免心里求佛一翻.

所谓Oracle数据库坏块顾名思义oracle数据库所在的数据存储介质的内容出现了讹误混乱或者无法访问.在Oracle自己的范围内对坏块有定义,这个可以参考文档[Note 840978.1].

坏块的种类有很多,它有可能因为各种原因出现在Oracle database的几种文件上面,报错也因此各有差异,处理的手段方法也各不相同,很早之前我就承诺过对这部分内容进行梳理更新到ludatou.com上,而现在我和陈辉正在对Mdata针对坏块部分的处理在做研发.所以趁此机会也尽量将文章更新到博客上,大部分上会是原创,有好的文章我也会转发.浅谈坏块这一系列的文章以方法和原理为主,除此之外我会把以往的坏块处理案例以日志方式更新,不作为浅谈部分文章.

浅谈坏块内容主要包含以下几部分:

    坏块分类以及产生的主要原因
    坏块的构造,检测方法以及可能发生的Oracle文件
    坏块的主要错误以及处理方法
    坏块的预防方式

本篇为坏块分类以及产生的主要原因

————————————————

1.坏块的主要分类,来自Oracle官方文档的解释,有助于更直接的了解区分物理坏块和逻辑坏块的区别(Note 840978.1有更加详细的描述):

For purposes of the paper we will categorize corruption under three general areasand give best practices for prevention, detection and repair for each:

    Memory corruption
    Logical corruption(soft corruption)
    Media corruption(Physicalcorruption)

Physicalor structural corruption can be defined as damage to internal data structureswhich do not allow Oracle software to find user data within the database. Logical corruption involves Oracle beingable to find the data, but the data values are incorrect as far as the end useris concerned.
Physica lcorruption due to hardware or software can occur in two general places — inmemory (including various IO buffers and the Oracle buffer cache) or on disk.Operator error such as overwriting a file can also be defined as a physicalcorruption. Logical corruption on theother hand is usually due to end-user error or non-robust(?) applicationdesign. A small physical corruption such as a single bit flip may be mistakenfor a logical error.

2.坏块的产生主要原因
坏块产生的原因很多 ,这里根据资料整理以及历史遭遇梳理出主要产生数据库坏块的原因.

    2.1 硬件问题
    Oracle进程在处理一个数据块时,首先将其读入物理内存空间,在处理完成后,再由特定进程将其写回磁盘;如果在这个过程中,出现内存故障,CPU计算失误,都会导致内存数据块的内容混乱,最后反映到写回磁盘的数据块内容有误。同样,如果存储子系统出现异常,数据块损坏也就随之出现了。比如硬盘出现坏道,那么这部分的数据就处于无法读取的情况,和坏块没有区别.

    2.2 操作系统BUG
    由于Oracle进程对数据块的读写,都是以操作系统内核调用(system call)的方式完成的,如果操作系统在内核调用存在问题,必然导致Oracle进程写入非法的内容。

    2.3 操作系统的I/O错误或缓冲问题
    比如写丢失,io系统缓存掉电,io操作结果被截断

    2.4 内存或paging问题
    Oracle软件有较多的bug能导致坏块问题的出现,

    2.5 非Oracle进程扰乱Oracle共享内存区域
    如上文所述,在当数据块的内容被读入主机的物理内存时,如果其他非Oracle进程,对Oracle使用的共享内存区域形成了扰乱,最终导致写回磁盘的数据块内容混乱。

    2.6 异常关机,掉电,终止服务
    异常关机,掉电,终止服务使进程异常终止,也会导致坏块产生。

    2.7 数据库操作人为失误
    使用nologging选项操作后再做恢复后可能造成坏块,或者人为的破坏文件导致的坏块。

Oracle坏块常见错误

ORA-1578

ORA-1578 is reported when a block is thought to be corrupt on read.

ORA-1410

This error is raised when an operation refers to a ROWID in a table for which there is no such row.
The reference to a ROWID may be implicit from a WHERE CURRENT OF clause or directly from a WHERE ROWID=… clause.
ORA 1410 indicates the ROWID is for a BLOCK that is not part of this table.

ORA-8103

The object has been deleted by another user since the operation began.
If the error is reproducible, following may be the reasons:-
a.) The header block has an invalid block type.
b.) The data_object_id (seg/obj) stored in the block is different than the data_object_id stored in the segment header. See dba_objects.data_object_id and compare it to the decimal value stored in the block (field seg/obj).

ORA-8102

An ORA-08102 indicates that there is a mismatch between the key(s) stored in the index and the values stored in the table. What typically happens is the index is built and at some future time, some type of corruption occurs, either in the table or index, to cause the mismatch.

ORA-1498

Generally this is a result of an ANALYZE … VALIDATE … command.
This error generally manifests itself when there is inconsistency in the data/Index block. Some of the block check errors that may be found:-
a.) Row locked by a non-existent transaction
b.) The amount of space used is not equal to block size
c.) Transaction header lock count mismatch.
While support are processing the tracefile it may be worth the re-running the ANALYZE after restarting the database to help show if the corruption is consistent or if it ‘moves’.
Send the tracefile to support for analysis.
If the ANALYZE was against an index you should check the whole object. Eg: Find the tablename and execute:
ANALYZE TABLE xxx VALIDATE STRUCTURE CASCADE;

ORA-1499

An error occurred when validating an index or a table using the ANALYZE command.
One or more entries does not point to the appropriate cross-reference.

ORA-26040

Trying to access data in block that was loaded without redo generation using the NOLOGGING/UNRECOVERABLE option.
This Error raises always together with ORA-1578

ORA-600 [12700]

Oracle is trying to access a row using its ROWID, which has been obtained from an index.
A mismatch was found between the index rowid and the data block it is pointing to. The rowid points to a non-existent row in the data block. The corruption can be in data and/or index blocks.
ORA-600 [12700] can also be reported due to a consistent read (CR) problem.

ORA-600 [3020]

This is called a ‘STUCK RECOVERY’.
There is an inconsistency between the information stored in the redo and the information stored in a database block being recovered.

ORA-600 [4194]

A mismatch has been detected between Redo records and rollback (Undo) records.
We are validating the Undo record number relating to the change being applied against the maximum undo record number recorded in the undo block.
This error is reported when the validation fails.

ORA-600 [4193]

A mismatch has been detected between Redo records and Rollback (Undo) records.
We are validating the Undo block sequence number in the undo block against the Redo block sequence number relating to the change being applied.
This error is reported when this validation fails.

ORA-600 [4137]

While backing out an undo record (i.e. at the time of rollback) we found a transaction id mis-match indicating either a corruption in the rollback segment or corruption in an object which the rollback segment is trying to apply undo records on.
This would indicate a corrupted rollback segment.

ORA-600 [6101]

Not enough free space was found when inserting a row into an index leaf block during the application of undo.

ORA-600 [2103]

Oracle is attempting to read or update a generic entry in the control file.
If the entry number is invalid, ORA-600 [2130] is logged.

ORA-600 [4512]

Oracle is checking the status of transaction locks within a block.
If the lock number is greater than the number of lock entries, ORA-600 [4512] is reported followed by a stack trace, process state and block dump.
This error possibly indicates a block corruption.

ORA-600 [2662]

A data block SCN is ahead of the current SCN.
The ORA-600 [2662] occurs when an SCN is compared to the dependent SCN stored in a UGA variable.
If the SCN is less than the dependent SCN then we signal the ORA-600 [2662] internal error.

ORA-600 [4097]

We are accessing a rollback segment header to see if a transaction has been committed.
However, the xid given is in the future of the transaction table.
This could be due to a rollback segment corruption issue OR you might be hitting the following known problem.

ORA-600 [4000]

It means that Oracle has tried to find an undo segment number in the dictionary cache and failed.

ORA-600 [6006]

Oracle is undoing an index leaf key operation. If the key is not found, ORA-00600 [6006] is logged.
ORA-600[6006] is usually caused by a media corruption problem related to either a lost write to disk or a corruption on disk.

ORA-600 [4552]

This assertion is raised because we are trying to unlock the rows in a block, but receive an incorrect block type.
The second argument is the block type received.

ORA-600[6856]

Oracle is checking that the row slot we are about to free is not already on the free list.
This internal error is raised when this check fails.

ORA-600[13011]

During a delete operation we are deleting from a view via an instead-of trigger or an Index organized table and have exceeded a 5000 pass count when we raise this exception.

ORA-600[13013]

During the execution of an UPDATE statement, after several attempts (Arg [a] passcount) we are unable to get a stable set of rows that conform to the WHERE clause.

ORA-600[13030]

ORA-600[25012]

We are trying to generate the absolute file number given a tablespace number and relative file number and cannot find a matching file number or the file number is zero.

ORA-600[25026]

Looking up/checking a tablespace
invalid tablespace ID and/or rdba found

ORA-600[25027]

Invalid tsn and/or rfn found

ORA-600 [kcbz_check_objd_typ_3]

An object block buffer in memory is checked and is found to have the wrong object id. This is most likely due to corruption.

ORA-600[kddummy_blkchk] &ORA-600[kdblkcheckerror]

ORA-600[kddummy_blkchk] is for 10.1/10.2 and ORA-600[kdblkcheckerror] for 11 onwards.

ORA-600[ktadrprc-1]

ORA-600[ktsircinfo_num1]

This exception occurs when there are problems obtaining the row cache information correctly from sys.seg$. In most cases there is no information in sys.seg$.

ORA-600[qertbfetchbyrowid]

ORA-600[ktbdchk1-bad dscn]

This exception is raised when we are performing a sanity check on the dependent SCN and fail.
The dependent scn is greater than the current scn.

ORA-12518: TNS: listener could not hand off client connection

ORA-12518: TNS: listener could not hand off client connection

Note:
Starting in 11gR2, the listener log is not activated by default. You have to turn on listener logging: logging_listener_name=on

Oracle docs note this about ORA-12518:

ORA-12518:
TNS:listener could not hand off client connection

Cause:
The process of handing off a client connection to another process failed.

Action:
Turn on listener tracing and re-execute the operation. Verify that the listener and database instance are properly configured for direct handoff. If problem persists, call Oracle Support.

ORA-12518 has been known to occur in Oracle Net Services version 9.2.0.5-11.2.0.1 in which attempting new connections on the database throw either ORA-12518 or TNS-12518.ORA-12518 appears in the listener log upon new user connection.

来自orace.群员的提问摘录。

处理 Oracle7/8/8i/9i/10g/11g 中的 Oracle 块损坏(转)

本文章讨论如何处理 Oracle 数据文件中的一个或多个坏块,并介绍了处理这些坏块的主要方法。在采取任何措施之前,请先阅读完整篇文章。
本文档未介绍内存坏块问题(通常为 ORA-600 [17xxx] 类型错误)。

注意: 如果在启动时出现 ORA-1578 问题,请与当地支持中心联系,以获得参考建议。

本文章介绍了许多类型的错误,很多其他地方也可能引用到本文章。重要的是,您需要知道关于每个坏块的以下信息:

包含坏块的文件的绝对文件编号 (FILE NUMBER)。本文中称为“&AFN”。包含坏块的文件的名称。本文中称为“&FILENAME”。

如果您知道文件编号,但不知道文件名,则可以使用 V$DATAFILE 来获取文件名:
SELECT name FROM v$datafile WHERE file#=&AFN;

如果文件号未显示在 Oracle8i 的 V$DATAFILE 中,且 &AFN 大于 DB_FILES 参数值,则该文件可能是临时文件。在这种情况下,可以使用以下查询找到文件名:
SELECT name FROM v$tempfile WHERE file#=(&AFN – &DB_FILES_value);

文件中坏块的块编号。本文中称为“&BL”。包含受影响块的表空间编号和名称。

本文中称为“&TSN”(表空间编号)和“&TABLESPACE_NAME”。

如果您不知道这些信息,请使用以下查询找到它们:
SELECT ts# “TSN” FROM v$datafile WHERE file#=&AFN;
SELECT tablespace_name FROM dba_data_files WHERE file_id=&AFN;
表空间中的坏块大小。本文中称为“&TS_BLOCK_SIZE”。

SELECT block_size FROM dba_tablespaces
WHERE tablespace_name =
(SELECT tablespace_name FROM dba_data_files WHERE file_id=&AFN);
对于 Oracle 7、8.0 和 8.1:

数据库中所有表空间使用相同的块大小。
对于这些版本,使用命令”SHOW PARAMETER DB_BLOCK_SIZE” 返回的值作为 “ &TS_BLOCK_SIZE”

例如:对于 ORA-1578 错误:

ORA-01578: ORACLE data block corrupted (file # 7, block # 12698)
ORA-01110: data file 22: ‘/oracle1/oradata/V816/oradata/V816/users01.dbf’
那么:

&AFN 为 “22” (从错误 ORA-1110 部分获得)
&RFN 为 “7” (从错误 ORA-1578 的”file #”部分获得)
&BL 为 “12698” (从错误 ORA-1578 的”block #”部分获得)
&FILENAME 为 ‘/oracle1/oradata/V816/oradata/V816/users01.dbf’
&TSN 及其他信息可以从上面提到的 SQL 语句获得

对于其他错误(ORA-600、ORA-1498 等),上述值应由 Oracle Support 提供给您,或从涵盖相关错误的文章中获取。
对于某些错误,如 ORA-1410“invalid ROWID(无效 ROWID)”、ORA-12899“value too large for column(列值过大)”等,未给出损坏的文件/块的详细信息。对于此类情况, Note:869305.1 可以帮助您定位损坏的行。

概述处理坏块的步骤

有多种原因可能导致坏块,包括:

坏的 IO 硬件/固件
OS 问题
Oracle 问题
对于执行过“UNRECOVERABLE”或“NOLOGGING”操作的数据库进行恢复
(在这种情况下可能产生 ORA-1578 错误 – 如下方所示)
产生 Oracle 错误的时间点可能要比最初发生任何块损坏的时间点晚得多。

在遇到坏块时,我们通常无从了解根本原因,并且在大多数情况下,当下最迫切的需求是重新启动数据库并使其运行起来,正因如此,本文将介绍用于解决坏块问题的步骤,如下所列:

确定坏块问题的范围,并确定这些问题是持久性问题还是暂时性问题。
如果问题涉及范围很大,或错误不稳定,则关键在于先识别原因(检查硬件等)。这点很重要,因为如果是底层硬件出现错误,恢复系统便毫无意义。

更换或拆下任何有问题的或可疑的硬件。
确定哪些数据库对象受到影响。
选择最合适的数据库恢复/数据抢救选项。
对于上述所有步骤,最好应收集证据并详细记录所采取的措施。本文中的“证据>>”标签列出了应收集的信息,以帮助您识别问题的根本原因。

由于 NOLOGGING 或 UNRECOVERABLE 操作导致的坏块

如果对某个对象执行了 NOLOGGING(或 UNRECOVERABLE)操作,随后又恢复了包含该对象的数据文件,则受到 NOLOGGING 操作影响的数据块将被标记为“坏块”,当您访问该数据块时将显示 ORA-1578 错误。
NOLOGGING option(数据块使用 NOLOGGING 选项加载)”,此时原因一目了然,而较早版本中则没有附加这条错误消息。如果坏块是由于对执行过 NOLOGGING 操作的数据文件进行恢复而产生的,则可以使用本文中从 Section 3 “Information to Record for Each Corruption” 开始之后介绍的内容,但请注意以下问题:

恢复操作无法找回受 NOLOGGING 操作影响的数据
块内的数据无法抢救

(1) 确定坏块问题的范围

每次发生坏块错误时,都应记下完整的错误消息,并查看该实例的告警日志和跟踪文件,以了解任何相关的错误。首先进行这些步骤非常重要,这可以评估该损坏是单个块,还是由于 UNRECOVERABLE 操作产生的错误,抑或是更严重的问题。
使用 DBVERIFY 扫描受影响的文件(以及一切重要的文件)也是不错的办法,这样可以检查是否有其他坏块,从而确定问题的范围。有关使用 DBVERIFY 的详细信息,请参阅 Note:35512.1

一旦确定了损坏的文件/块组合列表,即可使用以下步骤来帮助确定应采取何种措施。

证据:
完整记录初始错误,以及发生错误的应用程序的详细信息。
及时地保存从告警日志中首次 (FIRST) 记录到问题前数小时到当前时间点所提取的内容。
保存告警日志中提到的任何跟踪文件。
记录最近遇到的任何 OS 问题。
记录是否正在使用任何特殊功能,例如:ASYNC IO、快速写入磁盘选项等。
记录当前的备份位置(日期、类型等)
记录数据库是否处于 ARCHIVELOG 模式,
例如:在SQL*Plus(或 Server Manager)中运行“ARCHIVE LOG LIST”

(2) 更换或拆下可疑硬件

大多数坏块问题是由故障硬件导致的。
如果出现硬件错误或可疑组件,最好进行修复,或者在执行恢复操作之前,确保在单独的磁盘子系统上有足够的可用空间用于恢复。

您可以使用以下步骤移动数据文件:

确保要迁移的文件已离线或数据库实例处于 MOUNT 状态(未打开)
将该数据文件物理还原(或复制)到新位置
例如:/newlocation/myfile.dbf
将该文件的新位置告知 Oracle。
例如:ALTER DATABASE RENAME FILE ‘/oldlocation/myfile.dbf’ TO ‘/newlocation/myfile.dbf’;
(请注意,您不能对临时文件进行重命名,而应删除临时文件并在新位置重新创建)
重要信息: 如果存在多个错误(不是由于 NOLOGGING操作导致的)
或 受影响文件所在的 OS 层面出现错误
或 错误是暂时性的且游离不定,
那么,如果不解决底层问题或准备另外的磁盘空间,那么进行任何操作都是毫无意义的。
与硬件供应商联系,以全面检查系统,并联系 Oracle Support,告知所有错误详情。
请注意: 如果硬件检查失败,即表明存在硬件问题,但硬件检查成功通过却并不能证明没有硬件相关问题 — 硬件测试报告成功但确实存在底层错误,这种情况也是经常发生。
如果使用了任何特殊 IO 选项,例如 direct IO、async IO 或类似的选项,最好将其禁用,以消除这些选项成为潜在问题原因的可能性。

(3) 每次坏块需记录的信息

在决定如何恢复之前,最好先确定哪些对象受到了影响,因为坏块可能发生在那些容易被重新创建的对象中。
例如:对于只有 5 行数据的表中发生的坏块,删除并重新创建表可能要比执行恢复快得多。

对于每个坏块,请收集下表中的信息。
进行此操作的步骤如下所述。

针对每次坏块需记录的信息
初始错误
绝对文件号

&AFN

相关文件号

&RFN

块编号

&BL

表空间 段类型 段
所有者.名称 相关对象 恢复选项
下列说明将有助于您针对每个坏块填写此表。

“初始错误”最初报告的错误。例如:ORA-1578/ORA-1110、ORA-600 和所有参数等。
“绝对文件号”, “相关文件号”和”块号”文件号和块号应该已在错误中显示,或由 Oracle Support 提供,或在指引您参考本文章的其他文章的步骤中提供。
在 Oracle8/8i/9i/10g 中: 绝对文件号和相关文件号通常是一样的,但也可能不同(尤其是在数据库是由 Oracle7 迁移而来的情况下)。请务必获得正确的 &AFN 和 &RFN 编号,否则您可能最终抢救的是错误的对象!!
ORA-1578 报告相关文件号,绝对文件号在伴随的 ORA-1110 错误中显示。对于 ORA-600 错误,您应该会被告知绝对文件号。
下列查询将显示数据库中数据文件的绝对和相关文件号:
SELECT tablespace_name, file_id “AFN”, relative_fno “RFN” FROM dba_data_files;[Insert code here. Use ‘Paste from Word’ to retain layout.]
在 Oracle8i/9i/10g 中:
除了上述关于 Oracle8 的说明外,从 Oracle8i 开始将拥有临时文件。下列查询将显示数据库中临时文件的绝对和相关文件号:
SELECT tablespace_name, file_id+value “AFN”, relative_fno “RFN” FROM dba_temp_files, v$parameter WHERE name=’db_files
在 Oracle7 中: “绝对文件号”和“相关文件号”使用相同的文件号
“段类型”, “所有者”, “名称”和”表空间”
在给定坏块的绝对文件号“&AFN”和块编号“&B”的情况下,下列查询将显示对象的段类型、所有者和名称,数据库必须打开才能使用此查询:
SELECT tablespace_name, segment_type, owner, segment_name FROM dba_extents
WHERE file_id = &AFN
and &BL between block_id AND block_id + blocks – 1;
如果坏块位于临时文件中,则上述查询将不会返回任何数据。
对于临时文件,“段类型”应为“TEMPORARY”。

如果上述查询未返回行,也可能是因为坏块是本地管理表空间 (Locally Managed Tablespace, LMT) 中的段头。当坏块为 LMT 中的段头块时,上述查询将在 alert.log 中生成一个坏块消息,但查询不会失败。在这种情况下,请使用以下查询:
SELECT owner, segment_name, segment_type, partition_name
FROM dba_segments
WHERE header_file = &AFN
and header_block = &BL;
{go to content}

(4) Which Object is affected and 可能的恢复选项:

相关对象和能够使用的恢复选项取决于 SEGMENT_TYPE。对于各种最常见的段类型,其他查询和可能的恢复选项如下所列。

CACHE
CLUSTER
INDEX PARTITION
INDEX
LOBINDEX
LOBSEGMENT
ROLLBACK
TABLE PARTITION
TABLE
TEMPORARY
TYPE2 UNDO
Some other Segment Type
“no rows” from the query

CACHE

如果段类型为 CACHE,请再次检查您是否输入了正确的 SQL语句和参数。
如果仍得到相同结果,请联系 Oracle Support 并上传您所了解的全部信息。

选项:可能需要恢复数据库。

{Continue} {Back to Segment List}

CLUSTER

如果段类型为 CLUSTER,则应确定它包含哪些表。

例如: SELECT owner, table_name fROM dba_tables WHERE owner=’&OWNER’ AND cluster_name=’&SEGMENT_NAME’;
选项:
如果所有者为“SYS”,则联系 Oracle Support 并上传所有详细信息。
可能需要恢复数据库。
对于非数据字典 cluster,可能的选项包括:

恢复
或 抢救 cluster 中所有表的数据
然后 重新创建 cluster 及其所有表

cluster 可能包含多个表,因此在做出决策之前,最好先收集 cluster 中每个表的信息。

{Collect TABLE information} {Back to Segment List}

INDEX PARTITION

如果段类型为 INDEX PARTITION,请记录名称和所有者,然后确定哪些分区受到影响:

SELECT partition_name
FROM dba_extents
WHERE file_id = &AFN AND &BL BETWEEN block_id AND block_id + blocks – 1
选项:
使用下列语句可以重建索引分区:
ALTER INDEX xxx REBUILD PARTITION ppp;
(请注意下方“重建索引”中所述的 REBUILD 选项)

{Continue} {Back to Segment List}

INDEX

如果段类型为 INDEX,而且所有者为“SYS”,则联系 Oracle Support 并上传所有详细信息。
对于非字典 INDEX 或 INDEX PARTITION,确定索引位于哪个表中:

SELECT table_owner, table_name
FROM dba_indexes
WHERE owner=’&OWNER’ AND index_name=’&SEGMENT_NAME’;
CONSTRAINT_TYPE 的可能值包括:
– P 索引支持主键约束。
– U 索引支持唯一约束。
如果索引支持主键约束(类型“P”),则确认主键是否被任何外键约束引用:

SELECT owner, constraint_name, constraint_type, table_name
FROM dba_constraints
WHERE r_owner=’&TABLE_OWNER’ AND r_constraint_name=’&INDEX_NAME’;
选项:
如果所有者为“SYS”,则联系 Oracle Support 并上传所有详细信息。
可能需要恢复数据库。

对于非字典索引,可能的选项包括:

恢复
或 重建索引(任何相关联的约束会随之禁用/启用)
(请注意下方”重建索引”中所述的 REBUILD 选项)

{Continue} {Back to Segment List}

ROLLBACK

如果段类型为 ROLLBACK,请联系 Oracle Support,因为 ROLLBACK 段坏块需要特殊处理。

选项:
可能需要恢复数据库。

{Continue} {Back to Segment List}

TYPE2 UNDO

TYPE2 UNDO 是系统管理的 undo 段,它是 rollback 段的一种特殊形式。这些段的坏块需要特殊处理。

选项:
可能需要恢复数据库。

{Continue} {Back to Segment List}

TABLE PARTITION

如果段类型为 TABLE PARTITION,请记录名称和所有者,然后确定哪些分区受到影响:

SELECT partition_name
FROM dba_extents
WHERE file_id = &AFN
AND &BL BETWEEN block_id AND block_id + blocks – 1;
然后按照处理 TABLE 段的步骤继续下面的操作。

选项:
如果所有坏块均位于同一个分区,则此时可以采取的一个做法是用一个空表 EXCHANGE 坏块所在的分区,这可以让应用程序继续运行(无法访问坏块所在的分区中的数据),然后可以从之前的空表中提取任何未损坏的数据。
有关其他选项,请参见下面的 TABLE 选项。

{Continue} {Back to Segment List}

TABLE

如果所有者为“SYS”,则联系 Oracle Support 并上传所有详细信息。
可能需要恢复数据库。

对于非字典 TABLE 或 TABLE PARTITION,确定表中存在哪些索引:

例如: SELECT owner, index_name, index_type
FROM dba_indexes
WHERE table_owner=’&OWNER’
AND table_name=’&SEGMENT_NAME’;
并确定表中是否存在任何主键:

例如:SELECT owner, constraint_name, constraint_type, table_name
FROM dba_constraints
WHERE owner=’&OWNER’
AND table_name=’&SEGMENT_NAME’
AND constraint_type=’P’;
如果存在主键,则确认它是否被任何外键约束引用:

例如:
SELECT owner, constraint_name, constraint_type, table_name
FROM dba_constraints
WHERE r_owner=’&OWNER’
AND r_constraint_name=’&CONSTRAINT_NAME’;
选项:
如果所有者为“SYS”,则联系 Oracle Support 并上传所有详细信息。
可能需要恢复数据库。

对于非字典表,可能的选项包括:
恢复
或 抢救表(或分区)中的数据
然后 重新创建表(或分区)
或 忽略坏块
(例如:使用 DBMS_REPAIR 标记需要跳过的问题块)

{Continue} {Back to Segment List}

IOT(索引组织表)

IOT 表中的坏块应按照表或分区表中的处理方式来处理。
唯一的例外是如果 PK 损坏。
IOT 表的 PK 就是表本身,它不能被删除和重新创建。

选项:
如果所有者为“SYS”,则联系 Oracle Support 并上传所有详细信息。
可能需要恢复数据库。

对于非字典表,可能的选项包括:
恢复
或 抢救表(或分区)中的数据
然后 重新创建表(或分区)
或 忽略坏块
(DBMS_REPAIR 不适用于 IOT)

{Continue} {Back to Segment List}

LOBINDEX

确定 LOB 属于哪个表:

SELECT table_name, column_name
fROM dba_lobs
wHERE owner=’&OWNER’
AND index_name=’&SEGMENT_NAME’;

如果表的所有者为“SYS”,则联系 Oracle Support 并上传所有详细信息。可能需要恢复数据库。

不可以重建 LOB 索引,因此您必须将该问题作为受影响的表中 LOB 列上的坏块来处理。

使用 ”TABLE“ 部分中的 SQL 语句获取包含损坏的 LOB 索引的表的索引和约束信息,然后返回此处。

选项:

如果所有者为“SYS”,则联系 Oracle Support 并上传所有详细信息。
可能需要恢复数据库。

对于非字典表,可能的选项包括:
恢复
或 抢救表(及其 LOB 列)中的数据
然后 重新创建表
忽略坏块的做法通常不可取,除非不大可能对表中的问题列执行任何进一步的 DML 操作。

{Continue} {Back to Segment List}

LOBSEGMENT

确定 LOB 属于哪个表:

例如:
SELECT table_name, column_name
FROM dba_lobs
WHERE owner=’&OWNER’
AND segment_name=’&SEGMENT_NAME’;

如果表的所有者为“SYS”,则联系 Oracle Support 并上传所有详细信息。可能需要恢复数据库。

对于非字典表 …

使用 ”TABLE“ 部分中的 SQL 语句获取包含坏块的 LOB 数据的表的索引和约束信息,然后返回此处查找具体受影响的行的详细信息。

要查找引用损坏的 LOB 块的具体行可能比较困难,因为报告的错误中不会显示表中的哪一行数据包含损坏的 LOB 数据。

Typically one can refer to application logs or any SQL_TRACE or 10046 trace of a session hitting the error (if available) or see if having

event “1578 trace name errorstack level 3”
set in the session helps identify the current SQL/binds/row.

例如:
ALTER SYSTEM SET EVENTS ‘1578 trace name errorstack level 3’;
然后等待应用程序触发该错误,并查找跟踪文件。

如果没有任何线索,您可以构建 PLSQL 块,逐行扫描问题表以提取 LOB 列数据,扫描将一直循环进行,直至发生错误。此方法可能需要一段时间,但它应该可以找到引用了损坏的 LOB 块的数据行的主键或 ROWID。

例如:
set serverout on
exec dbms_output.enable(100000);
declare
error_1578 exception;
pragma exception_init(error_1578,-1578);
n number;
cnt number:=0;
badcnt number:=0;
begin
for cursor_lob in
(select rowid r, &LOB_COLUMN_NAME L from &OWNER..&TABLE_NAME)
loop
begin
n:=dbms_lob.instr(cursor_lob.L,hextoraw(‘AA25889911’),1,999999) ;
exception
when error_1578 then
dbms_output.put_line(‘Got ORA-1578 reading LOB at ‘||cursor_lob.R);
badcnt:=badcnt+1;
end;
cnt:=cnt+1;
end loop;
dbms_output.put_line(‘Scanned ‘||cnt||’ rows – saw ‘||badcnt||’ errors’);
end;
/

another script more generic:

set serverout on
exec dbms_output.enable(100000);
declare
pag number;
len number;
c varchar2(10);
charpp number := 8132/2;

begin
for r in (select rowid rid, dbms_lob.getlength () len
from ) loop
if r.len is not null then
for page in 0..r.len/charpp loop
begin
select dbms_lob.substr (, 1, 1+ (page * charpp))
into c
from
where rowid = r.rid;

exception
when others then
dbms_output.put_line (‘Error on rowid ‘ ||R.rid||’ page ‘||page);
dbms_output.put_line (sqlerrm);
end;
end loop;
end if;
end loop;
end;
/
选项:

如果所有者为“SYS”,则联系 Oracle Support 并上传所有详细信息。
可能需要恢复数据库。

对于非字典表,可能的选项包括:

恢复
或 抢救表(及其 LOB 列)中的数据
然后 重新创建表
或 忽略坏块
(不可以在 LOB 段上使用 DBMS_REPAIR)

{Continue} {Back to Segment List}

TEMPORARY

如果段类型为 TEMPORARY,则坏块不会影响永久对象。检查发生问题的表空间是否正在被用作 TEMPORARY 表空间:

SELECT count(*) FROM dba_users WHERE temporary_tablespace=’&TABLESPACE_NAME’;
选项:

如果是 TEMPORARY_TABLESPACE,则可能可以创建新的临时表空间,并将所有用户切换到该表空间,然后删除有问题的表空间。

如果不是临时表空间,则该块不会再被读取,而且会在下次使用时被重新格式化 — 如果问题的根本原因已经得到解决,则不应再发生该错误。

通常情况下,不需要进行任何还原,但如果磁盘可能有问题,且表空间包含有用数据,则最好对数据库中受影响的文件进行恢复。

{Continue} {Back to Segment List}

其他一些段类型

如果返回的段类型未包含在上述类型中,则请联系 Oracle Support 并提供迄今为止收集的所有信息,以获得相关建议。

{Continue} {Back to Segment List}

“无返回行”

如果没有包含坏块的 extent,则首先再次检查查询中使用的参数。如果您确定文件号和块编号是正确的,且不属于 DBA_EXTENTS 中的某个对象,则执行以下操作:

再次检查相关文件是否为临时文件。
请注意,临时文件的文件号取决于数据库初始化参数 DB_FILES,因此对该参数的任何更改都会改变错误中报告的绝对文件号。
DBA_EXTENTS 不包含本地管理表空间中用于本地空间管理的块。
如果您在数据库运行查询语句的时间点与出错的时间点不相同,那么问题对象可能已经被删除,因此针对 DBA_EXTENTS 的查询可能不会显示任何行。
如果您正在调查的错误由 DBVERIFY 报告,则 DBV 将检查所有块,而不管它们是否属于某个对象。因此,坏块可能存在于数据文件中,但却未被任何对象使用。
选项:

未使用的 Oracle 块上的错误可以忽略,因为如果需要使用该块,Oracle 会创建新的块映像(格式化),因此,该块上的任何问题将永不会被读取。

如果您怀疑该块可能是空间管理块,则可以使用 DBMS_SPACE_ADMIN 包来帮助您进行检查:

exec DBMS_SPACE_ADMIN.TABLESPACE_VERIFY(‘&TABLESPACE_NAME’);
以上命令会将不一致写入跟踪文件,但如果遇到致命的坏块,它将报告如下错误:

ORA-03216: Tablespace/Segment Verification cannot proceed

{Continue} {Back to Segment List}

{go to content}

证据

对于每个坏块,如果需要尝试并确定实际坏块原因,则收集如下物理证据也是一个比较好的方法:

坏块及位于其任意一侧的块的操作系统 HEX 转储。

在 UNIX 上:

dd if=&FILENAME bs=&TS_BLOCK_SIZE skip=&BL-1 count=3 of=BL.dd
^^^^^^^^ ^^^^^^^^^^^^^^ ^^^

例如:对于 BL=1224:

dd if=ts11.dbf bs=4k skip=1223 count=3 of=1223_1225.dd

在 VMS 上:

DUMP/BLOCKS=(start:XXXX,end:YYYY)/out=dump.out &FILENAME

其中 XXXX=操作系统块编号(512 字节块中)
要计算此值,用报告的块编号乘以“&TS_BLOCK_SIZE/512”。
处于 ARCHIVELOG 模式时,复制出错时间前后的归档日志文件的安全副本,最好包括报告错误前数小时的日志文件。并且,保存问题数据文件在出错前的所有副本,因为之前的数据文件映像以及 redo 记录有助于找出错误原因。
(DBV 通常可用于检查问题是否存在于文件的备份副本中)。理想的情况是获得没有报告坏块的数据文件备份映像,以及从该时间点开始到首次报告坏块时间之后不久的时段内的所有 redo 记录。

获得问题块的 Oracle 转储:
ALTER SYSTEM DUMP DATAFILE ‘&FILENAME’ BLOCK &BL;
(DUMP将生成到 USER_DUMP_DEST 下的跟踪文件)。

{Continue} {Back to Segment List}

{go to content}

(5) 选择恢复选项

现在,最佳的恢复选项取决于受影响的对象。前面第 (3) 部分中的说明应该已经重点介绍了针对每个受影响对象的主要可用选项。选择的实际恢复方法可能包含以下一种或多种混合方法:

是否需要进行任何恢复操作?

表空间中,或位于不再属于任何数据库对象的块中,则无需进行任何操作,尽管将问题表空间重定位到其他存储设备中可能较为明智。

请参阅警告

可以使用完全恢复吗?

要选用完全恢复,必须满足如下条件:

数据库处于 ARCHIVELOG 模式
(“ARCHIVE LOG LIST”命令显示 Archivelog 模式)

拥有受影响文件的完好备份。请注意,在某些情况下,坏块可能已经存在,但在很长一段时间内未被发现。如果最近的数据文件备份仍包含坏块,那么只要您拥有所 有必需的归档日志,就可以尝试使用更早的备份。
(通常可以使用 DBV START= / END= 选项来检查位于某个备份文件的恢复副本中的特定块是否损坏)

从备份时间开始到当前时间点的所有归档日志均可用

当前的在线日志均可用且完好无缺

错误不是由运行 NOLOGGING 操作之后执行的恢复所导致的

如果满足上述条件,完全恢复通常是首选方法

*但请注意*

如果事务回滚已发现坏块位于对象上,而非 rollback 段本身,则 undo 操作可能已被放弃。在这种情况下,可能需要在恢复完成后重建索引/检查数据完整性。

如果要恢复的文件包含自上次备份以来执行的 NOLOGGING 操作的数据,在使用了数据文件或数据库恢复的情况下,这些块将被标记为“坏块”。在某些情况下,这会使情况更加糟糕。
如果执行数据库恢复后坏块仍然存在,则表示所有备份都包含坏块,底层错误仍存在,或问题通过 redo 重现。在这些情况下,需要选择其他一些恢复选项。

请参阅 “(4A) 完全恢复” ,以了解完全恢复步骤。

{go to content}

如果不需要从对象本身提取任何数据,能否删除或重新创建该对象?

您可以删除对象或从脚本/最近导出的副本重新创建对象。一旦删除一个对象后,该对象中的块将被标记为“空闲”,并且该块在被分配到新对象时将被重新格式化。明智的做法是,对表进行重命名,而不是删除,除非您完全确定不再需要其中的数据。

对于表分区,只需要删除受影响的分区。

例如: ALTER TABLE … DROP PARTITION …
如果坏块影响到分区段头,或者包含分区头的文件处于离线状态,则 DROP PARTITION 可能会失败。在这种情况下,首先将其更换为具有相同定义的表,之后仍然可以删除该分区。

例如: ALTER TABLE .. EXCHANGE PARTITION .. WITH TABLE ..;
最常见的可重建对象为索引。始终在处理表中的索引问题之前处理表坏块。
有关详细信息,请参阅”(4B) 重建索引” 。

对于任何段,如果您拥有坏块的绝对文件号和块号,则可使用以下快速提取对象 DDL 的方法:

set long 64000
select dbms_metadata.get_ddl(segment_type, segment_name, owner)
FROM dba_extents
WHERE file_id=&AFN
AND &BL BETWEEN block_id AND block_id + blocks -1;

{go to content}

是否需要在重新创建对象之前抢救数据?

如果问题位于定期%9