Oracle ASM异常dismount磁盘组

朋友反馈他们单位Oracle RAC中的一个节点异常关闭了,操作环境是IBM小机720,EMC存储,Oracle是11.2.0.4。收集了一些信息给我,查看该节点实例的alert.log文件发现了如下信息:

Thu Mar 31 14:29:18 2016
NOTE:Waiting for all pending writes to complete before de-registering: grpnum 3
Thu Mar 31 14:29:20 2016
WARNING: group 3 dismounted: failed to write virtual extent 263 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 263 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 265 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 265 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 265 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 265 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 265 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 265 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 265 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 265 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 260 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 260 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 246 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 246 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 246 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 246 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 246 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 246 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 246 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 246 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 260 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 260 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 260 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 260 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 260 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 260 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 261 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 261 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 261 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 261 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 261 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 261 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 261 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 261 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 244 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 244 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 244 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 244 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 257 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 257 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 244 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 244 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 257 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 257 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 244 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 257 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 244 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 257 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 257 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 257 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 259 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 259 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 259 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 259 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 259 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 259 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 259 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 259 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 254 of file 264 
WARNING: group 3 dismounted: failed to write virtual extent 254 of file 264 
Thu Mar 31 14:29:21 2016
WARNING: requested mirror side 1 of virtual extent 0 logical extent 0 offset 16384 is not allocated; I/O request failed
WARNING: requested mirror side 2 of virtual extent 0 logical extent 1 offset 16384 is not allocated; I/O request failed
WARNING: requested mirror side 3 of virtual extent 0 logical extent 2 offset 16384 is not allocated; I/O request failed
Errors in file /opt/app/oracle/diag/rdbms/jtpsoft/jtpsoft1/trace/jtpsoft1_arc1_10551306.trc:
ORA-00202: control file: '+GJJ_DG/jtpsoft/controlfile/current.260.841581789'
ORA-15079: ASM file is closed
ORA-15079: ASM file is closed
ORA-15079: ASM file is closed
System state dump requested by (instance=1, osid=15007960 (CKPT)), summary=[abnormal instance termination].
System State dumped to trace file /opt/app/oracle/diag/rdbms/jtpsoft/jtpsoft1/trace/jtpsoft1_diag_4784254_20160331142927.trc
Thu Mar 31 14:29:28 2016
ORA-1092 : opitsk aborting process
Thu Mar 31 14:29:34 2016
ORA-1092 : opitsk aborting process
Thu Mar 31 14:29:34 2016
License high water mark = 181
Thu Mar 31 14:29:37 2016
Instance terminated by CKPT, pid = 15007960
USER (ospid: 15073490): terminating the instance
Instance terminated by USER, pid = 15073490

从上面信息可以看到磁盘组3(也就是磁盘组+GJJ_DG)已经dismounted了并且ckpt进程终止了实例。如是查看跟踪文件/opt/app/oracle/diag/rdbms/jtpsoft/jtpsoft1/trace/jtpsoft1_arc1_10551306.trc,可以看到如下内容:

Trace file /opt/app/oracle/diag/rdbms/jtpsoft/jtpsoft1/trace/jtpsoft1_arc1_10551306.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
ORACLE_HOME = /opt/app/oracle/product/11.2.0/db_1
System name:	AIX
Node name:	p720a
Release:	1
Version:	6
Machine:	00C855104C00
Instance name: jtpsoft1
Redo thread mounted by this instance: 1
Oracle process number: 41
Unix process pid: 10551306, image: oracle@p720a (ARC1)


*** 2016-03-31 14:29:21.527
*** SESSION ID:(641.1) 2016-03-31 14:29:21.527
*** CLIENT ID:() 2016-03-31 14:29:21.527
*** SERVICE NAME:(SYS$BACKGROUND) 2016-03-31 14:29:21.527
*** MODULE NAME:() 2016-03-31 14:29:21.527
*** ACTION NAME:() 2016-03-31 14:29:21.527
 

*** TRACE FILE RECREATED AFTER BEING REMOVED ***

