刚发完上篇文章之后，又从老杨的一篇文章“http://blog.itpub.net/post/468/450451?SelectActiveLayout=a”中看到一些有所帮助的信息，而这个案例中在alert里看到，在这个600的错误抛出之前一条错误信息中看到：
Wed Jul 25 09:56:46 2012 Thread 1 advanced to log sequence 580 (LGWR switch) Current log# 1 seq# 580 mem# 0: +DATA/zhfr8db/onlinelog/group_1.271.783424599 Current log# 1 seq# 580 mem# 1: +FLASH/zhfr8db/onlinelog/group_1.256.783424601 Wed Jul 25 10:49:39 2012 Unexpected communication failure with ASM instance: error 21561 (ORA-21561: 生成 OID 失败 )
的错误信息。
从后续的alert日志里，尝试关闭数据库服务器的时候抛出的错误中也有类似错误：
Wed Jul 25 10:55:03 2012 Trace dumping is performing id=[cdmp_20120725105503] Wed Jul 25 10:56:06 2012 Restarting dead background process MMON MMON started with pid=33, OS id=6756 Wed Jul 25 12:46:20 2012 Unexpected communication failure with ASM instance: error 21561 (ORA-21561: 生成 OID 失败 ) NOTE: ASMB process state dumped to trace file c:\oracle\product\10.2.0\admin\zhfr8db\udump\zhfr8db1_ora_5552.trc Wed Jul 25 12:47:03 2012 Unexpected communication failure with ASM instance: error 21561 (ORA-21561: 生成 OID 失败 ) NOTE: ASMB process state dumped to trace file c:\oracle\product\10.2.0\admin\zhfr8db\udump\zhfr8db1_ora_2008.trc Wed Jul 25 12:50:01 2012 Unexpected communication failure with ASM instance: error 21561 (ORA-21561: 生成 OID 失败 )
再从c:\oracle\product\10.2.0\admin\zhfr8db\udump\zhfr8db1_ora_5552.trc文件跟踪看到：
*** 2012-07-25 12:46:20.268
*** CLIENT ID:() 2012-07-25 12:46:20.268
----------------------------------------
SO: 000000047111DEF0, type: 2, owner: 0000000000000000, flag: INIT/-/-/0x00
(process) Oracle pid=31, calls cur/top: 000000047E15DC20/000000047E15DC20, 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: 7e11e6f8 1 6
last post sent: 849 0 4
last post sent-location: kslpsr
last process posted by me: 7312aef8 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 00000004731384B8
O/S info: user: SYSTEM, term: DATACENTER01, ospid: 4828
OSD pid info: Windows thread id: 4828, image: ORACLE.EXE (ASMB)
Short stack dump:
ksdxfstk+42<-ksdxcb+1630<-ssthreadsrgruncallback+589<-OracleOradebugThreadStart+975<-0000000077D6B71A
<-0000000077EF047A<-0000000077DA79F3<-0000000008653328<-000000000865190C<-0000000005F564A9
<-0000000005F0CF64<-0000000005EE5D88<-0000000005EE57F9<-0000000005EA5ECB<-ttcdrv+14881
<-0000000005EAAA6D<-xupirtrc+1335<-xupirtr+216<-upirtr+23<-kpurcs+45
<-OCIKDispatch+32<-kfnOpExecute+146<-kfnbRun+1062<-ksbrdp+988<-opirip+700
<-opidrv+856<-sou2o+52<-opimai_real+268<-opimai+96<-BackgroundThreadStart+637<-0000000077D6B71A
----------------------------------------
SO: 000000047114E1A0, type: 4, owner: 000000047111DEF0, flag: INIT/-/-/0x00
(session) sid: 189 trans: 0000000000000000, creator: 000000047111DEF0, flag: (51) USR/- BSY/-/-/-/-/-
DID: 0001-001F-00000003, short-term DID: 0000-0000-00000000
txn branch: 0000000000000000
oct: 0, prv: 0, sql: 0000000000000000, psql: 0000000000000000, user: 0/SYS
service name: SYS$BACKGROUND
waiting for 'ASM background timer' wait_time=0, seconds since wait started=420165
=0, =0, =0
blocking sess=0x0000000000000000 seq=31
Dumping Session Wait History
for 'ASM background timer' count=1 wait_time=4.999949 sec
=0, =0, =0
for 'ASM background timer' count=1 wait_time=4.999893 sec
=0, =0, =0
for 'ASM background timer' count=1 wait_time=5.000022 sec
=0, =0, =0
for 'ASM background timer' count=1 wait_time=4.999948 sec
=0, =0, =0
for 'ASM background timer' count=1 wait_time=4.999924 sec
=0, =0, =0
for 'ASM background timer' count=1 wait_time=5.000012 sec
=0, =0, =0
for 'ASM background timer' count=1 wait_time=4.999948 sec
=0, =0, =0
for 'ASM background timer' count=1 wait_time=4.999858 sec
=0, =0, =0
for 'ASM background timer' count=1 wait_time=4.999991 sec
=0, =0, =0
for 'ASM background timer' count=1 wait_time=5.000000 sec
=0, =0, =0
Sampled Session History of session 189 serial 1
---------------------------------------------------
The sampled session history is constructed by sampling
the target session every 1 second. The sampling process
captures at each sample if the session is in a non-idle wait,
an idle wait, or not in a wait. If the session is in a
non-idle wait then one interval is shown for all the samples
the session was in the same non-idle wait. If the
session is in an idle wait or not in a wait for
consecutive samples then one interval is shown for all
the consecutive samples. Though we display these consecutive
samples in a single interval the session may NOT be continuously
idle or not in a wait (the sampling process does not know).
The history is displayed in reverse chronological order.
sample interval: 1 sec, max history 120 sec
---------------------------------------------------
[121 samples, 12:44:20 - 12:46:20]
idle wait at each sample
temporary object counter: 0
KTU Session Commit Cache Dump for IDLs:
KTU Session Commit Cache Dump for Non-IDLs:
----------------------------------------
UOL used : 0 locks(used=0, free=0)
KGX Atomic Operation Log 000000047AECC840
Mutex 0000000000000000(0, 0) idn 0 oper NONE
Cursor Pin uid 189 efd 3 whr 11 slp 0
KGX Atomic Operation Log 000000047AECC888
Mutex 0000000000000000(0, 0) idn 0 oper NONE
Library Cache uid 189 efd 0 whr 0 slp 0
KGX Atomic Operation Log 000000047AECC8D0
Mutex 0000000000000000(0, 0) idn 0 oper NONE
Library Cache uid 189 efd 0 whr 0 slp 0
----------------------------------------
SO: 000000045A233D80, type: 41, owner: 000000047114E1A0, flag: INIT/-/-/0x00
(dummy) nxc=0, nlb=0
----------------------------------------
SO: 0000000472172A40, type: 11, owner: 000000047111DEF0, flag: INIT/-/-/0x00
(broadcast handle) flag: (2) ACTIVE SUBSCRIBER, owner: 000000047111DEF0,
event: 31, last message event: 31,
last message waited event: 31, next message: 0000000476225BC8(0), messages read: 0
channel: (00000004711640E0) system events broadcast channel
scope: 2, event: 30690, last mesage event: 7413,
publishers/subscribers: 1/45,
messages published: 3
oldest msg (?): 0000000476225BB8 id: 1 pub: 000000047E11F768
heuristic msg queue length: 3
----------------------------------------
SO: 0000000472270FA0, type: 19, owner: 000000047111DEF0, flag: INIT/-/-/0x00
GES MSG BUFFERS: st=emp chunk=0x0000000000000000 hdr=0x0000000000000000 lnk=0x0000000000000000 flags=0x0 inc=0
outq=0 sndq=0 opid=0 prmb=0x0
mbg[i]=(0 0) mbg[b]=(0 0) mbg[r]=(0 0)
fmq[i]=(0 0) fmq[b]=(0 0) fmq[r]=(0 0)
mop[s]=0 mop[q]=0 pendq=0 zmbq=0
nonksxp_recvs=0
------------process 0x0000000472270FA0--------------------
proc version : 0
Local node : 0
pid : 4828
lkp_node : 0
svr_mode : 0
proc state : KJP_FROZEN
Last drm hb acked : 0
Total accesses : 3
Imm. accesses : 0
Locks on ASTQ : 0
Locks Pending AST : 0
Granted locks : 0
AST_Q:
PENDING_Q:
GRANTED_Q:
----------------------------------------
SO: 000000047E15DC20, type: 3, owner: 000000047111DEF0, flag: INIT/-/-/0x00
(call) sess: cur 7114e1a0, rec 0, usr 7114e1a0; depth: 0
----------------------------------------
SO: 000000045ED23770, type: 84, owner: 000000047E15DC20, flag: INIT/-/-/0x00
(kfgso) flags: 00000000 clt: 3 err: 0 hint: 0
(kfgpn) rpi: 1 itrn:0000000000000000 gst:0000000000000000 usrp:0000000000000000
busy: 0 rep: 0 grp: 5d60b840 check: 0/0 glink: 5d60b888 5d60b888
kfgrp: number: 0/0 type: 0 compat: 0.0.0.0.0 dbcompat:0.0.0.0.0
timestamp: 0 state: 0 flags: 2 gpnlist: 5ed237f0 5ed237f0
KFGPN at 5ed23770 in dependent chain
----------------------------------------
SO: 000000045AEEDD48, type: 16, owner: 000000047111DEF0, flag: INIT/-/-/0x00
(osp req holder)
PSO child state object changes :
Dump of memory from 0x0000000474167DC0 to 0x0000000474167FC8
474167DC0 00000005 00000000 5AEEDD48 00000004 [........H..Z....]
474167DD0 00000010 000313F4 7E15DC20 00000004 [........ ..~....]
474167DE0 00000003 000313F4 72270FA0 00000004 [..........'r....]
474167DF0 00000013 000312CB 72172A40 00000004 [........@*.r....]
474167E00 0000000B 000313F4 7114E1A0 00000004 [...........q....]
474167E10 00000004 000312CB 00000000 00000000 [................]
474167E20 00000000 00000000 00000000 00000000 [................]
Repeat 25 times
474167FC0 00000000 00000000 [........]
*** 2012-07-25 12:46:37.393
*** CLIENT ID:() 2012-07-25 12:46:37.393
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1
WARNING:Could not lower the asynch I/O limit to 320 for SQL direct I/O. It is set to -1
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1
WARNING:Could not lower the asynch I/O limit to 288 for SQL direct I/O. It is set to -1
WARNING:Could not lower the asynch I/O limit to 224 for SQL direct I/O. It is set to -1
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1
WARNING:Could not lower the asynch I/O limit to 192 for SQL direct I/O. It is set to -1
WARNING:Could not lower the asynch I/O limit to 160 for SQL direct I/O. It is set to -1
*** 2012-07-25 12:47:20.314
*** CLIENT ID:() 2012-07-25 12:47:20.314
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1
难道问题是：
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1 WARNING:Could not lower the asynch I/O limit to 320 for SQL direct I/O. It is set to -1 WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1 WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1 WARNING:Could not lower the asynch I/O limit to 288 for SQL direct I/O. It is set to -1 WARNING:Could not lower the asynch I/O limit to 224 for SQL direct I/O. It is set to -1 WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1 WARNING:Could not lower the asynch I/O limit to 192 for SQL direct I/O. It is set to -1 WARNING:Could not lower the asynch I/O limit to 160 for SQL direct I/O. It is set to -1
导致的，这些WARNING又说明什么呢？
.png)
.png)
