遇到ORA-03113: end-of-file on communication channel

打开数据库的时候报ORA-03113。

关于ORA-03113，ORACLE官方文档是这样描述的：

ORA-03113: end-of-file on communication channel

Cause: The connection between Client and Server process was broken.

Action: There was a communication error that requires further investigation. First, check for network problems and review the SQL*Net setup. Also, look in the alert.log file for any errors. Finally, test to see whether the server process is dead and whether a trace file was generated at failure time.

并没有明确的解决方法。

查看日志文件：

Wed May 13 21:22:55 2009

Errors in file /u01/admin/YSP/bdump/ysp_lgwr_2920.trc:

ORA-00322: log 1 of thread 1 is not current copy

ORA-00312: online log 1 thread 1: '/u01/oradata/YSP/redo01B.log'

关于ORA-00322，ORACLE官方是这样描述的：

ORA-00322: log string of thread string is not current copy

Cause: Check of log file header at database open found that an online log appears to be an incorrectly restored backup.

Action: Restore correct file or reset logs.

此时重建日志文件将会报错。

SQL> ALTER DATABASE CLEAR LOGFILE GROUP 1;

ALTER DATABASE CLEAR LOGFILE GROUP 1

*

ERROR at line 1:

ORA-00350: log 1 of instance YSP (thread 1) needs to be archived

ORA-00312: online log 1 thread 1: '/u01/oradata/YSP/redo01.log'

ORA-00312: online log 1 thread 1: '/u01/oradata/YSP/redo01B.log'

SQL> ALTER DATABASE CLEAR UNARCHIVED LOGFILE GROUP 1;

ALTER DATABASE CLEAR UNARCHIVED LOGFILE GROUP 1

*

ERROR at line 1:

ORA-00322: log 1 of thread 1 is not current copy

ORA-00312: online log 1 thread 1: '/u01/oradata/YSP/redo01B.log'

ORA-00322: log 1 of thread 1 is not current copy

ORA-00312: online log 1 thread 1: '/u01/oradata/YSP/redo01.log'

SQL> SELECT * FROM V$LOGFILE;

rows will be truncated

GROUP# STATUS  TYPE    MEMBER

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

1         ONLINE  /u01/oradata/YSP/redo01.log

3         ONLINE  /u01/oradata/YSP/redo03.log

2         ONLINE  /u01/oradata/YSP/redo02.log

1         ONLINE  /u01/oradata/YSP/redo01B.log

2         ONLINE  /u01/oradata/YSP/redo02B.log

3         ONLINE  /u01/oradata/YSP/redo03B.log

6 rows selected.

SQL> SELECT * FROM V$LOG;

truncating (as requested) before column FIRST_CHANGE#

GROUP#    THREAD#  SEQUENCE#      BYTES    MEMBERS ARC STATUS           FIRS

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

1          1          0   15728640          2 NO  CLEARING_CURRENT 13-M

3          1         13   15728640          2 YES INACTIVE         13-M

2          1          0   15728640          2 YES UNUSED           13-M

由于数据处于MOUNT状态，因此日志切换不行。

SQL> ALTER SYSTEM SWITCH LOGFILE;

ALTER SYSTEM SWITCH LOGFILE

*

ERROR at line 1:

ORA-01109: database not open

测试打开数据库就会报ORA-03113

SQL> ALTER DATABASE OPEN;

ALTER DATABASE OPEN

*

ERROR at line 1:

ORA-03113: end-of-file on communication channel

而且数据库INSTANCE将会意外终止。

此时可以用基于CANCEL的不完全恢复。

SQL> CONN / AS SYSDBA

Connected to an idle instance.

SQL> STARTUP MOUNT;

ORACLE instance started.

Total System Global Area  167772160 bytes

Fixed Size                  1218316 bytes

Variable Size              79694068 bytes

Database Buffers           83886080 bytes

Redo Buffers                2973696 bytes

Database mounted.

SQL> select * from v$log;

truncating (as requested) before column FIRST_CHANGE#

GROUP#    THREAD#  SEQUENCE#      BYTES    MEMBERS ARC STATUS           FIRS

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

1          1          0   15728640          2 NO  CLEARING_CURRENT 13-M

3          1         13   15728640          2 YES INACTIVE         13-M