WARNING:failed xlate 2 
WARNING: requested mirror side 1 of virtual extent 0 logical extent 0 offset 16384 is not allocated; I/O request failed
WARNING:failed xlate 2 
WARNING: requested mirror side 2 of virtual extent 0 logical extent 1 offset 16384 is not allocated; I/O request failed
WARNING:failed xlate 2 
WARNING: requested mirror side 3 of virtual extent 0 logical extent 2 offset 16384 is not allocated; I/O request failed
DDE rules only execution for: ORA 202
----- START Event Driven Actions Dump ----
---- END Event Driven Actions Dump ----
----- START DDE Actions Dump -----
Executing SYNC actions
----- START DDE Action: 'DB_STRUCTURE_INTEGRITY_CHECK' (Async) -----
Successfully dispatched
----- END DDE Action: 'DB_STRUCTURE_INTEGRITY_CHECK' (SUCCESS, 0 csec) -----
Executing ASYNC actions
----- END DDE Actions Dump (total 0 csec) -----

*** 2016-03-31 14:29:21.533
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=1, mask=0x0)
----- Error Stack Dump -----
ORA-00202: control file: '+GJJ_DG/jtpsoft/controlfile/current.260.841581789'
ORA-15079: ASM file is closed
ORA-15079: ASM file is closed
ORA-15079: ASM file is closed
----- SQL Statement (None) -----
Current SQL information unavailable - no cursor.

----- Call Stack Trace -----
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
skdstdst()+40        bl       0000000109B3BDC0     FFFFFFFFFFF6D60 ? 000000001 ?
                                                   000000001 ? 000000000 ?
                                                   000000000 ? 000000001 ?
                                                   000000001 ? 000000000 ?
ksedst1()+112        call     skdstdst()           FFFFFFFFFFF6E38 ? 000002004 ?
                                                   110720F48 ? 10A6D6A74 ?
                                                   10A6D5F50 ? FFFFFFFFFFF7190 ?
                                                   FFFFFFFFFFF6F40 ?
                                                   2050033FFFF6E18 ?
ksedst()+40          call     ksedst1()            10A6D6A68 ? 7000000000291 ?
                                                   10A6D6A3C ? B000000000000 ?
                                                   10A6D5F50 ? 000000000 ?
                                                   400000000 ? 1D25C0C474A0C ?
dbkedDefDump()+1516  call     ksedst()             000000001 ? FFFFFFFFFFF72F0 ?
                                                   000000001 ? 000000000 ?
                                                   000000003 ? 00001ED50 ?
                                                   000000000 ? 000000000 ?
ksedmp()+72          call     dbkedDefDump()       1A006FE88 ? 9001000A0000E00 ?
                                                   FFFFFFFFFFF7CD0 ? 004C3009B ?
                                                   000000000 ? 000000001 ?
                                                   000000001 ? 0000000CC ?
kcccsi()+416         call     ksedmp()             CA000000CA ? 000000001 ?
                                                   000000031 ? 7000104BCDE1D56 ?
                                                   000000000 ? 7000104C8CC4478 ?
                                                   000000006 ? 000000030 ?
kccrhd()+1488        call     kcccsi()             000000020 ? 000000000 ?
                                                   110738B50 ? 10A344FE0 ?
                                                   FFFFFFFFFFF7FA0 ? 004C3009B ?
                                                   102D0B800 ? 11298BF30 ?
kccgft_refresh_hdr(  call     kccrhd()             FFFFFFFFFFF8100 ? 004C3009B ?
)+124                                              11297B0B0 ? FFFFFFFFFFFA5E0 ?
                                                   6B736C636D617266 ?
                                                   112939850 ? 10A38F248 ?
                                                   10A38F258 ?
kcc_noenq_refresh()  call     kccgft_refresh_hdr(  110E9DA20 ? 000000004 ?
+40                           )                    000000018 ? 11012D7C8 ?
                                                   000000021 ? 00000374E ?
                                                   000000001 ? FFFFFFFFFFF81F0 ?
kccocx_noenq()+292   call     kcc_noenq_refresh()  20B6CECD0 ? 000000102 ?
                                                   000000000 ? 000000000 ?
                                                   FFFFFFFFFFF8070 ?
                                                   44244288000537D0 ?
                                                   9000000000051AC ?
                                                   FFFFFFFFFFF8030 ?
...省略...

上面的内容也就是不能对磁盘组执行IO操作,并没有得到更有用的信息。如是查看asm的alert.log文件,可以看到如下信息:

Thu Mar 31 14:29:18 2016
WARNING: Waited 15 secs for write IO to PST disk 0 in group 3.
WARNING: Waited 15 secs for write IO to PST disk 1 in group 3.
WARNING: Waited 15 secs for write IO to PST disk 2 in group 3.
WARNING: Waited 15 secs for write IO to PST disk 0 in group 3.
WARNING: Waited 15 secs for write IO to PST disk 1 in group 3.
WARNING: Waited 15 secs for write IO to PST disk 2 in group 3.
Thu Mar 31 14:29:18 2016
NOTE: process _b000_+asm1 (22544528) initiating offline of disk 0.3043853018 (GJJ_DG_0000) with mask 0x7e in group 3
NOTE: process _b000_+asm1 (22544528) initiating offline of disk 1.3043853019 (GJJ_DG_0001) with mask 0x7e in group 3
NOTE: process _b000_+asm1 (22544528) initiating offline of disk 2.3043853020 (GJJ_DG_0002) with mask 0x7e in group 3
NOTE: checking PST: grp = 3
GMON checking disk modes for group 3 at 10 for pid 30, osid 22544528
ERROR: no read quorum in group: required 2, found 0 disks
NOTE: checking PST for grp 3 done.
NOTE: initiating PST update: grp = 3, dsk = 0/0xb56d82da, mask = 0x6a, op = clear
NOTE: initiating PST update: grp = 3, dsk = 1/0xb56d82db, mask = 0x6a, op = clear
NOTE: initiating PST update: grp = 3, dsk = 2/0xb56d82dc, mask = 0x6a, op = clear
GMON updating disk modes for group 3 at 11 for pid 30, osid 22544528
ERROR: no read quorum in group: required 2, found 0 disks
Thu Mar 31 14:29:18 2016
NOTE: cache dismounting (not clean) group 3/0x46ED7239 (GJJ_DG) 
NOTE: messaging CKPT to quiesce pins Unix process pid: 30277648, image: oracle@p720a (B001)
Thu Mar 31 14:29:18 2016
NOTE: halting all I/Os to diskgroup 3 (GJJ_DG)
Thu Mar 31 14:29:18 2016
NOTE: LGWR doing non-clean dismount of group 3 (GJJ_DG)
NOTE: LGWR sync ABA=22.4306 last written ABA 22.4306
WARNING: Offline for disk GJJ_DG_0000 in mode 0x7f failed.
WARNING: Offline for disk GJJ_DG_0001 in mode 0x7f failed.
WARNING: Offline for disk GJJ_DG_0002 in mode 0x7f failed.
Thu Mar 31 14:29:18 2016
kjbdomdet send to inst 2
detach from dom 3, sending detach message to inst 2
Thu Mar 31 14:29:18 2016
List of instances:
 1 2
Dirty detach reconfiguration started (new ddet inc 1, cluster inc 20)
 Global Resource Directory partially frozen for dirty detach
* dirty detach - domain 3 invalid = TRUE 
 305 GCS resources traversed, 0 cancelled