2          1          0   15728640          2 YES UNUSED           13-M

SQL> recover database until cancel;

Media recovery complete.

SQL> select * from v$log;

truncating (as requested) before column FIRST_CHANGE#

GROUP#    THREAD#  SEQUENCE#      BYTES    MEMBERS ARC STATUS           FIRS

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

1          1          0   15728640          2 NO  CLEARING_CURRENT 13-M

3          1         13   15728640          2 YES INACTIVE         13-M

2          1          0   15728640          2 YES UNUSED           13-M

SQL> alter database open resetlogs;

Database altered.

最近装了两套AIX平台的11.2.0.3的数据库，在最后使用dbca图形化工具创建数据库的时候都遇到了同样的错误：ORA-03113: end-of-file on communication channel，真的是非常讨论在AIX平台安装Oracle RAC，问题太多，不过话说回来，问题多成长才快嘛，下面把整个过程记录下来。

使用DBCA工具将数据库创建在存储设备对应的ASM磁盘组时遇到了ORA-03113错误。之后回想起之前将数据库创建在本地文件系统时非常的顺利，于是尝试先将数据库创建在本地文件系统，然后利用RMAN工具将所有文件转存到ASM磁盘组中。

# id grid

uid=205(grid) gid=204(oinstall) groups=205(asmadmin),206(asmdba),207(asmoper),208(dba)

# id oracle

uid=206(oracle) gid=204(oinstall) groups=206(asmdba),208(dba),209(oper)

# oslevel -s

6100-07-05-1228

数据库成功创建到本地之后，首先做了以下的尝试：

#su - oracle

$ sqlplus / as sysdba

SQL*Plus: Release 11.2.0.3.0 Production on Mon Sep 10 19:37:38 2012

Copyright (c) 1982, 2011, Oracle.  All rights reserved.

Connected to:

Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production

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

SQL> create tablespace test datafile '+DATA01' size 5m ;

create tablespace test datafile '+DATA01' size 5m

*

ERROR at line 1:

ORA-03113: end-of-file on communication channel

Process ID: 45023418

Session ID: 131 Serial number: 293

通过上面这里例子很明显的感觉到oracle用户没有向ASM磁盘组写数据的权限。通过这两次的安装我个人认为dbca执行过程中出现ORA-03113错误很大可能是因为oracle用户下的数据库实例没有向grid用户下的磁盘组写数据的权限。

这时检查Oracle数据库的告警日志，可以明显看到有ORA-600的错误报出：ORA-00600 [kfioTranslateIO03]，根据这个错误在METALINK很容易到了下面这篇文章：

ORA-00600 [kfioTranslateIO03] [17090] [ID 1336846.1]

修改时间:2012-3-23

类型:PROBLEM

状态:PUBLISHED

优先级:3 

Applies to:

Oracle Server - Enterprise Edition - Version: 11.2.0.2 and later   [Release: 11.2 and later ]

Information in this document applies to any platform.

Symptoms

In 11.2.0.2 where role separation between GRID and RDBMS is implemented, the following ORA-600 error prevents database from starting up.

ORA-00600: internal error code, arguments: [kfioTranslateIO03]

ORA-00600: internal error code, arguments: [17090]

Cause

group permission of "oracle" executable from RDBMS home should have the same group information for ASM devices according to note 1084186.1.

$ ls -l $GRID_HOME/bin/oracle

-rwsr-s--x 1 grid oinstall 228954465 Jul 1 13:37 /oh1/grid/product/11.2.0/bin/oracle

$ ls -l $RDBMS_HOME/bin/oracle

-rwsr-s--x 1 oracle asmadmin 228954465 Jul 1 13:37 /oh1/oracle/product/11.2.0/bin/oracle