Thu Mar 31 14:29:18 2016
ERROR: ORA-15130 in COD recovery for diskgroup 3/0x46ed7239 (GJJ_DG)
ERROR: ORA-15130 thrown in RBAL for group number 3
Dirty Detach Reconfiguration complete
Errors in file /opt/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_rbal_12386526.trc:
ORA-15130: diskgroup "GJJ_DG" is being dismounted
Thu Mar 31 14:29:18 2016
WARNING: dirty detached from domain 3
NOTE: cache dismounted group 3/0x46ED7239 (GJJ_DG) 
NOTE: cache deleting context for group GJJ_DG 3/0x46ed7239
SQL> alter diskgroup GJJ_DG dismount force /* ASM SERVER:1189966393 */ 
Thu Mar 31 14:29:18 2016
NOTE: No asm libraries found in the system
ERROR: ORA-15130 in COD recovery for diskgroup 3/0x46ed7239 (GJJ_DG)
ERROR: ORA-15130 thrown in RBAL for group number 3
Errors in file /opt/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_rbal_12386526.trc:
ORA-15130: diskgroup "" is being dismounted
ERROR: ORA-15130 in COD recovery for diskgroup 3/0x46ed7239 (GJJ_DG)
ERROR: ORA-15130 thrown in RBAL for group number 3
Errors in file /opt/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_rbal_12386526.trc:
ORA-15130: diskgroup "" is being dismounted
ERROR: ORA-15130 in COD recovery for diskgroup 3/0x46ed7239 (GJJ_DG)
ERROR: ORA-15130 thrown in RBAL for group number 3
Errors in file /opt/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_rbal_12386526.trc:
ORA-15130: diskgroup "" is being dismounted
Thu Mar 31 14:29:27 2016
NOTE: ASM client jtpsoft1:jtpsoft disconnected unexpectedly.
NOTE: check client alert log.
NOTE: Trace records dumped in trace file /opt/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_ora_14024932.trc
ASM Health Checker found 1 new failures
Thu Mar 31 14:29:30 2016
ERROR: ORA-15130 in COD recovery for diskgroup 3/0x46ed7239 (GJJ_DG)
ERROR: ORA-15130 thrown in RBAL for group number 3
Errors in file /opt/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_rbal_12386526.trc:
ORA-15130: diskgroup "" is being dismounted
ERROR: ORA-15130 in COD recovery for diskgroup 3/0x46ed7239 (GJJ_DG)
ERROR: ORA-15130 thrown in RBAL for group number 3
Errors in file /opt/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_rbal_12386526.trc:
ORA-15130: diskgroup "" is being dismounted
ERROR: ORA-15130 in COD recovery for diskgroup 3/0x46ed7239 (GJJ_DG)
ERROR: ORA-15130 thrown in RBAL for group number 3
Errors in file /opt/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_rbal_12386526.trc:
ORA-15130: diskgroup "" is being dismounted
Thu Mar 31 14:29:37 2016
GMON dismounting group 3 at 12 for pid 31, osid 30277648
Thu Mar 31 14:29:37 2016
NOTE: Disk GJJ_DG_0000 in mode 0x7f marked for de-assignment
NOTE: Disk GJJ_DG_0001 in mode 0x7f marked for de-assignment
NOTE: Disk GJJ_DG_0002 in mode 0x7f marked for de-assignment
SUCCESS: diskgroup GJJ_DG was dismounted
SUCCESS: alter diskgroup GJJ_DG dismount force /* ASM SERVER:1189966393 */
SUCCESS: ASM-initiated MANDATORY DISMOUNT of group GJJ_DG
Thu Mar 31 14:29:37 2016
NOTE: diskgroup resource ora.GJJ_DG.dg is offline
Thu Mar 31 14:29:44 2016
Errors in file /opt/app/grid/diag/asm/+asm/+ASM1/trace/+ASM1_ora_15073504.trc:
ORA-17503: ksfdopn:2 Failed to open file +GJJ_DG/jtpsoft/spfilejtpsoft.ora
ORA-15001: diskgroup "GJJ_DG" does not exist or is not mounted
ASMCMD> lsdg
State    Type    Rebal  Sector  Block       AU  Total_MB  Free_MB  Req_mir_free_MB  Usable_file_MB  Offline_disks  Voting_files  Name
MOUNTED  NORMAL  N         512   4096  1048576    614400   606078           204800          200639              0             N  BACK_DG/
MOUNTED  NORMAL  N         512   4096  1048576     10240     9310             2048            3631              0             Y  CRS_DG/
MOUNTED  NORMAL  N         512   4096  1048576   1228800   858311           409600          224355              0             N  GJJ_DG/