$ ls -l $ASM_DEVICE/*

brw-rw---- 1 grid asmadmin 8, 33 Feb 15 08:11 /dev/oracleasm/disks/ASMD1

brw-rw---- 1 grid asmadmin 8, 49 Feb 15 08:11 /dev/oracleasm/disks/ASMD2

brw-rw---- 1 grid asmadmin 8, 17 May 4 22:30 /dev/oracleasm/disks/CRSD1

But in this case, "oracle" executable from RDBMS shows different group information which is different from group information for ASM devices.

ORA-600[kfioTranslateIO03] and [17090] occurrs due to the permission issue.

$ ls -l $RDBMS_HOME/bin/oracle

-rwsr-s--x 1 oracle oinstall 228954465 Jul 1 13:37 /oh1/oracle/product/11.2.0/bin/oracle

^^^^^^^ it should be "asmadmin" or at least should be the same group of all ASM devices.

Solution

group information for $RDBMS_HOME/bin/oracle should be changed to the group that can read/write to ASM devices.

Please execute the following action plan from note 1084186.1.

$ su - grid

$ cd /bin

$ ./setasmgidwrap o=<11.2 RDBMS Home>/bin/oracle

References

NOTE:1084186.1 - Database Creation on 11.2 Grid Infracture with Role Separation ( ORA-15025, KFSG-00312, ORA-15081 )

根据上面的文章内容做了如下操作：

$ cd $GRID_HOME/bin

$ ls -al oracle

-rwsr-s--x    1 grid     oinstall  264678476 Sep 10 18:58 oracle

$ exit

# cd /dev/

# ls -al rhdisk*

crw-rw----    2 grid     oinstall     15,  0 Jul 19 12:22 rhdisk0

crw-rw----    1 grid     oinstall     15,  1 Jul 19 12:22 rhdisk1

crw-rw----    1 grid     oinstall     15, 16 Sep 10 18:40 rhdisk10

crw-rw----    1 grid     oinstall     15, 10 Sep 10 18:40 rhdisk11

crw-rw----    1 grid     oinstall     15, 14 Sep 10 18:40 rhdisk12

crw-rw----    1 grid     oinstall     15,  7 Sep 10 18:40 rhdisk13

......

# chown -R grid:asmadmin rhdisk*

# ls -al rhdisk*

crw-rw----    2 grid     asmadmin     15,  0 Jul 19 12:22 rhdisk0

crw-rw----    1 grid     asmadmin     15,  1 Jul 19 12:22 rhdisk1

crw-rw----    1 grid     asmadmin     15, 16 Sep 10 18:40 rhdisk10

crw-rw----    1 grid     asmadmin     15, 10 Sep 10 18:40 rhdisk11

crw-rw----    1 grid     asmadmin     15, 14 Sep 10 18:40 rhdisk12

crw-rw----    1 grid     asmadmin     15,  7 Sep 10 18:40 rhdisk13

......

# su - grid

$ cd $GRID_HOME/dbs

$ cd ../bin

$ ls -al oracle

-rwsr-s--x    1 grid     oinstall  264678476 Sep 10 18:58 oracle

$ pwd

/u01/app/11.2.0/grid/bin

$ ./setasmgidwrap o=/u01/app/oracle/product/11.2.0/db_1/bin/oracle

$ exit

# su - oracle

$ cd $ORACLE_HOME/bin

$ ls -al oracle

-rwsr-s--x    1 oracle   asmadmin  300832186 Sep 10 19:17 oracle

通过以上的调整之后，GRID_HOME/bin/oracle和$RDBMS_HOME/bin/oracle两个程序都具备了对/dev/rhdisk*的读写权限，这是出现ORA-03113问题的根源。

$ sql

SQL*Plus: Release 11.2.0.3.0 Production on Mon Sep 10 19:57:07 2012

Copyright (c) 1982, 2011, Oracle.  All rights reserved.

Connected to:

Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production

With the Partitioning, Automatic Storage Management, OLAP, Data Mining

and Real Application Testing options

SQL> create tablespace test datafile '+DATA01' size 5m;

create tablespace test datafile '+DATA01' size 5m

*

ERROR at line 1:

ORA-03113: end-of-file on communication channel

Process ID: 25690140

Session ID: 212 Serial number: 23

$ sqlplus / as sysdba

SQL*Plus: Release 11.2.0.3.0 Production on Mon Sep 10 19:59:52 2012

Copyright (c) 1982, 2011, Oracle.  All rights reserved.

Connected to:

Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production

With the Partitioning, Automatic Storage Management, OLAP, Data Mining

and Real Application Testing options

SQL> shutdown immediate

Database closed.

Database dismounted.

ORACLE instance shut down.

SQL> startup

ORACLE instance started.

Total System Global Area 9887760384 bytes

Fixed Size                  2229944 bytes

Variable Size            1577060680 bytes

Database Buffers         8287944704 bytes

Redo Buffers               20525056 bytes

Database mounted.

Database opened.

SQL> create tablespace test datafile '+DATA01' size 5m;

Tablespace created.

SQL> drop tablespace test including contents and datafiles;

Tablespace dropped.

实例经过重启，之前所做的更改才会生效。

通过这个例子，可以总结出试图将数据库存放到Grid软件下的ASM磁盘组的时候一定要注意以下两点：

1).按照Oracle文档的要求，对共享磁盘执行以下两个修改：

chown grid:asmadmin /dev/rhdisk*

chmod 660 /dev/rhdisk*

2).确保$GRID_HOME/bin/oracle和$RDBMS_HOME/bin/oracle的两个程序都具备读写共享磁盘文件/dev/rhdisk*的权限。

相信部署满足了以上两个条件的Oracle数据库不再会出现ORA-03113的错误。

相关文章：《Oracle RAC 11gR2 ORA-15055 ORA-27140 ORA-27300 ORA-27301 ORA-27302 ORA-27303》http://space.itpub.net/?uid-23135684-action-viewspace-itemid-751960，文章重点讨论的是$GRID_HOME/bin/oracle和$ORACLE_HOME/bin/oracle两个文件的权限和/dev/rhdisk*的对应关系；而这篇文章重点讨论的是$GRID_HOME/bin/oracle和$ORACLE_HOME/bin/oracle两个文件的所有者、组和/dev/rhdisk*的对应关系。

【案例】Oracle报错ORA-03113 ORA-15064产生原因和解决办法

时间:2016-12-11 18:47   来源:Oracle研究中心   作者:网络   点击:

次

天萃荷净

Oracle研究中心案例分析：运维DBA反映Oracle RAC数据库报错ORA-03113 ORA-15064，分析原因为数据库实例的asmb进程crash，然后导致数据库实例crash，进而被crs给重启了。

本站文章除注明转载外，均为本站原创： 转载自love wife & love life —Roger 的Oracle技术博客

本文链接地址: 10gR2 rac(asm) crash with ora-15064

以前同事发过来一个rac log，让帮忙分析一下，该问题2011年我也看过，当时没有详细分析，这次我们再来看看，能否找到根本的原因，首先我们来看database的alert log：

Mon Sep 17 09:59:37 2012

Thread 1 advanced to log sequence 8631

Current log# 1 seq# 8631 mem# 0: +DG_DATA/cmsdb3/onlinelog/redo01_1.log

Current log# 1 seq# 8631 mem# 1: +DG_DATA/cmsdb3/onlinelog/redo01_2.log

Mon Sep 17 10:35:00 2012

Errors in file /oracle/admin/cmsdb3/bdump/cmsdb31_asmb_1155.trc:

ORA-15064: communication failure with ASM instance

ORA-03113: end-of-file on communication channel

Mon Sep 17 10:35:00 2012

ASMB: terminating instance due to error 15064

Mon Sep 17 10:35:00 2012

System state dump is made for local instance

System State dumped to trace file /oracle/admin/cmsdb3/bdump/cmsdb31_diag_639.trc

Mon Sep 17 10:35:02 2012

Shutting down instance (abort)

License high water mark = 177

Mon Sep 17 10:35:05 2012

Instance terminated by ASMB, pid = 1155

Mon Sep 17 10:35:07 2012

Instance terminated by USER, pid = 106

Mon Sep 17 10:35:16 2012

Starting ORACLE instance (normal)

LICENSE_MAX_SESSION = 0

LICENSE_SESSIONS_WARNING = 0

Interface type 1 ce1 192.168.0.0 configured from OCR for use as a cluster interconnect

Interface type 1 ce0 172.16.0.0 configured from OCR for use as  a public interface

Picked latch-free SCN scheme 3

WARNING: db_recovery_file_dest is same as db_create_file_dest

Autotune of undo retention is turned on.

LICENSE_MAX_USERS = 0

SYS auditing is disabled

ksdpec: called for event 13740 prior to event group initialization

Starting up ORACLE RDBMS Version: 10.2.0.3.0.

System parameters with non-default values:

processes                = 723

sessions                 = 800

从上面错误可以清楚的看到，在时间点Mon Sep 17 10:35:00 2012 出现故障，数据Oracleо库实例的asmb进程出现故障，导致数据库实例无法跟asm进行交互。

这里补充一下，数据库实例和asm实例都存在asmb进程，我猜测应该是数据库实例的asmb进程和asm实例的asmb进程进行交互，只要其中一个asmb进程出现故障，那么可能都会导致数据库crash。

我们来看上面提到的trace cmsdb31_asmb_1155.trc内容，如下：

/oracle/admin/cmsdb3/bdump/cmsdb31_asmb_1155.trc

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

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

ORACLE_HOME = /oracle/product/10.2.0/cmsdb

System name: SunOS

Node name: cmsdb05

Release: 5.10

Version: Generic_137111-01

Machine: sun4u

Instance name: cmsdb31

Redo thread mounted by this instance: 1

Oracle process number: 52

Unix process pid: 1155, image: oracle@cmsdb05 (ASMB)

*** 2012-09-17 10:35:00.281

*** SERVICE NAME:(SYS$BACKGROUND) 2012-09-17 10:35:00.280

*** SESSION ID:(586.1) 2012-09-17 10:35:00.280

error 15064 detected in background process

ORA-15064: communication failure with ASM instance

ORA-03113: end-of-file on communication channel

ksuitm: waiting for [5] seconds before killing DIAG

我们看到这个trace基本上没有什么信息，就只有ora-15064和ora-03113错误，这2个错误很好理解，不多说。

后面还有一句ksuitm: waiting for [5] seconds before killing DIAG 其实也值得我们关注。

这个oracle 10g中是通过一个隐含参数来进行控制的：

SQL> show parameter ksu_diag

NAME                                 TYPE        VALUE

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

_ksu_diag_kill_time                  integer     5

该参数默认是5s，也就上面错误提到的5s，下面是关于该参数的描述：

number of seconds ksuitm waits before killing diag

这里解释下ksu是什么意思：kernel service user 的简称。所以这里不难猜测ksuitm是一个函数，大概是下面的简称：

kernel service user diag wait time。

也就是说diag进程默认等待超过5s，就会被kill掉。

接着我们来继续看asm实例的alert log，如下：

Mon Sep 17 10:35:15 2012

Starting background process ASMB

ASMB started with pid=22, OS id=599

Mon Sep 17 10:38:21 2012

NOTE: ASMB process exiting due to lack of ASM file activity

从上面信息可以看到，在Mon Sep 17 10:35:15 2012，asm实例启动了asmb进程，这里说明一下，asm实例的asmb进程是需要进行数据交互时，才会启动，否则不会启动，我通过vm asm环境测试发现的。

另外通过分析asm的pmon trace，发现大量如下信息：

/oracle/admin/+ASM/bdump/+asm1_pmon_18359.trc

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

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

ORACLE_HOME = /oracle/product/10.2.0/cmsdb

System name: SunOS

Node name: cmsdb05

Release: 5.10

Version: Generic_137111-01

Machine: sun4u

Instance name: +ASM1

Redo thread mounted by this instance: 0

Oracle process number: 2

Unix process pid: 18359, image: oracle@cmsdb05 (PMON)

*** 2012-09-10 13:55:18.344

*** SERVICE NAME:() 2012-09-10 13:55:18.343

*** SESSION ID:(49.1) 2012-09-10 13:55:18.343

[claim lock for dead process][lp 0x3877a7308][p 0x3877265d0.0][hist x951]

[claim lock for dead process][lp 0x3877a71a0][p 0x3877265d0.0][hist x951]

[claim lock for dead process][lp 0x3877a7050][p 0x3877265d0.0][hist x951]

[claim lock for dead process][lp 0x3877a6f00][p 0x3877265d0.0][hist x951]

[claim lock for dead process][lp 0x3877a6db0][p 0x3877265d0.0][hist x951]

[claim lock for dead process][lp 0x3877a6c60][p 0x3877265d0.0][hist x951]

[claim lock for dead process][lp 0x3877a6b10][p 0x3877265d0.0][hist x951]

通过查询mos发现，这个是一个bug，不过无关紧要，如下描述:

Cause

This is an informational message.

The meaning of "claim lock for dead process" message:

The message "claim lock for dead process" indicates that PMON is cleaning up the dead process and releasing the

locks held by this process.These messages do not correlate to any instance termination.

This message will be logged when sessions/processes are killed manually and PMON is clearing the lock held by

the dead process.

Solution

This is a regular massage and there is no ways to remove or suppress it.

Database and System Administrator should focus on finding why the processes are dying.

If that is expected then they just can ignore the messages included in the PMON trace file.

从前面的信息，我们可以发现，都没有什么具体价值的东西，下面我们来看看diag的trace，看看能不能找到一些蛛丝马迹。

搜索asmb，找到如下信息：

PROCESS 52:

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

SO: 680005f58, type: 2, owner: 0, flag: INIT/-/-/0x00

(process) Oracle pid=52, calls cur/top: 68015ba68/68015ba68, 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: 741001830 5 0

last post sent: 818 0 4

last post sent-location: kslpsr

last process posted by me: 6800037d0 1 6

(latch info) wait_event=0 bits=0

Process Group: DEFAULT, pseudo proc: 5373ab390

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

OSD pid info: Unix process pid: 1155, image: oracle@cmsdb05 (ASMB)

Dump of memory from 0x0000000534329A58 to 0x0000000534329C60

534329A50                   00000005 00000000          [........]

534329A60 00000006 801CFF08 00000010 0003139D  [................]

534329A70 00000006 8015BA68 00000003 0003139D  [.......h........]

534329A80 00000005 3643C6B0 00000013 00031291  [....6C..........]

534329A90 00000006 801BFD58 0000000B 0003139D  [.......X........]

534329AA0 00000006 801482C8 00000004 00031291  [................]

534329AB0 00000000 00000000 00000000 00000000  [................]

Repeat 26 times

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

SO: 6801482c8, type: 4, owner: 680005f58, flag: INIT/-/-/0x00

(session) sid: 586 trans: 0, creator: 680005f58, flag: (51) USR/- BSY/-/-/-/-/-

DID: 0000-0034-00000003, short-term DID: 0000-0000-00000000

txn branch: 0

oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS

last wait for 'ASM background timer' blocking sess=0x0 seq=3 wait_time=1310127 seconds since wait started=592766

=0, =0, =0

Dumping Session Wait History

for 'ASM background timer' count=1 wait_time=1310127

=0, =0, =0

for 'ASM background timer' count=1 wait_time=4892509

=0, =0, =0

for 'ASM background timer' count=1 wait_time=4892503

=0, =0, =0

for 'ASM background timer' count=1 wait_time=4892462

=0, =0, =0

for 'ASM background timer' count=1 wait_time=4892512

=0, =0, =0

for 'ASM background timer' count=1 wait_time=4892454

=0, =0, =0

for 'ASM background timer' count=1 wait_time=4892504

=0, =0, =0

for 'ASM background timer' count=1 wait_time=4892602

=0, =0, =0

for 'ASM background timer' count=1 wait_time=4892541

=0, =0, =0

for 'ASM background timer' count=1 wait_time=4892473

=0, =0, =0

temporary object counter: 0

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

UOL used : 0 locks(used=0, free=0)

KGX Atomic Operation Log 51df73dc0

Mutex 0(0, 0) idn 0 oper NONE

Library Cache uid 586 efd 0 whr 0 slp 0

KGX Atomic Operation Log 51df73e08

Mutex 0(0, 0) idn 0 oper NONE

Library Cache uid 586 efd 0 whr 0 slp 0

KGX Atomic Operation Log 51df73e50

Mutex 0(0, 0) idn 0 oper NONE

Library Cache uid 586 efd 0 whr 0 slp 0

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

SO: 6812679b8, type: 41, owner: 6801482c8, flag: INIT/-/-/0x00

(dummy) nxc=0, nlb=0

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

SO: 6801bfd58, type: 11, owner: 680005f58, flag: INIT/-/-/0x00

(broadcast handle) flag: (2) ACTIVE SUBSCRIBER, owner: 680005f58,

event: 24, last message event: 24,

last message waited event: 24, messages read: 0

channel: (5363f4a98) system events broadcast channel

scope: 2, event: 8814, last mesage event: 33,

publishers/subscribers: 0/201,

messages published: 1

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

SO: 53643c6b0, type: 19, owner: 680005f58, flag: INIT/-/-/0x00

GES MSG BUFFERS: st=emp chunk=0x0 hdr=0x0 lnk=0x0 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

------------process 0x53643c6b0--------------------

proc version      : 0

Local node        : 0

pid               : 1155

lkp_node          : 0

svr_mode          : 0

proc state        : KJP_FROZEN

Last drm hb acked : 0

Total accesses    : 1

Imm.  accesses    : 0

Locks on ASTQ     : 0

Locks Pending AST : 0

Granted locks     : 0

AST_Q:

PENDING_Q:

GRANTED_Q:

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

SO: 68015ba68, type: 3, owner: 680005f58, flag: INIT/-/-/0x00

(call) sess: cur 6801482c8, rec 0, usr 6801482c8; depth: 0

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

SO: 6812a5b90, type: 84, owner: 68015ba68, flag: INIT/-/-/0x00

(kfgso) flags: 00000000 clt: 3 err: 0 hint: 0

(kfgpn) rpi: 1 itrn:0 gst:0 usrp:0

busy: 0 rep: 0 grp: 0 check: 0/0 glink: 812a5c10 812a5c10

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

SO: 6801cff08, type: 16, owner: 680005f58, flag: INIT/-/-/0x00

(osp req holder)

似乎没有什么异常，ASM background timer是一个idle event，虽然wait time挺长的，但是这里是一个累积值。

另外看下了diag进程的信息，也没有什么特别的，如下：

PROCESS 8:

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

SO: 680000860, type: 2, owner: 0, flag: INIT/-/-/0x00

(process) Oracle pid=8, calls cur/top: 68015bfe8/68015bfe8, flag: (2) SYSTEM

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

(post info) last post received: 0 0 0

last post received-location: No post

last process to post me: none

last post sent: 0 0 48

last post sent-location: ksoreq_reply

last process posted by me: 800058f98 1 0

(latch info) wait_event=0 bits=0

Process Group: DEFAULT, pseudo proc: 5373ab390

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

OSD pid info: Unix process pid: 639, image: oracle@cmsdb05 (DIAG)

Dump of memory from 0x0000000534328400 to 0x0000000534328608

534328400 00000005 00000000 00000006 801D0018  [................]

534328410 00000010 0003139D 00000006 8015BFE8  [................]

534328420 00000003 0003139D 00000006 801C0088  [................]

534328430 0000000B 0003139D 00000006 80158FB8  [................]

534328440 00000004 00031291 00000005 3643D520  [............6C. ]

534328450 00000013 00031291 00000000 00000000  [................]

534328460 00000000 00000000 00000000 00000000  [................]

Repeat 25 times

534328600 00000000 00000000                    [........]

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

SO: 53643d520, type: 19, owner: 680000860, flag: INIT/-/-/0x00

GES MSG BUFFERS: st=emp chunk=0x0 hdr=0x0 lnk=0x0 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

------------process 0x53643d520--------------------

proc version      : 0

Local node        : 0

pid               : 639

lkp_node          : 0

svr_mode          : 0

proc state        : KJP_FROZEN

Last drm hb acked : 0

Total accesses    : 1

Imm.  accesses    : 0

Locks on ASTQ     : 0

Locks Pending AST : 0

Granted locks     : 0

AST_Q:

PENDING_Q:

GRANTED_Q:

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

SO: 680158fb8, type: 4, owner: 680000860, flag: INIT/-/-/0x00

(session) sid: 599 trans: 0, creator: 680000860, flag: (51) USR/- BSY/-/-/-/-/-

DID: 0000-0000-00000000, short-term DID: 0000-0000-00000000

txn branch: 0

oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS

last wait for 'DIAG idle wait' blocking sess=0x0 seq=3 wait_time=136913 seconds since wait started=592763

component=1, where=1, wait time(millisec)=c8

Dumping Session Wait History

for 'DIAG idle wait' count=1 wait_time=136913

component=1, where=1, wait time(millisec)=c8

for 'DIAG idle wait' count=1 wait_time=309499

component=1, where=1, wait time(millisec)=c8

for 'DIAG idle wait' count=1 wait_time=205062

component=1, where=1, wait time(millisec)=c8

for 'DIAG idle wait' count=1 wait_time=205050

component=1, where=1, wait time(millisec)=c8

for 'DIAG idle wait' count=1 wait_time=204984

component=1, where=1, wait time(millisec)=c8

for 'DIAG idle wait' count=1 wait_time=205079

component=1, where=1, wait time(millisec)=c8

for 'DIAG idle wait' count=1 wait_time=205032

component=1, where=1, wait time(millisec)=c8

for 'DIAG idle wait' count=1 wait_time=205052

component=1, where=1, wait time(millisec)=c8

for 'DIAG idle wait' count=1 wait_time=205057

component=1, where=1, wait time(millisec)=c8

for 'DIAG idle wait' count=1 wait_time=204994

component=1, where=1, wait time(millisec)=c8

temporary object counter: 0

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

UOL used : 0 locks(used=0, free=0)

KGX Atomic Operation Log 52cffe850

Mutex 0(0, 0) idn 0 oper NONE

Library Cache uid 599 efd 0 whr 0 slp 0

KGX Atomic Operation Log 52cffe898

Mutex 0(0, 0) idn 0 oper NONE

Library Cache uid 599 efd 0 whr 0 slp 0

KGX Atomic Operation Log 52cffe8e0

Mutex 0(0, 0) idn 0 oper NONE

Library Cache uid 599 efd 0 whr 0 slp 0

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

SO: 681267698, type: 41, owner: 680158fb8, flag: INIT/-/-/0x00

(dummy) nxc=0, nlb=0

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

SO: 68015bfe8, type: 3, owner: 680000860, flag: INIT/-/-/0x00

(call) sess: cur 680158fb8, rec 0, usr 680158fb8; depth: 0

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

SO: 6801d0018, type: 16, owner: 680000860, flag: INIT/-/-/0x00

(osp req holder)

可以看到diag 的等待时间确实挺长的，以至于该进程被kill。

通过strace 跟踪asm和数据库实例的asmb进程发现都是如下类似的几个函数，没有别的：

% time     seconds  usecs/call     calls    errors syscall

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

nan    0.000000           0        22           read

nan    0.000000           0        22           write

nan    0.000000           0        66           gettimeofday

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

100.00    0.000000                   110           total

但是通过查看/proc/pid/fd/下面的信息，发现应该就是asmb 2个进程进行数据交互的：

--datbase instance

lr-x------ 1 oracle oinstall 64 Sep 26 08:35 23 -> pipe:[141579]

l-wx------ 1 oracle oinstall 64 Sep 26 08:35 22 -> pipe:[141578]

lrwx------ 1 oracle oinstall 64 Sep 26 08:35 20 -> socket:[141577]

---asm instance

lr-x------ 1 oracle oinstall 64 Sep 26 08:40 22 -> pipe:[142437]

l-wx------ 1 oracle oinstall 64 Sep 26 08:40 21 -> pipe:[142436]

lr-x------ 1 oracle oinstall 64 Sep 26 08:40 2 -> /dev/null

lrwx------ 1 oracle oinstall 64 Sep 26 08:40 19 -> socket:[142435]

不过至于具体是怎么交互，就不清楚了。

从diag trace看也没有发现任何的死进程，如下：

Orapids on dead process list: [count = 0]

综上所掌握的信息来看，就是数据库实例的asmb进程crash，然后导致数据库实例crash，进而被crs给重启了。

到最后我们都没有搞清楚数据库实例的asmb进程为何会crash 掉。 从数据库alert log看，故障前6天都是正常的，alert中只有redo切换信息，而且并不频繁，所以最后我不得不再次怀疑是oracle bug了。

我记得该客户除了这3套10.2.0.3 rac(asm)外，还有另外2套10.2.0.4、10.2.0.5的asm rac，几乎从来没有出现过问题。

最后还是没有找到根本原因，不知道是不是应该直接建议该客户直接升级得了。

mos有个bug 有点沾边，虽然是说的11.1.0.7，但是以下版本可能也会受影响，但是关于该bug的具体信息看不到，比较遗憾。

Bug 9246245 – Instance crash due to ORA-15064 in RAC [ID 9246245.8]

另外一种猜测就是有可能当前系统负载过高，可能触发什么bug之类的，不过这些都是猜测，总的来说，bug的可能性是非常之大的。

--------------------------------------ORACLE-DBA----------------------------------------

最权威、专业的Oracle案例资源汇总之【案例】Oracle报错ORA-03113 ORA-15064产生原因和解决办法