从上面的信息’Thu Mar 31 14:29:18 2016’与’WARNING: Waited 15 secs for write IO to PST disk 1 in group 3’可知在2016-03-31 14:29:18这个时间点,由于对ASM正常或高冗余磁盘所执行的ASM PST心跳检测出现了延迟,而且延迟时间超过了15秒,因此ASM实例dismount了ASM磁盘组。这种心跳方式会忽略对外部冗余磁盘组的检测,在ASM PST重新验证之前ASM实例会停止执行更多的PST心跳检测,但PST心跳延迟不会dismount外部冗余磁盘组。可能出现这种情况有以下几种原因:
1.由于多路径设备的某些物理路径脱机或丢失
2.多路径执行路径故障转移
3.服务器负载或存储/多路径/操作系统的维护,但这种情况可以排除因为负载不高,也没进行任何维护操作。

那么在出现这种情况时,可以通过以下几种方式来解决:
1.检查操作系统和存储对磁盘管理的响应时间
2.尽可能把磁盘的响应时间维持在15秒以下,但这将处于了操作系统,多路径软件与内核参数等多种因素,需要一一排查。
3.如果不能保证磁盘的响应时间维持在15秒以下,那么可以对ASM实例设置隐含参数_asm_hbetaiowait,对于这个参值数如果遇到bug 17274537可以设置120,并且这个bug在12.1.0.2中被修复了。

Thu Mar 31 14:30:05 2016
SQL> ALTER DISKGROUP GJJ_DG MOUNT  /* asm agent *//* {0:23:23972} */ 
NOTE: cache registered group GJJ_DG number=3 incarn=0x46ed72a8
NOTE: cache began mount (not first) of group GJJ_DG number=3 incarn=0x46ed72a8
NOTE: Assigning number (3,0) to disk (/dev/rhdiskpower5)
NOTE: Assigning number (3,1) to disk (/dev/rhdiskpower6)
NOTE: Assigning number (3,2) to disk (/dev/rhdiskpower7)
Thu Mar 31 14:30:05 2016
GMON querying group 3 at 14 for pid 27, osid 29163580
NOTE: cache opening disk 0 of grp 3: GJJ_DG_0000 path:/dev/rhdiskpower5
NOTE: F1X0 found on disk 0 au 2 fcn 0.0
NOTE: cache opening disk 1 of grp 3: GJJ_DG_0001 path:/dev/rhdiskpower6
NOTE: F1X0 found on disk 1 au 2 fcn 0.0
NOTE: cache opening disk 2 of grp 3: GJJ_DG_0002 path:/dev/rhdiskpower7
NOTE: F1X0 found on disk 2 au 2 fcn 0.0
NOTE: cache mounting (not first) normal redundancy group 3/0x46ED72A8 (GJJ_DG)
Thu Mar 31 14:30:05 2016
kjbdomatt send to inst 2
Thu Mar 31 14:30:05 2016
NOTE: attached to recovery domain 3
NOTE: redo buffer size is 256 blocks (1053184 bytes)
Thu Mar 31 14:30:05 2016
NOTE: LGWR attempting to mount thread 2 for diskgroup 3 (GJJ_DG)
NOTE: LGWR found thread 2 closed at ABA 22.4306
NOTE: LGWR mounted thread 2 for diskgroup 3 (GJJ_DG)
NOTE: LGWR opening thread 2 at fcn 0.383934 ABA 23.4307
NOTE: cache mounting group 3/0x46ED72A8 (GJJ_DG) succeeded
NOTE: cache ending mount (success) of group GJJ_DG number=3 incarn=0x46ed72a8
Thu Mar 31 14:30:05 2016
NOTE: Instance updated compatible.asm to 11.2.0.0.0 for grp 3
SUCCESS: diskgroup GJJ_DG was mounted
SUCCESS: ALTER DISKGROUP GJJ_DG MOUNT  /* asm agent *//* {0:23:23972} */

从上面的信息可以看到在 2016-03-31 14:30:05这个时间点asm_agent在执行mount磁盘组(GJJ_DG),在14:29:18 dismount磁盘组到14:30:05 mount磁盘之间的时间间隔是47秒。所以等我检查时ASM磁盘组(GJJ_DG)已经mount成功了,于是只能让客户去检查操作系统,多路径软件和光纤。

发表评论

电子邮件地址不会被公开。