关于DataPump的external_table模式

在pre10g的很长时间内,Oracle仅提供exp/imp导入导出工具,虽然这2个实用程序十分有效(现在也是如此),但因为它们受限于client/server模式工具自身的限制,以普通用户程序的身份来运转数以TB计的数据,其才不堪大用!DataPump是10g以后主推的数据抽取/导入工具,不同于exp/imp工具,DataPump是一个服务器端的实用程序,因为运行在服务器上故而DataPump进程可以直接访问数据文件与SGA(无需借shadow进程之手),与exp/imp工具相比使用DataPump可以获得显著的性能改善。DataPump可以通过直接路径或外部表路径这两种方法导出数据;其中直接路径避开了数据库高速缓存。当使用直接路径模式抽取数据时,DataPump从磁盘直接读取数据文件,抽取和格式化文件内容,最后将内容写出到转储文件。该种模式和SGA交互等待少,其导入导出速度直接取决于数据库所在磁盘速度和cpu;因此,直接路径极为快速。

外部表路径模式将使用到数据库的高速缓存buffer cache,通过外部表路径方法导出数据时,DataPump使用普通的SELECT操作将数据块从数据文件中读入buffer cache,为了写出转储文件,数据会在缓存中被格式化。通过外部表路径导入数据时,DataPump根据转储文件的内容构造标准的插入语句,并且通过将数据块从数据文件读至缓存来执行这些语句,插入操作按照标准的样式在缓存中完成;如同任何普通DML操作一样,外部表路径也会同时产生撤销和重做。

DataPump自身会根据对象的复杂性作出使用直接路径还是外部表路径的选择;对于较复杂的对象(后文将列出)而言,为了分解复杂性而必须同SGA进行交互,此情况下Data Pump只能采用外部表模式。我们还可以通过使用access_method参数来控制其行为,当然这仅在我们确认Data Pump作出了错误选择时才有必要。

若满足右列条件EXPDP将采用direct_path即直接路径模式 表结构允许使用直接路径模式,举例而言:

表上没有启用针对SELECT操作的fine-grained access control

非队列表(queue table)

表上没有BFILE和opaque类型的列,或包含有opaque列的对象类型

表上没有加密列

表上没有被废弃的旧类型列

若表上存在LONG或LONG RAW类型列,则此列只能是最后一列
使用Expdp执行导出任务时没有为相关表指定QUERY, SAMPLE, or REMAP_DATA等参数

需要导出的表或分区相对较少(多达250M),亦或者表或分区其实很大,但导出任务无法工作在并行模式(未指定parallel参数,或parallel参数设置为1)

若满足右列条件EXPDP将采用external_table即外部表模式 数据结构不满足在直接路径模式下抽取的条件,举例而言:

表上启用了针对SELECT操作的精细粒度控制

队列表

表上包含了BFILE或opaque类型列,或者包含有opaque列的对象类型

表上存在加密列

表上存在被废弃的旧类型列

表上存在LONG或LONG RAW类型列,且不是最后列

数据结构满足使用直接路径模式的条件,但执行导出任务时相关表上指定了QUERY, SAMPLE, or REMAP_DATA等参数

数据结构满足使用直接路径模式的条件,但相关的表或分区相对较大(大于250M),此时并行SQL可以用来加速数据抽取

若满足右列条件IMPDP将采用direct_path即直接路径模式 数据结构满足使用直接路径模式的条件,举例而言:

当导入某单一表分区时该分区表上没有建立全局索引,这一点也包括分区的对象表

没有基于LOB列建立的域索引(domain index)

非cluster表

表上没有BFILE列或opaque类型列

表上没有嵌入了opaque类型的VARRAY列

表上没有加密列

没有启用补全日志(Supplemental logging)且表上没有LOB类型列

若导入表已预先建立了表建构,则需满足以下条件:

表上没有激活的触发器 并且 若是分区表则应有索引 并且 表上上没有启用针对INSERT操作的精细粒度控制 并且 表上除去check类型约束不存在其他类型约束 并且 表上没有unique的索引

执行导入任务时没有为相关表指定QUERY, REMAP_DATA等参数

需要导入的表或分区相对较小(少于250M),或者表或分区其实很大,但无法以并行模式导入(未指定parallel参数或指定其为1)

若满足右列条件IMPDP将采用external_table即外部表路径 当数据结构不满足在直接路径模式下导入的条件,举例而言:

当导入某单一表分区时该分区表上建有全局索引,这一点也包括分区的对象表

表上有基于LOB列建立的域索引(domain index)

cluster表

表上有BFILE列或opaque类型列

表上有嵌入了opaque类型的VARRAY列

表上有加密列

启用了补全日志且表上有至少一个LOB列

若导入表已预先建立了表建构,且满足以下条件:

表上有激活的触发器 或者

是分区表且没有任何索引 或者

表上启用了针对INSERT操作的精细粒度控制 或者

表上除去check类型约束还还有其他类型约束 或者

表上有unique的索引

执行导入任务时有为相关表指定QUERY, REMAP_DATA等参数

数据结构满足使用直接路径模式的条件,但相关的表或分区相对较大(大于250M),此时并行SQL可以用来加速数据导入

我们有必要深入了解一下外部表路径究竟是如何工作的:

SQL> select * from v$version;
BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bi
PL/SQL Release 10.2.0.4.0 - Production
CORE    10.2.0.4.0      Production
TNS for Linux: Version 10.2.0.4.0 - Production
NLSRTL Version 10.2.0.4.0 - Production

SQL> exec dbms_workload_repository.create_snapshot;
PL/SQL procedure successfully completed.

/*  执行expdp导出任务,TCACHE表大小为465M,这里显示指定了外部表路径 */

[maclean@rh2 ~]$ expdp maclean/maclean directory=dumps tables=TCACHE dumpfile=tcache1.dmp access_method=external_table
Export: Release 10.2.0.4.0 - 64bit Production on Tuesday, 24 August, 2010 20:31:48
Copyright (c) 2003, 2007, Oracle.  All rights reserved.
Connected to: Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Starting "MACLEAN"."SYS_EXPORT_TABLE_07":  maclean/******** directory=dumps tables=TCACHE dumpfile=tcache1.dmp access_method=external_table
Estimate in progress using BLOCKS method...
Processing object type TABLE_EXPORT/TABLE/TABLE_DATA
Total estimation using BLOCKS method: 544 MB
Processing object type TABLE_EXPORT/TABLE/TABLE
Processing object type TABLE_EXPORT/TABLE/STATISTICS/TABLE_STATISTICS
. . exported "MACLEAN"."TCACHE"                          465.6 MB 4999999 rows
Master table "MACLEAN"."SYS_EXPORT_TABLE_07" successfully loaded/unloaded
******************************************************************************
Dump file set for MACLEAN.SYS_EXPORT_TABLE_07 is:
  /s01/dump/tcache1.dmp
Job "MACLEAN"."SYS_EXPORT_TABLE_07" successfully completed at 20:32:18

/*  这次我们指定了并行度为4  */

[maclean@rh2 ~]$ expdp maclean/maclean directory=dumps tables=TCACHE dumpfile=tcache2.dmp,tcache3.dmp,tcache4.dmp,tcache5.dmp access_method=external_table parallel=4
Export: Release 10.2.0.4.0 - 64bit Production on Tuesday, 24 August, 2010 20:32:49
Copyright (c) 2003, 2007, Oracle.  All rights reserved.
Connected to: Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Starting "MACLEAN"."SYS_EXPORT_TABLE_07":  maclean/******** directory=dumps tables=TCACHE dumpfile=tcache2.dmp,tcache3.dmp,tcache4.dmp,tcache5.dmp access_method=external_table parallel=4
Estimate in progress using BLOCKS method...
Processing object type TABLE_EXPORT/TABLE/TABLE_DATA
Total estimation using BLOCKS method: 544 MB
Processing object type TABLE_EXPORT/TABLE/TABLE
Processing object type TABLE_EXPORT/TABLE/STATISTICS/TABLE_STATISTICS
. . exported "MACLEAN"."TCACHE"                          465.6 MB 4999999 rows
Master table "MACLEAN"."SYS_EXPORT_TABLE_07" successfully loaded/unloaded
******************************************************************************
Dump file set for MACLEAN.SYS_EXPORT_TABLE_07 is:
  /s01/dump/tcache2.dmp
  /s01/dump/tcache3.dmp
  /s01/dump/tcache4.dmp
Job "MACLEAN"."SYS_EXPORT_TABLE_07" successfully completed at 20:33:04

SQL> exec dbms_workload_repository.create_snapshot;
PL/SQL procedure successfully completed.

SQL> @?/rdbms/admin/awrrpt

接着我们分析该时段内的awr报告!

从AWR报告中,我们不难找到以下语句:
SQL ID 3qwsywpvtdyjp:
CREATE TABLE "ET$088200010001" ( "OWNER", "OBJECT_NAME", "SUBOBJECT_NAME", "OBJECT_ID", "DATA_OBJECT_ID", "OBJECT_TYPE", "CREATED", "LAST_DDL_TIME", "TIMESTAMP", "STATUS", "TEMPORARY", "GENERATED", "SECONDARY" ) ORGANIZATION EXTERNAL ( TYPE ORACLE_DATAPUMP DEFAULT DIRECTORY DUMPS ACCESS PARAMETERS (DEBUG =0 DATAPUMP INTERNAL TABLE "MACLEAN"."TCACHE" JOB ( "MACLEAN", "SYS_EXPORT_TABLE_07", 1) WORKERID 1 PARALLEL 1 VERSION COMPATIBLE ENCRYPTPASSWORDISNULL ) LOCATION ('bogus.dat') ) PARALLEL 1 REJECT LIMIT UNLIMITED AS SELECT /*+ PARALLEL(KU$, 1) */ "OWNER", "OBJECT_NAME", "SUBOBJECT_NAME", "OBJECT_ID", "DATA_OBJECT_ID", "OBJECT_TYPE", "CREATED", "LAST_DDL_TIME", "TIMESTAMP", "STATUS", "TEMPORARY", "GENERATED", "SECONDARY" FROM RELATIONAL("MACLEAN"."TCACHE" ) KU$

SQL ID 1rxax27p7anr3:
CREATE TABLE "ET$088000020001" ( "OWNER", "OBJECT_NAME", "SUBOBJECT_NAME", "OBJECT_ID", "DATA_OBJECT_ID", "OBJECT_TYPE", "CREATED", "LAST_DDL_TIME", "TIMESTAMP", "STATUS", "TEMPORARY", "GENERATED", "SECONDARY" ) ORGANIZATION EXTERNAL ( TYPE ORACLE_DATAPUMP DEFAULT DIRECTORY DUMPS ACCESS PARAMETERS (DEBUG =0 DATAPUMP INTERNAL TABLE "MACLEAN"."TCACHE" JOB ( "MACLEAN", "SYS_EXPORT_TABLE_07", 1) WORKERID 2 PARALLEL 2 VERSION COMPATIBLE ENCRYPTPASSWORDISNULL ) LOCATION ('bogus.dat') ) PARALLEL 2 REJECT LIMIT UNLIMITED AS SELECT /*+ PARALLEL(KU$, 2) */ "OWNER", "OBJECT_NAME", "SUBOBJECT_NAME", "OBJECT_ID", "DATA_OBJECT_ID", "OBJECT_TYPE", "CREATED", "LAST_DDL_TIME", "TIMESTAMP", "STATUS", "TEMPORARY", "GENERATED", "SECONDARY" FROM RELATIONAL("MACLEAN"."TCACHE" ) KU$

以上就是Expdp在导出数据时使用的创建组织类型为ORACLE_DATAPUMP的外部表的SQL语句;后者语句中指定的并行度为2,而非我所指定的4,因该是Oracle考虑到所需导出表的具体大小,设置过高的并行度反而会适得其反,所以对设定值做了修正。

启用了并行的SQL 1rxax27p7anr3执行时间为22.63s,反而要比不使用并行慢;可见在TCACHE表这个数量级,完全没有必要使用并行导出。

接着我们来探究一下外部表路径的导入:

SQL> truncate table tcache;
Table truncated.
SQL> set pagesize 1400;
SQL> set linesize 140;

/* 执行外部表路径的数据导入,并行度1  */

[maclean@rh2 admin]$ impdp maclean/maclean directory=dumps tables=TCACHE content=data_only  dumpfile=tcache1.dmp access_method=external_table

/* 在以上SQL执行期间查询V$SQL动态视图的相关语句*/

select sql_text,
       sql_id,
       cpu_time,
       elapsed_time,
       disk_reads,
       buffer_gets,
       rows_processed
  from v$sql
 where sql_text like '%TCACHE%'
   and sql_text not like '%like%';

SQL_TEXT
--------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID          CPU_TIME ELAPSED_TIME DISK_READS BUFFER_GETS ROWS_PROCESSED
------------- ---------- ------------ ---------- ----------- --------------
INSERT /*+ SYS_DL_CURSOR */ INTO RELATIONAL("MACLEAN"."TCACHE") ("OWNER","OBJECT_NAME","SUBOBJECT_NAME","OBJECT_ID","DATA_OBJECT_ID","OBJECT
_TYPE","CREATED","LAST_DDL_TIME","TIMESTAMP","STATUS","TEMPORARY","GENERATED","SECONDARY") VALUES (NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,N
ULL,NULL,NULL,NULL,NULL)
6tn47a220d34q        408          408          0           0              0

INSERT /*+APPEND+*/  /*+PARALLEL("TCACHE",1)+*/ INTO RELATIONAL("MACLEAN"."TCACHE" ) ("OWNER", "OBJECT_NAME", "SUBOBJECT_NAME", "OBJECT_ID",
 "DATA_OBJECT_ID", "OBJECT_TYPE", "CREATED", "LAST_DDL_TIME", "TIMESTAMP", "STATUS", "TEMPORARY", "GENERATED", "SECONDARY")     SELECT "OWNE
R", "OBJECT_NAME", "SUBOBJECT_NAME", "OBJECT_ID", "DATA_OBJECT_ID", "OBJECT_TYPE", "CREATED", "LAST_DDL_TIME", "TIMESTAMP", "STATUS", "TEMPO
RARY", "GENERATED", "SECONDARY"     FROM "ET$087B00060001" KU$
66q4w8c4ak0wf      31576        31576          0         608              0

/* 当导入job完成后再次查询 */
select sql_text,
       sql_id,
       cpu_time,
       elapsed_time,
       disk_reads,
       buffer_gets,
       rows_processed
  from v$sql
 where sql_text like '%TCACHE%'
   and sql_text not like '%like%';

SQL_TEXT
--------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID          CPU_TIME ELAPSED_TIME DISK_READS BUFFER_GETS ROWS_PROCESSED
------------- ---------- ------------ ---------- ----------- --------------
INSERT /*+ SYS_DL_CURSOR */ INTO RELATIONAL("MACLEAN"."TCACHE") ("OWNER","OBJECT_NAME","SUBOBJECT_NAME","OBJECT_ID","DATA_OBJECT_ID","OBJECT
_TYPE","CREATED","LAST_DDL_TIME","TIMESTAMP","STATUS","TEMPORARY","GENERATED","SECONDARY") VALUES (NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,N
ULL,NULL,NULL,NULL,NULL)
6tn47a220d34q        408          408          0           0              0

/* 执行完成后一句SQL立马消失了!? Oracle好像很不情愿我们看到外部表路径使用的INSERT语句 :) */

INSERT /*+APPEND+*/ /*+PARALLEL("TCACHE",1)+*/
INTO RELATIONAL
  ("MACLEAN"."TCACHE")
  ("OWNER",
   "OBJECT_NAME",
   "SUBOBJECT_NAME",
   "OBJECT_ID",
   "DATA_OBJECT_ID",
   "OBJECT_TYPE",
   "CREATED",
   "LAST_DDL_TIME",
   "TIMESTAMP",
   "STATUS",
   "TEMPORARY",
   "GENERATED",
   "SECONDARY")
  SELECT "OWNER",
         "OBJECT_NAME",
         "SUBOBJECT_NAME",
         "OBJECT_ID",
         "DATA_OBJECT_ID",
         "OBJECT_TYPE",
         "CREATED",
         "LAST_DDL_TIME",
         "TIMESTAMP",
         "STATUS",
         "TEMPORARY",
         "GENERATED",
         "SECONDARY"
    FROM "ET$087F00230001" KU$

/* 这里的KU$代表的就是以ORACLE_DATAPUMP转储文件形式存放在数据库外的外部表 */

/* 可以看到这里尝试使用了APPEND插入模式,以减少undo和redo的产生*/

SQL> truncate table tcache;
Table truncated.

/* 若启用并行导入呢? */

[maclean@rh2 admin]$ impdp maclean/maclean directory=dumps tables=TCACHE content=data_only  dumpfile=tcache2.dmp,tcache3.dmp,tcache4.dmp access_method=external_table parallel=3
........

select sql_text,
       sql_id,
       cpu_time,
       elapsed_time,
       disk_reads,
       buffer_gets,
       rows_processed
  from v$sql
 where sql_text like '%TCACHE%'
   and sql_text not like '%like%';
SQL_TEXT
--------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID          CPU_TIME ELAPSED_TIME DISK_READS BUFFER_GETS ROWS_PROCESSED
------------- ---------- ------------ ---------- ----------- --------------
INSERT /*+APPEND+*/  /*+PARALLEL("TCACHE",1)+*/ INTO RELATIONAL("MACLEAN"."TCACHE" ) ("OWNER", "OBJECT_NAME", "SUBOBJECT_NAME", "OBJECT_ID",
 "DATA_OBJECT_ID", "OBJECT_TYPE", "CREATED", "LAST_DDL_TIME", "TIMESTAMP", "STATUS", "TEMPORARY", "GENERATED", "SECONDARY")     SELECT "OWNE
R", "OBJECT_NAME", "SUBOBJECT_NAME", "OBJECT_ID", "DATA_OBJECT_ID", "OBJECT_TYPE", "CREATED", "LAST_DDL_TIME", "TIMESTAMP", "STATUS", "TEMPO
RARY", "GENERATED", "SECONDARY"     FROM "ET$087A00040001" KU$
2mvs15623ssvy    5910289      5910289          0       73578              0

INSERT /*+ SYS_DL_CURSOR */ INTO RELATIONAL("MACLEAN"."TCACHE") ("OWNER","OBJECT_NAME","SUBOBJECT_NAME","OBJECT_ID","DATA_OBJECT_ID","OBJECT
_TYPE","CREATED","LAST_DDL_TIME","TIMESTAMP","STATUS","TEMPORARY","GENERATED","SECONDARY") VALUES (NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,N
ULL,NULL,NULL,NULL,NULL)
6tn47a220d34q       1167         1167          0           0              0

/* 似乎因为沿用了APPEND插入模式,插入语句的并行度并未上升 */

/* 因为Oracle不想同我们分享它的小秘密,所以awr和ash报告中都不记录外部表路径插入SQL的相关信息 */

/* 好吧,它有权保持沉默!  */

That's great!

Pending Problem

这个问题发生在今年的1月,用户以操作系统认证形式登陆RAC中的主用实例时发现登陆挂起,但不出现错误。之后应用人员陆续手动杀死服务进程,杀死进程后发现实例可以登录了,应用人员在没有做任何信息转储的情况下重启了数据库,这就造成了我们后期诊断时缺乏必要的信息,也是这个case变成悬案的主要原因。

在实例hang住的一个半小时中告警日志没有任何信息;仅有的有用信息是该实例中diag,pmon,lmd后台进程的trace文件。以下为trace文件:

lmd0 trace:
*** 2010-01-16 11:02:58.106
DUMP LOCAL BLOCKER/HOLDER: block level 5 res [0x10b0005][0xeb5],[TX]
----------resource 0x70000044a76e1a0----------------------
resname       : [0x10b0005][0xeb5],[TX]
Local node    : 1
dir_node      : 1
master_node   : 1
hv idx        : 25
hv last r.inc : 0
current inc   : 20
hv status     : 0
hv master     : 0
open options  : dd
grant_bits    : KJUSERNL KJUSEREX
grant mode    : KJUSERNL  KJUSERCR  KJUSERCW  KJUSERPR  KJUSERPW  KJUSEREX
count         : 1         0         0         0         0         1
val_state     : KJUSERVS_NOVALUE
valblk        : 0x00000000000000000000000000000000 .
access_node   : 1
vbreq_state   : 0
state         : x0
resp          : 70000044a76e1a0
On Scan_q?    : N
Total accesses: 15061
Imm.  accesses: 12545
Granted_locks : 1
Cvting_locks  : 1
value_block:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
GRANTED_Q :
lp 700000488546990 gl KJUSEREX rp 70000044a76e1a0 [0x10b0005][0xeb5],[TX]
  master 1 gl owner 70000048dd08220 possible pid 2928930 xid 2033-0333-0026D22C bast 0 rseq 215 mseq 0 history 0x14951495
  open opt KJUSERDEADLOCK
CONVERT_Q:
lp 700000488546ae0 gl KJUSERNL rl KJUSEREX rp 70000044a76e1a0 [0x10b0005][0xeb5],[TX]
  master 1 gl owner 70000048ee0ed48 possible pid 2040272 xid 2006-0066-0006F888 bast 0 rseq 215 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE KJUSERTRCCANCEL
----------enqueue 0x700000488546990------------------------
lock version     : 2242641
Owner node       : 1
grant_level      : KJUSEREX
req_level        : KJUSEREX
bast_level       : KJUSERNL
notify_func      : 0
resp             : 70000044a76e1a0
procp            : 70000048928b8f0
pid              : 2040272
proc version     : 40135
oprocp           : 0
opid             : 0
group lock owner : 70000048dd08220
possible pid     : 2928930
xid              : 2033-0333-0026D22C
dd_time          : 0.0 secs
dd_count         : 0
timeout          : 0.0 secs
On_timer_q?      : N
On_dd_q?         : N
lock_state       : GRANTED
Open Options     : KJUSERDEADLOCK
Convert options  : KJUSERNOQUEUE
History          : 0x14951495
Msg_Seq          : 0x0
res_seq          : 215
valblk           : 0x00000000000000000000000000000000 .
DUMP LOCAL BLOCKER: initiate state dump for TIMEOUT
  possible owner[819.2928930] on resource TX-010B0005-00000EB5
Submitting asynchronized dump request [28]

pmon trace:
*** SESSION ID:(3384.1) 2010-01-16 11:00:11.349
[claim lock for dead process][lp 0x7000004870f7078][p 0x7000004891a79e0.2928930][hist x49514951]

[claim lock for dead process][lp 0x700000488546990][p 0x70000048928b8f0.0][hist x49514951]   <<<< note:this message@2010-01-16 12:35

pmon trace:
*** 2010-01-16 11:02:58.244
Dump requested by process [orapid=6]
REQUEST:custom dump [2] with parameters [6][819][2][2]
. process info of pid[819.2928930] requested by pid[6.3621092]
Dumping process 819.2928930 info:
*** 2010-01-16 11:02:58.244
Dumping diagnostic information for ospid 2928930:
OS pid = 2928930
loadavg : 10.83 10.96 10.91
swap info: free_mem = 21646.73M rsv = 128.00M
           alloc = 235.52M avail = 32768.00M swap_free = 32532.48M
       F S      UID     PID    PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD
  240001 A  orauser 2928930       1 120 120 20 6da7bd510 174068          10:35:28      -  1:50 oracleCRMDB22 (LOCAL=NO)
open: The file access permissions do not allow the specified action.
procstack: write(/proc/2928930/ctl): The requested resource is busy.
2928930: oracleCRMDB22 (LOCAL=NO)

lmd0进程的trace文件显示该进程发现了本地存在阻塞超时的问题,[0x10b0005][0xeb5],[TX]资源的拥有者是2928930进程,而pmon进程认为2928930进程可能出于僵死状态,故希望RAC中的diag进程能对该进程做进一步的诊断,diag进程受到pmon的邀请”Dump requested by process [orapid=6]”,尝试”Dumping process 819.2928930 info:”,并利用AIX上的procstack调试工具分析此进程当时的调用栈,但出现了”procstack: write(/proc/2928930/ctl): The requested resource is busy”的错误,在网上搜索该记录的相关信息发现可能是AIX上procstack工具的一个Bug,而跟实例挂起问题关系不大:

Problem summary
****************************************************************
* USERS AFFECTED:
* Users of the procstac command on the 5300-09 Technology Level
* with the bos.perf.proctools fileset at the 5.3.9.0 and 5.3.9.1
* levels.
****************************************************************
* PROBLEM DESCRIPTION:
* The procstac command fails with an error similar to:
*
* open: Permission denied
* procstack: write(/proc/2068724/ctl): Device busy
****************************************************************
* RECOMMENDATION:
* Install APAR IZ47903.
****************************************************************
Problem conclusion
*Modified the code to fix this problelm.

diag进程的跟踪文件还显示2928930进程持有redo copy latch;这个case发生后的一个礼拜恰好有Oracle原厂工程师到该客户单位做巡检,原厂工程师查看了实例挂起期间的ASH报告,发现该时段内实例中redo相关的等待频繁发生,基本可以认定是僵死进程持有”redo copy latch”造成了RAC中单实例hang住。

原厂工程师的结论令客户比较满意,这个case基本可以结束了。但我对这个结论并不完全认同,2928930进程持有的redo copy latch是一个子栓,该类子栓在实例上的总数取决于CPU总数,一般来说等于CPU * 2;该实例所在服务器为IBM的p595配有32个cpu,redo copy latch共有64个,单单一个子栓被hold住会造成整个实例都hang住,且登录挂起吗?

SQL> show parameter cpu_count
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
cpu_count                            integer     32

SQL> select count(*) from v$latch_children where name='redo copy';
  COUNT(*)
----------
        64

/*我们在非生产环境测试一下*/

select addr "十六进制地址",
       to_number(addr, 'xxxxxxxxxxxx') "十进制地址",
       gets,
       misses,
       immediate_gets,
       immediate_misses
  from v$latch_children
 where name = 'redo copy';

十六进制 十进制地址       GETS     MISSES IMMEDIATE_GETS IMMEDIATE_MISSES
-------- ---------- ---------- ---------- -------------- ----------------
2DAB5898  766204056          7          0              0                0
2DAB5818  766203928          5          0              0                0
2DAB5798  766203800          5          0              0                0
2DAB5718  766203672          5          0              0                0
2DAB5698  766203544          5          0              0                0
2DAB5618  766203416          5          0              0                0
2DAB5598  766203288          5          0            511                0
2DAB5518  766203160          5          0         297024              347
8 rows selected.

/*正式测试前的redo copy child latch统计信息,我们还要用到这里的十进制latch地址*/

/*我们尝试手动hold住一个redo copy child latch,并在其他会话中执行一些产生redo的操作*/

session A:
SQL> oradebug setmypid;
Statement processed.
SQL> oradebug call kslgetl 766203160 1;
Function returned 1

/* kslgetl是Oracle内部用get latch的函数,oradebug 可以调用该函数*/

session B:

SQL> select * From v$latchholder;
       PID        SID LADDR    NAME                                                                   GETS
---------- ---------- -------- ---------------------------------------------------------------- ----------
        22        136 2DAB5518 redo copy                                                            297443

另外开三个session,执行一下批量插入数据的匿名块,测试redo是否能够正常产生:
begin
  for i in 1 .. 90000 loop
    insert into tv values (i, i, i);
    commit;
  end loop;
end;
/
PL/SQL procedure successfully completed.

session A:
SQL> oradebug call kslfre 766203160 1;
Function returned 2FD548E0
/*手动释放766203160对应的redo copy 子闩*/

select addr "十六进制地址",
       to_number(addr, 'xxxxxxxxxxxx') "十进制地址",
       gets,
       misses,
       immediate_gets,
       immediate_misses
  from v$latch_children
 where name = 'redo copy';

十六进制 十进制地址       GETS     MISSES IMMEDIATE_GETS IMMEDIATE_MISSES
-------- ---------- ---------- ---------- -------------- ----------------
2DAB5898  766204056          7          0              0                0
2DAB5818  766203928          5          0              0                0
2DAB5798  766203800          5          0              0                0
2DAB5718  766203672          5          0            745                0
2DAB5698  766203544          5          0         122370                5
2DAB5618  766203416          5          0         176712                5
2DAB5598  766203288          5          0         144441                6
2DAB5518  766203160          6          0         297443              373
/*可以看到虽然8个子闩中一个被手动hold住,但对实例的影响远不足以到达hang所需要的条件*/

虽然能证明单个redo copy latch被僵死进程长期持有和实例hang住没有必然的因果联系,但因为缺少相关的systemstate和hanganalyze转储信息,我们也无法进一步做出推断。
这个case发生后的几个月,我无意中在MOS上发现了以下Bug note:

Diagnostic collection may hang or crash the instance
Description

Sometimes while the DIAG process is collecting diagnostics
the database may hang or crash.
This is more likely to occur in a RAC or ASM environment .

You may be seeing this problem if the database crashes or hangs just
after you see the following text in a trace file:
“Dumping diagnostic information for X”
where X is the process that hung or terminated.

This fix replaces invokations of a port specific OS debugger
(like gdb) with Oracle ORADEBUG calls to gather the required
diagnostics.

Note:
For HP Itanium fixes for this issue in 10.2.0.3/10.2.0.4 use bug 8767023
instead of this bug#.

For AIX fixes for this issue in 10.2.0.3/10.2.0.4 use bug 8929701
instead of this bug#.

Workaround
>=10.2.0.3 only: Set init.ora parameter “_ksb_disable_diagpid” = TRUE
but this will disable automatic diagnostics collection.

当diag诊断进程调用系统debugger工具调试问题进程时可能出现实例hang或crash的,且该问题多发于RAC或ASM环境中,workaroud的方法是动态设置_ksb_disable_diagpid为TRUE,可以避免diag诊断进程对问题进程的调试,但这些调试信息往往对我们又是有用的,这倒有些《种树郭橐驼说》中”既然已,勿动勿虑,去不复顾”的味道。

好了这个问题,仍旧pending着,是个悬案。

Brain Split?

真正出现脑裂的几率并不高,但确实让我们碰上了。2个月前为一套AIX6.1上的10.2.0.4双节点RAC系统做故障测试,主要内容是拔除RAC interconnect网线,测试CRS能否正确处理私有网络挂掉的情况。

 

正式测试时发现2台主机都没有重启,而两端的CSS都认为对方节点已经down了。这就造成2个节点都以为自身是幸存者,也就是我们说的脑裂(brain split),此时实例一般会因为LMON进程的缘故而hang住。

 

我们来比对当时2个节点上的日志进一步分析:

 

STEP 1 :20:41:19物理拔出网线后,节点间无法正常通信,进入misscount倒计时600s
节点1:
[    CSSD]2010-06-22 20:41:21.465 [3342] >TRACE:   clssnmPollingThread: node gis2 (2) missed(2) checkin(s)
[    CSSD]2010-06-22 20:41:22.465 [3342] >TRACE:   clssnmPollingThread: node gis2 (2) missed(3) checkin(s)
.........
[    CSSD]2010-06-22 20:51:17.956 [3342] >TRACE:   clssnmPollingThread: node gis2 (2) missed(598) checkin(s)
[    CSSD]2010-06-22 20:51:18.963 [3342] >TRACE:   clssnmPollingThread: node gis2 (2) missed(599) checkin(s)
[    CSSD]2010-06-22 20:51:19.963 [3342] >TRACE:   clssnmPollingThread: Eviction started for node gis2 (2), flags 0x0001, state 3, wt4c 0

/* 节点1上完成倒计时后开始驱逐节点2*/

节点2:
[    CSSD]2010-06-22 20:41:19.598 [3342] >TRACE:   clssnmPollingThread: node gis1 (1) missed(2) checkin(s)
[    CSSD]2010-06-22 20:41:20.599 [3342] >TRACE:   clssnmPollingThread: node gis1 (1) missed(3) checkin(s)
......................
[    CSSD]2010-06-22 20:51:15.871 [3342] >TRACE:   clssnmPollingThread: node gis1 (1) missed(598) checkin(s)
[    CSSD]2010-06-22 20:51:16.871 [3342] >TRACE:   clssnmPollingThread: node gis1 (1) missed(599) checkin(s)
[    CSSD]2010-06-22 20:51:17.878 [3342] >TRACE:   clssnmPollingThread: Eviction started for node gis1 (1), flags 0x0001, state 3, wt4c 0

/*同样的节点2也是在10分钟后的51分开始驱逐节点1*/

STEP 2: 2个节点读取磁盘心跳信息(clssnmReadDskHeartbeat),且认为对方节点已经down了

节点1:
[    CSSD]2010-06-22 20:51:20.964 [3856] >TRACE:   clssnmSetupAckWait: node(1) is ACTIVE
[    CSSD]2010-06-22 20:51:20.964 [3856] >TRACE:   clssnmSendVote: syncSeqNo(3)
[    CSSD]2010-06-22 20:51:20.964 [3856] >TRACE:   clssnmWaitForAcks: Ack message type(13), ackCount(1)
[    CSSD]2010-06-22 20:51:20.965 [2057] >TRACE:   clssnmSendVoteInfo: node(1) syncSeqNo(3)
[    CSSD]2010-06-22 20:51:21.714 [1543] >TRACE:   clssnmReadDskHeartbeat: node(2) is down. rcfg(3) wrtcnt(4185) LATS(1628594178) Disk lastSeqNo(4185)
[    CSSD]2010-06-22 20:51:21.965 [3856] >TRACE:   clssnmWaitForAcks: done, msg type(13)
[    CSSD]2010-06-22 20:51:21.965 [3856] >TRACE:   clssnmCheckDskInfo: Checking disk info...
[    CSSD]2010-06-22 20:51:22.718 [1543] >TRACE:   clssnmReadDskHeartbeat: node(2) is down. rcfg(3) wrtcnt(4186) LATS(1628595183) Disk lastSeqNo(4186)
[    CSSD]2010-06-22 20:51:22.964 [3342] >TRACE:   clssnmPollingThread: node gis1 (1) missed(2) checkin(s)
[    CSSD]2010-06-22 20:51:23.722 [1543] >TRACE:   clssnmReadDskHeartbeat: node(2) is down. rcfg(3) wrtcnt(4187) LATS(1628596186) Disk lastSeqNo(4187)
[ CSSD]2010-06-22 20:51:24.724 [1543] >TRACE: clssnmReadDskHeartbeat: node(2) is down.
rcfg(3) wrtcnt(4188) LATS(1628597189) Disk lastSeqNo(4188)
.............................
[    CSSD]2010-06-22 20:59:49.953 [1543] >TRACE:   clssnmReadDskHeartbeat: node(2) is down. rcfg(3) wrtcnt(4692) LATS(1629102418) Disk lastSeqNo(4692)
[    CSSD]2010-06-22 20:59:50.057 [3085] >TRACE:   clssgmPeerDeactivate: node 2 (gis2), death 0, state 0x80000001 connstate 0xf
[    CSSD]2010-06-22 20:59:50.104 [1029] >TRACE:   clssnm_skgxncheck: CSS daemon failed on node 2
[    CSSD]2010-06-22 20:59:50.382 [2314] >TRACE:   clssgmClientConnectMsg: Connect from con(112a6c5b0) proc(112a5a190) pid() proto(10:2:1:1)
[    CSSD]2010-06-22 20:59:51.231 [3856] >TRACE:   clssnmEvict: Start
[    CSSD]2010-06-22 20:59:51.231 [3856] >TRACE:   clssnmEvict: Evicting node 2, birth 1, death 3, killme 1
[    CSSD]2010-06-22 20:59:51.232 [3856] >TRACE:   clssnmWaitOnEvictions: Start
[    CSSD]2010-06-22 20:59:51.232 [3856] >TRACE:   clssnmWaitOnEvictions: Node(0) down, LATS(0),timeout(1629103696)
[    CSSD]2010-06-22 20:59:51.232 [3856] >TRACE:   clssnmWaitOnEvictions: Node(2) down, LATS(1629102418),timeout(1278)
[    CSSD]2010-06-22 20:59:51.232 [3856] >TRACE:   clssnmSetupAckWait: Ack message type (15)
[    CSSD]2010-06-22 20:59:51.232 [3856] >TRACE:   clssnmSetupAckWait: node(1) is ACTIVE
[    CSSD]2010-06-22 20:59:51.232 [3856] >TRACE:   clssnmSendUpdate: syncSeqNo(3)
[    CSSD]2010-06-22 20:59:51.232 [3856] >TRACE:   clssnmWaitForAcks: Ack message type(15), ackCount(1)
[    CSSD]2010-06-22 20:59:51.232 [2057] >TRACE:   clssnmUpdateNodeState: node 0, state (0/0) unique (0/0) prevConuni(0) birth (0/0) (old/new)
[    CSSD]2010-06-2F1.232 [2057] >TRACE:   clssnmDeactivateNode: node 0 () left cluster

[    CSSD]2010-06-22 20:59:51.232 [2057] >TRACE:   clssnmUpdateNodeState: node 1, state (3/3) unique (1277207505/1277207505) prevConuni(0) birth (2/2) (old/new)
[    CSSD]2010-06-22 20:59:51.232 [2057] >TRACE:   clssnmUpdateNodeState: node 2, state (0/0) unique (1277206874/1277206874) prevConuni(1277206874) birth (1/0) (old/new)
[    CSSD]2010-06-22 20:59:51.232 [2057] >TRACE:   clssnmDeactivateNode: node 2 (gis2) left cluster

[    CSSD]2010-06-22 20:59:51.233 [2057] >USER:    clssnmHandleUpdate: SYNC(3) from node(1) completed
[    CSSD]2010-06-22 20:59:51.233 [2057] >USER:    clssnmHandleUpdate: NODE 1 (gis1) IS ACTIVE MEMBER OF CLUSTER
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmReconfigThread:  started for reconfig (3)
[    CSSD]2010-06-22 20:59:51.310 [4114] >USER:    NMEVENT_RECONFIG [00][00][00][02]
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupGrocks: cleaning up grock crs_version type 2
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupGrocks: cleaning up grock ORA_CLSRD_1_gisdb type 2
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupGrocks: cleaning up grock ORA_CLSRD_1_gisdb type 3
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupGrocks: cleaning up grock ORA_CLSRD_2_gisdb type 3
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(0) grock(ORA_CLSRD_2_gisdb) birth(1/0)
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupGrocks: cleaning up grock DBGISDB type 2
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupGrocks: cleaning up grock DGGISDB type 2
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupGrocks: cleaning up grock DAALL_DB type 2
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupGrocks: cleaning up grock EVMDMAIN type 2
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupGrocks: cleaning up grock CRSDMAIN type 2
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupGrocks: cleaning up grock IGGISDBALL type 2
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupGrocks: cleaning up grock ocr_crs type 2
[    CSSD]2010-06-22 20:59:51.310 [4114] >TRACE:   clssgmCleanupGrocks: cleaning up grock ORA_CLSRCSN_SRV_gisdb1 type 3
[    CSSD]2010-06-22 20:59:51.311 [4114] >TRACE:   clssgmEstablishConnections: 1 nodes in cluster incarn 3
[    CSSD]2010-06-22 20:59:51.311 [3085] >TRACE:   clssgmPeerListener: connects done (1/1)
[    CSSD]2010-06-22 20:59:51.311 [4114] >TRACE:   clssgmEstablishMasterNode: MASTER for 3 is node(1) birth(2)
[    CSSD]2010-06-22 20:59:51.311 [4114] >TRACE:   clssgmChangeMasterNode: requeued 1 RPCs
[    CSSD]2010-06-22 20:59:51.311 [4114] >TRACE:   clssgmMasterCMSync: Synchronizing group/lock status
[    CSSD]2010-06-22 20:59:51.312 [4114] >TRACE:   clssgmMasterSendDBDone: group/lock status synchronization complete
[    CSSD]CLSS-3000: reconfiguration successful, incarnation 3 with 1 nodes

[    CSSD]CLSS-3001: local node number 1, master node number 1

/* 节点1在hearbeat 8分钟左右后认为CSS daemon failed on node 2,正式认为Node 2离开了集群,并完成了reconfiguration*/

节点2:
[    CSSD]2010-06-22 20:51:18.892 [3856] >TRACE:   clssnmSendVote: syncSeqNo(3)
[    CSSD]2010-06-22 20:51:18.892 [3856] >TRACE:   clssnmWaitForAcks: Ack message type(13), ackCount(1)
[    CSSD]2010-06-22 20:51:18.892 [2057] >TRACE:   clssnmSendVoteInfo: node(2) syncSeqNo(3)
[    CSSD]2010-06-22 20:51:19.287 [1543] >TRACE:   clssnmReadDskHeartbeat: node(1) is down. rcfg(3) wrtcnt(3548) LATS(351788040) Disk lastSeqNo(3548)
[    CSSD]2010-06-22 20:51:19.892 [3856] >TRACE:   clssnmWaitForAcks: done, msg type(13)
[    CSSD]2010-06-22 20:51:19.892 [3856] >TRACE:   clssnmCheckDskInfo: Checking disk info...
[ CSSD]2010-06-22 20:51:20.288 [1543] >TRACE: clssnmReadDskHeartbeat: node(1) is down. rcfg(3) wrtcnt(3549) LATS(351789041) Disk lastSeqNo(3549)
[    CSSD]2010-06-22 20:51:21.308 [1543] >TRACE:   clssnmReadDskHeartbeat: node(1) is down. rcfg(3) wrtcnt(3550) LATS(351790062) Disk lastSeqNo(3550)
...........................
[    CSSD]2010-06-22 20:59:46.122 [1543] >TRACE:   clssnmReadDskHeartbeat: node(1) is down. rcfg(3) wrtcnt(4051) LATS(352294875) Disk lastSeqNo(4051)
[    CSSD]2010-06-22 20:59:46.341 [2314] >TRACE:   clssgmClientConnectMsg: Connect from con(112947c70) proc(112946f90) pid() proto(10:2:1:1)
[    CSSD]2010-06-22 20:59:46.355 [2314] >WARNING: clssgmShutDown: Received explicit shutdown request from client.
[    CSSD]2010-06-22 20:59:46.355 [2314] >TRACE:   clssgmClientShutdown: Aborting client (112a50210) proc (112a4e3d0)
[    CSSD]2010-06-22 20:59:46.355 [2314] >TRACE:   clssgmClientShutdown: Aborting client (112a50cd0) proc (112a4e3d0)
[    CSSD]2010-06-22 20:59:46.355 [2314] >TRACE:   clssgmClientShutdown: Aborting client (112a536f0) proc (112a4e3d0)
[    CSSD]2010-06-22 20:59:46.355 [2314] >TRACE:   clssgmClientShutdown: Aborting client (112a4eb90) proc (112a4eef0)
[    CSSD]2010-06-22 20:59:46.355 [2314] >TRACE:   clssgmClientShutdown: Aborting client (112a69250) proc (112a67e10)
[    CSSD]2010-06-22 20:59:46.355 [2314] >TRACE:   clssgmClientShutdown: Aborting client (112946050) proc (112945e50)
[    CSSD]2010-06-22 20:59:46.355 [2314] >TRACE:   clssgmClientShutdown: waited 0 seconds on 6 IO capable clients
[    CSSD]2010-06-22 20:59:46.494 [2314] >WARNING: clssgmClientShutdown: graceful shutdown completed.
[    CSSD]2010-06-22 20:59:47.130 [1543] >TRACE:   clssnmReadDskHeartbeat: node(1) is down. rcfg(3) wrtcnt(4052) LATS(352295883) Disk lastSeqNo(4052)
[    CSSD]2010-06-22 21:34:40.167 >USER:    Oracle Database 10g CSS Release 10.2.0.1.0 Production Copyright 1996, 2004 Oracle.  All rights reserved.

/* node2 也正确进行了heartbeat,并认为node(1) is down,最后被手动关闭;之后还原了网络故障,在21:34时CSS重新启动*/

 

如果你仔细看以上日志的话,你大概会找出”Oracle Database 10g CSS Release 10.2.0.1.0″的记录;这套RAC不是10.2.0.4的吗,为什么CSS还是10.2.0.1版本的呢,事后调查才发觉是安装该套系统的施工方国内某X码工程师在给CRS打补丁的时候忘记运行最后的root102.sh脚本了,该脚本将更新OCR/Voting disk及实际的CRS binary文件等,如果补丁安装结束后没有运行该脚本则升级不会有任何效果,而只会更新oraInventory中的信息。

 

刚开始时哪位X码的工程师抵死不肯承认忘记了运行脚本,而实际上在AIX 6.1上打10.2.0.4 CRS的patch是需要为oracle用户赋特有的权限的,这一点不同于AIX 5.3上,即:

 

chuser capabilities=CAP_BYPASS_RAC_VMM,CAP_PROPAGATE,CAP_NUMA_ATTACH oracle
/*进一步检查*/
lsuser -f oracle | grep capabilities
        capabilities=CAP_BYPASS_RAC_VMM,CAP_PROPAGATE,CAP_NUMA_ATTACH

 

如果未对oracle用户赋以上权限则运行root102.sh脚本时将报错。另一个判断的标志是pre10204/pre10205目录,如果运行过root102.sh脚本的话$ORA_CRS_HOME/install目录下会多出一个形如pre$VERSION的目录,没有的话一般就是没有运行过脚本,当然也有可能是时候删除了(不建议删除)。

 

了解到以上信息后对此次脑裂的追根溯源就要简单的多了,版本10201上的CRS可以说Bug众多的,从10201-10204期间CRS加入了不少新的参数和机制,在MOS上搜索关键词”brain split CSS”可以找到以下案例:

Hdr: 8293652 10.2.0.3 PCW 10.2.0.3 OSD PRODID-5 PORTID-46
Abstract: CSS CANNOT HANDLE SPLIT-BRAIN AND DB INSTANCE RECEIVES ORA-29740
PROBLEM:
——–
config:
2-node RAC: Node1 (pdb01) and Node2 (pdb02)
There’s no time difference between two nodes.

pdb02 got ORA-29740 and terminated at “Tue Feb 17 12:13:06 2009”
ORA-29740 occured with reason 1.
After ORA-29740 happened, the instance won’t be able to start
until rebooting OS.
After rebooting OS, everything was fine and instances were up.

DIAGNOSTIC ANALYSIS:
——————–
clssnmReadDskHeartbeat: node(2) is down. rcfg(8) wrtcnt(2494425)
LATS(1205488794) Disk lastSeqNo(2494425)
nodes
clssgmMasterSendDBDone: group/lock status synchronization complete
nodes

WORKAROUND:
———–
none

RELATED BUGS:
————-

REPRODUCIBILITY:
—————-
once at ct’s env.

TEST CASE:
———-

STACK TRACE:
————

SUPPORTING INFORMATION:
———————–

24 HOUR CONTACT INFORMATION FOR P1 BUGS:
—————————————-

DIAL-IN INFORMATION:
——————–

IMPACT DATE:
————

Does ct apply any CRS(bundle) patch ?

When problem happen, cssd can’t connect each other via interconnect,
but both cssd can do heartbeat to voting disk.
However, both cssd consider that “I’m survivor”.
Looking into node 1 cssd.
* 12:02:30.856 – Initiated sync
[ CSSD]2009-02-17 12:02:30.856 [1262557536] >TRACE: clssnmDoSyncUpdate:
Initiating sync 7
[ CSSD]2009-02-17 12:02:30.856 [1262557536] >TRACE: clssnmDoSyncUpdate:
diskTimeout set to (57000)ms

* Checking voting disk, and find node2 is still voting and living.
[ CSSD]2009-02-17 12:02:30.874 [1262557536] >TRACE: clssnmCheckDskInfo:
Checking disk info…
[ CSSD]2009-02-17 12:02:30.874 [1262557536] >TRACE: clssnmCheckDskInfo:
node(2) timeout(20) state_network(5) state_disk(3) misstime(0)
[ CSSD]2009-02-17 12:02:31.878 [1262557536] >TRACE: clssnmCheckDskInfo:
node(2) disk HB found, network state 5, disk state(3) misstime(1010)

* Compared cluster size and confirmed it can survive.
[ CSSD]2009-02-17 12:02:34.885 [1262557536] >TRACE: clssnmCheckDskInfo:
node 2, iz-pdb02, state 5 with leader 2 has smaller cluster size 1;
my cluster size 1 with leader 1

* Then finished
[ CSSD]2009-02-17 12:02:34.886 [1262557536] >TRACE: clssnmDoSyncUpdate:
Sync Complete!
*** 03/08/09 11:23 pm ***
Looking into node 2 cssd log.

* 12:02:20.647 – initiated sync protocol
[ CSSD]2009-02-17 12:02:20.647 [1262557536] >TRACE: clssnmDoSyncUpdate:
Initiating sync 7
[ CSSD]2009-02-17 12:02:20.647 [1262557536] >TRACE: clssnmDoSyncUpdate:
diskTimeout set to (57000)ms

* Checking disk and find node1 does not do disk heartbeart for 59690 ms.
it would have waited for misscount and considered node 1 is dead
[ CSSD]2009-02-17 12:02:22.285 [1262557536] >TRACE: clssnmCheckDskInfo:
Checking disk info…
[ CSSD]2009-02-17 12:02:22.285 [1262557536] >TRACE: clssnmCheckDskInfo:
node(1) timeout(59690) state_network(5) state_disk(3) misstime(61000)

* node2 is the only active member of cluster, finished.
[ CSSD]2009-02-17 12:02:22.723 [1262557536] >TRACE: clssnmDoSyncUpdate:
Sync Complete!
*** 03/08/09 11:45 pm ***
So, strange point is, node 2 cssd says node 1 cssd didn’t do
disk heartbeat for 60 seconds.

Looking into node1 cssd log just before initiating sync. We see 87sec gap.
———————————–
[ CSSD]2009-02-17 12:00:19.354 [1199618400] >TRACE: clssgmClientConnectMsg:
Connect from con(0x784d80) proc(0x7749b0) pid(14746) proto(10:2:1:1)
[ CSSD]2009-02-17 12:00:33.338 [1199618400] >TRACE: clssgmClientConnectMsg:
Connect from con(0x7d8620) proc(0x75cfb0) pid() proto(10:2:1:1)
[ CSSD]2009-02-17 12:01:03.688 [1199618400] >TRACE: clssgmClientConnectMsg:
Connect from con(0x76a390) proc(0x75cfb0) pid(13634) proto(10:2:1:1)
[ CSSD]2009-02-17 12:02:30.855 [1168148832] >WARNING: clssnmDiskPMT:
sltscvtimewait timeout (69200)
[ CSSD]2009-02-17 12:02:30.855 [1189128544] >WARNING: clssnmeventhndlr:
Receive failure with node 2 (iz-pdb02), state 3, con(0x72b980),
probe((nil)), rc=10
[ CSSD]2009-02-17 12:02:30.855 [1189128544] >TRACE: clssnmDiscHelper:
iz-pdb02, node(2) connection failed, con (0x72b980), probe((nil))
[ CSSD]2009-02-17 12:02:30.856 [1262557536] >TRACE: clssnmDoSyncUpdate:
Initiating sync 7

As an interesting point, clssgmClientConnectMsg does not show message,
but nm polling thread/disk ping thread does not warn timeout.
(Usually it should write message first at 50% of timeout = 30 sec)

And “sltscvtimewait timeout (69200)” message means, DiskPingMonitor thread
does not run for a 69200 ms whereas it just wants to sleep 1 second.

These suggest, cssd does not scheduled about 70 seconds on node 1.
I don’t see any log from DiskPingThread, but I assume it is suspended
at some point also, and back to work after 70 seconds.
Please check OS message file to see any interesting error is recorded.
To prevent this issue, keep watching OS performance to see if any
extreme high load does not happen.

Recommended solution it to go to 10.2.0.4 and use oprocd so that
we can expect oprocd kill node1 in such case.

 

 

上述案例同样是在”cssd can’t connect each other via interconnect”的状况下出现了”I’m survivor”的脑裂问题,MOS的建议是升级到10204后oprocd进程可以阻止这样的惨剧发生。

 

该问题最后通过升级到10.2.0.5解决了,这个case告诉我们在中国的it大环境内,有时候我们不得不亲力亲为地关心每一个细节,就拿这次来说我一开始也没发现升级没完成的情况,后来还是同事提醒了我;因为这是一个非常低级错误,如果施工方的X码工程师仔仔细细地按照他们下发的文档按部就班亦或者能留意一下升级时的图形窗口中的说明的话,这个问题都不会发生!而实际上不仅仅是此套系统,连带着其他2套系统也是这位X码工程师安装升级的,这几套系统在之后的故障测试时都发现了同样的问题。

事实告诉我们,细节决定成败!

ORA-00600: internal error code, arguments: [kdsgrp1] example

一套Linux x86-64上的11.2.0.1系统,alert日志中出现ORA-00600: internal error code, arguments: [kdsgrp1]错误,相关trace的部分内容如下:

Dump file /u01/app/oracle/diag/rdbms/utdw016/utdw016b/incident/incdir_276035/utdw016b_ora_5756_i276035.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/112utdw016
System name:	Linux
Node name:	x42k601
Release:	2.6.18-164.el5
Version:	#1 SMP Tue Aug 18 15:51:48 EDT 2009
Machine:	x86_64
Instance name: utdw016b
Redo thread mounted by this instance: 2
Oracle process number: 52
Unix process pid: 5756, image: oracle@x42k601

*** 2010-07-28 11:08:35.394
*** SESSION ID:(577.11818) 2010-07-28 11:08:35.394
*** CLIENT ID:() 2010-07-28 11:08:35.394
*** SERVICE NAME:(utdw016-edw) 2010-07-28 11:08:35.394
*** MODULE NAME:(pmdtm@x42k604-zone1 (TNS V1-V3)) 2010-07-28 11:08:35.394
*** ACTION NAME:() 2010-07-28 11:08:35.394

Dump continued from file: /u01/app/oracle/diag/rdbms/utdw016/utdw016b/trace/utdw016b_ora_5756.trc
ORA-00600: internal error code, arguments: [kdsgrp1], [], [], [], [], [], [], [], [], [], [], []

========= Dump for incident 276035 (ORA 600 [kdsgrp1]) ========

*** 2010-07-28 11:08:35.395
dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
----- Current SQL Statement for this session (sql_id=9hfdcgzzgmgvp) -----
DELETE FROM EIMABS.FACT_OPEN_SALES_ORDER WHERE DIM_SNAPSHOT_TYPE_ID = (SELECT DIM_SNAPSHOT_TYPE_ID FROM EIMABS.DIM_SNAPSHOT_TYPE WHERE SNAPSHOT_TYPE_CODE='FUTURE')
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
object line object
handle number name
0x5578e0528 6 anonymous block

----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
skdstdst()+36 call kgdsdst() 000000000 ? 000000000 ?
7FFFA85D7418 ? 000000001 ?
7FFFA85DB918 ? 000000000 ?
ksedst1()+98 call skdstdst() 000000000 ? 000000000 ?
7FFFA85D7418 ? 000000001 ?
000000000 ? 000000000 ?
ksedst()+34 call ksedst1() 000000000 ? 000000001 ?
7FFFA85D7418 ? 000000001 ?
000000000 ? 000000000 ?
dbkedDefDump()+2736 call ksedst() 000000000 ? 000000001 ?
7FFFA85D7418 ? 000000001 ?
000000000 ? 000000000 ?
ksedmp()+36 call dbkedDefDump() 000000003 ? 000000002 ?
7FFFA85D7418 ? 000000001 ?
000000000 ? 000000000 ?
ksfdmp()+64 call ksedmp() 000000003 ? 000000002 ?
7FFFA85D7418 ? 000000001 ?
000000000 ? 000000000 ?
dbgexPhaseII()+1764 call ksfdmp() 000000003 ? 000000002 ?
7FFFA85D7418 ? 000000001 ?
000000000 ? 000000000 ?
dbgexProcessError() call dbgexPhaseII() 2B30E1B74718 ? 2B30E1B795F8 ?
+2279 7FFFA85E3708 ? 000000001 ?
000000000 ? 000000000 ?
dbgeExecuteForError call dbgexProcessError() 2B30E1B74718 ? 2B30E1B795F8 ?
()+83 000000001 ? 000000000 ?
7FFF00000000 ? 000000000 ?
dbgePostErrorKGE()+ call dbgeExecuteForError 2B30E1B74718 ? 2B30E1B795F8 ?
1615 () 000000001 ? 000000001 ?
000000000 ? 000000000 ?
dbkePostKGE_kgsf()+ call dbgePostErrorKGE() 000000000 ? 2B30E1B87F38 ?
63 000000258 ? 2B30E1B795F8 ?
000000000 ? 000000000 ?
kgeadse()+383 call dbkePostKGE_kgsf() 00A9B2EE0 ? 2B30E1B87F38 ?
000000258 ? 2B30E1B795F8 ?
000000000 ? 000000000 ?
kgerinv_internal()+ call kgeadse() 00A9B2EE0 ? 2B30E1B87F38 ?
45 000000258 ? 000000000 ?
000000000 ? 000000000 ?
kgerinv()+33 call kgerinv_internal() 00A9B2EE0 ? 2B30E1B87F38 ?
A85DBCA000000000 ?
000000258 ? 000000000 ?
000000000 ?
kgeasnmierr()+143 call kgerinv() 00A9B2EE0 ? 2B30E1B87F38 ?
A85DBCA000000000 ?
000000000 ? 000000000 ?
000000000 ?
kdsgrp1_dump()+832 call kgeasnmierr() 00A9B2EE0 ? 2B30E1B87F38 ?
A85DBCA000000000 ?
000000000 ? 000000003 ?
000000003 ?
kdsgrp1()+19 call kdsgrp1_dump() 00A9B2EE0 ? 2B30E1B87F38 ?
7FFFA85E4360 ? 000000000 ?
000000003 ? 000000003 ?
kdsgrp()+6346 call kdsgrp1() 00A9B2EE0 ? 2B30E1B87F38 ?
7FFFA85E4360 ? 000000000 ?
000000003 ? 000000003 ?
qetlbr()+211 call kdsgrp() 2B30E2018620 ? 000000000 ?
2B30E2018620 ? 000000000 ?
000000003 ? 000000003 ?
qertbFetchByRowID() call qetlbr() 2B30E2018620 ? 00000001A ?
+850 000000000 ? 0000000C8 ?
00400F521 ? 000000000 ?
qergiFetch()+276 call qertbFetchByRowID() 000000000 ? 2B30E2018518 ?
000000000 ? 000000000 ?
000000001 ? 000000000 ?
qerdlFetch()+678 call qergiFetch() 511B78238 ? 2B30E20187F8 ?
000000000 ? 000000000 ?
000000001 ? 000000000 ?
delexe()+952 call qerdlFetch() 511B78090 ? 2B30E2018900 ?
000000000 ? 000000000 ?
000007FFF ? 000000000 ?
opiexe()+14449 call delexe() 000000000 ? 000000000 ?
000000000 ? 2B30E27E1E08 ?
2B30E1FCA000 ? 000000000 ?
opipls()+3098 call opiexe() 000000004 ? 000000005 ?
7FFFA85E6708 ? 2B30E27E1E08 ?
2B30E1FCA000 ? 000000000 ?
opiodr()+1149 call opipls() 000000066 ? 000000007 ?
7FFFA85E7F90 ? 000000000 ?
2B30E2701C28 ? 300000000 ?
__PGOSF141_rpidrus( call opiodr() 000000066 ? 000000007 ?
)+206 7FFFA85E7F90 ? 000000003 ?
008C71EF0 ? 300000000 ?
skgmstack()+148 call __PGOSF141_rpidrus( 7FFFA85E79A0 ? 000000007 ?
) 7FFFA85E7F90 ? 000000003 ?
008C71EF0 ? 300000000 ?
rpiswu2()+612 call skgmstack() 7FFFA85E7978 ? 00A9B2B20 ?
00000F618 ? 008468D40 ?
7FFFA85E79A0 ? 300000000 ?
rpidrv()+1342 call rpiswu2() 55CE5B2F8 ? 000000078 ?
55CE5B37C ? 000000009 ?
2B30E1FEEF98 ? 000000078 ?
psddr0()+459 call rpidrv() 000000003 ? 000000066 ?
7FFFA85E7F90 ? 000000039 ?
2B30E1FEEF98 ? 000000078 ?
psdnal()+457 call psddr0() 000000003 ? 000000066 ?
7FFFA85E7F90 ? 000000031 ?
2B30E1FEEF98 ? 000000078 ?
pevm_EXECC()+376 call psdnal() 7FFFA85E9370 ? 7FFFA85E9580 ?
7FFFA85E7F90 ? 2B30E2742370 ?
2B30E1FEEF98 ? 000000078 ?
pfrinstr_EXECC()+75 call pevm_EXECC() 2B30E273F0A0 ? 7FFFA85E9580 ?
000000020 ? 2B30E2742370 ?
2B30E1FEEF98 ? 000000078 ?
pfrrun_no_tool()+63 call pfrinstr_EXECC() 2B30E273F0A0 ? 51148B482 ?
2B30E273F110 ? 2B30E2742370 ?
2B30E1FEEF98 ? 2B3000000020 ?
pfrrun()+1025 call pfrrun_no_tool() 2B30E273F0A0 ? 51148B482 ?
2B30E273F110 ? 2B30E2742370 ?
2B30E1FEEF98 ? 2B3000000020 ?
plsql_run()+769 call pfrrun() 2B30E273F0A0 ? 000000000 ?
2B30E273F110 ? 7FFFA85E9370 ?
2B30E1FEEF98 ? 503AC23E2 ?
peicnt()+296 call plsql_run() 2B30E273F0A0 ? 000000001 ?
000000000 ? 7FFFA85E9370 ?
2B30E1FEEF98 ? 000000000 ?
kkxexe()+520 call peicnt() 7FFFA85E9370 ? 2B30E273F0A0 ?
2B30E2418960 ? 7FFFA85E9370 ?
2B30E2486008 ? 000000000 ?
opiexe()+14796 call kkxexe() 2B30E2013538 ? 2B30E273F0A0 ?
000000000 ? 7FFFA85E9370 ?
2B30E2486008 ? 000000000 ?
kpoal8()+2283 call opiexe() 000000049 ? 000000003 ?
7FFFA85EA8F8 ? 7FFFA85E9370 ?
2B30E2486008 ? 000000000 ?
opiodr()+1149 call kpoal8() 00000005E ? 00000001C ?
7FFFA85ED9D0 ? 7FFFA85E9370 ?
2B30E2486008 ? 5E00000001 ?
ttcpip()+1251 call opiodr() 00000005E ? 00000001C ?
7FFFA85ED9D0 ? 000000000 ?
008C71DB0 ? 5E00000001 ?
opitsk()+1628 call ttcpip() 00A9C6450 ? 0086CCB08 ?
7FFFA85ED9D0 ? 000000000 ?
7FFFA85ED430 ? 7FFFA85EDBD4 ?
opiino()+953 call opitsk() 00A9C6450 ? 000000000 ?
7FFFA85ED9D0 ? 000000000 ?
7FFFA85ED430 ? 7FFFA85EDBD4 ?
opiodr()+1149 call opiino() 00000003C ? 000000004 ?
7FFFA85EF0C8 ? 000000000 ?
7FFFA85ED430 ? 7FFFA85EDBD4 ?
opidrv()+565 call opiodr() 00000003C ? 000000004 ?
7FFFA85EF0C8 ? 000000000 ?
008C71860 ? 7FFFA85EDBD4 ?
sou2o()+98 call opidrv() 00000003C ? 000000004 ?
7FFFA85EF0C8 ? 000000000 ?
008C71860 ? 7FFFA85EDBD4 ?
opimai_real()+128 call sou2o() 7FFFA85EF0A0 ? 00000003C ?
000000004 ? 7FFFA85EF0C8 ?
008C71860 ? 7FFFA85EDBD4 ?
ssthrdmain()+209 call opimai_real() 000000002 ? 7FFFA85EF290 ?
000000004 ? 7FFFA85EF0C8 ?
008C71860 ? 7FFFA85EDBD4 ?
main()+196 call ssthrdmain() 000000002 ? 7FFFA85EF290 ?
000000001 ? 000000000 ?
008C71860 ? 7FFFA85EDBD4 ?
__libc_start_main() call main() 000000002 ? 7FFFA85EF438 ?
+244 000000001 ? 000000000 ?
008C71860 ? 7FFFA85EDBD4 ?
_start()+36 call __libc_start_main() 0009D3E88 ? 000000002 ?
7FFFA85EF428 ? 000000000 ?
008C71860 ? 000000002 ?

错误由此删除语句引起:

DELETE FROM EIMABS.FACT_OPEN_SALES_ORDER WHERE 
DIM_SNAPSHOT_TYPE_ID = 
(SELECT DIM_SNAPSHOT_TYPE_ID FROM EIMABS.DIM_SNAPSHOT_TYPE WHERE SNAPSHOT_TYPE_CODE='FUTURE')

其中EIMABS.DIM_SNAPSHOT_TYPE是一个普通堆表,而EIMABS.FACT_OPEN_SALES_ORDER是一个分区表,针对该分区表的各个分区进行了validate structure分析:

SQL> @?/rdbms/admin/utlvalid
Table created.

SQL> set time on;

23:32:51 SQL> analyze table EIMABS.DIM_SNAPSHOT_TYPE validate structure cascade;
Table analyzed.

00:30:46 SQL> analyze table EIMABS.FACT_OPEN_SALES_ORDER partition (P_2455405) validate structure cascade into invalid_rows;
analyze table EIMABS.FACT_OPEN_SALES_ORDER partition (P_2455405) validate structure cascade into invalid_rows
*
ERROR at line 1:
ORA-01499: table/index cross reference failure - see trace file

推测可能是P_2455405分区相关的索引可能出现了讹误,尝试重建该表上的15个索引,再次测试相关应用发现问题仍未解决。此次产生的trace文件:

Dump file /u01/app/oracle/diag/rdbms/utdw016/utdw016a/incident/incdir_310187/utdw016a_ora_26473_i310187.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/112utdw016
System name:	Linux
Node name:	x42k600
Release:	2.6.18-164.el5
Version:	#1 SMP Tue Aug 18 15:51:48 EDT 2009
Machine:	x86_64
Instance name: utdw016a
Redo thread mounted by this instance: 1
Oracle process number: 62
Unix process pid: 26473, image: oracle@x42k600

*** 2010-07-30 04:10:19.931
*** SESSION ID:(1993.31898) 2010-07-30 04:10:19.931
*** CLIENT ID:() 2010-07-30 04:10:19.931
*** SERVICE NAME:(utdw016-edw) 2010-07-30 04:10:19.931
*** MODULE NAME:(pmdtm@x42k604-zone2 (TNS V1-V3)) 2010-07-30 04:10:19.931
*** ACTION NAME:() 2010-07-30 04:10:19.931

Dump continued from file: /u01/app/oracle/diag/rdbms/utdw016/utdw016a/trace/utdw016a_ora_26473.trc
ORA-00600: internal error code, arguments: [kdsgrp1], [], [], [], [], [], [], [], [], [], [], []

========= Dump for incident 310187 (ORA 600 [kdsgrp1]) ========

*** 2010-07-30 04:10:19.932
dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
----- Current SQL Statement for this session (sql_id=9hfdcgzzgmgvp) -----
DELETE FROM EIMABS.FACT_OPEN_SALES_ORDER WHERE DIM_SNAPSHOT_TYPE_ID = (SELECT DIM_SNAPSHOT_TYPE_ID FROM EIMABS.DIM_SNAPSHOT_TYPE WHERE SNAPSHOT_TYPE_CODE='FUTURE')
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----

SO: 0x5334781d0, type: 52, owner: 0x55d2646b8, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
      proc=0x55caf0778, name=transaction, file=ktccts.h LINE:388, pg=0
     (trans) flg = 0x00001e03, flg2 = 0x000c0000, flg3 = 0x00000000, prx = (nil), ros = 2147483647
     flg  = 0x00001e03: ALC TRN VUS VID CHG USN
     flg2 = 0x000c0000: PGA NIP
     flg3 = 0x00000000:
     bsn = 0x8419 bndsn = 0x841b spn = 0x85c7
     efd = 15 DID:
     file:kta.c lineno:1665
     parent xid: 0x0000.000.00000000
     env: (scn: 0x0a19.a0b7c9d4  xid: 0x0021.017.00028415  uba: 0x00e00545.0438.12  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0a19.a0b7c9d9 0sch: scn: 0x0000.00000000  mascn: (scn: 0x0000.00000000)
     cev: (spc = 11546  arsp = 0x5335450a8  ubkds (ubk:tsn: 2 rdba: 0x00e00545 flag:0x8 hdl:(nil) addr:0x35c50c014)  useg tsn: 2 rdba: 0x00e2c990
           hwm uba: 0x00e00545.0438.12  col uba: 0x00000000.0000.00
           num bl: 3 bk list: 0x53db19518)
           cr opc: 0x0 spc: 11546 uba: 0x00e00545.0438.12
     ccbstg: 0x00000000
     (enqueue) TX-00210017-00028415	DID: 0001-003E-00000C70
     lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  res_flag: 0x47
     mode: X, lock_flag: 0x0, lock: 0x533478248, res: 0x5414c2da0
     own: 0x55d2646b8, sess: 0x8b37718, proc: 0x55caf0778, prv: 0x5414c2db0
     slk: (nil)
      xga: (nil), heap: UGA
     Trans IMU st: 0 Pool index 65535, Redo pool 0x533478980, Undo pool 0x533478a68
     Redo pool range [0x2b13aacccb90 0x2b13aacccb90 0x2b13aacd1390]
     Undo pool range [0x2b13aacc8390 0x2b13aacc8390 0x2b13aacccb90]
      chnf control flags 0x0         CHNF hwm uba uba: 0x00000000.0000.00        ----------------------------------------
       SO: 0x53db19518, type: 51, owner: 0x5334781d0, flag: -/-/-/0x00 if: 0x3 c: 0x3

SO: 0x55d2646b8, type: 4, owner: 0x55caf0778, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
    proc=0x55caf0778, name=session, file=ksu.h LINE:11467, pg=0
   (session) sid: 1993 ser: 31898 trans: 0x5334781d0, creator: 0x55caf0778
             flags: (0x45) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
             flags2: (0x40008) -/-
             DID: , short-term DID:
             txn branch: (nil)
             oct: 7, prv: 0, sql: 0x5534eae70, psql: 0x55a4ff230, user: 120/EIMABS
   ksuxds FALSE at location: 0
   service name: utdw016-edw
   client details:
     O/S info: user: infom, term: , ospid: 21955
     machine: x42k604-zone2 program: pmdtm@x42k604-zone2 (TNS V1-V3)
     application name: pmdtm@x42k604-zone2 (TNS V1-V3), hash value=4200765728
   Current Wait Stack:
     Not in wait; last wait ended 1.028093 sec ago
   Wait State:
     fixed_waits=0 flags=0x21 boundary=(nil)/-1
   Session Wait History:
       elapsed time of 1.028173 sec since last wait
    0: waited for 'Disk file operations I/O'
       FileOperation=0x5, fileno=0x1, filetype=0x3
       wait_id=4666 seq_num=4860 snap_id=2
       wait times: snap=0.000039 sec, exc=0.000181 sec, total=0.000687 sec
       wait times: max=infinite
       wait counts: calls=0 os=0
       occurred after 0.000000 sec of elapsed time
    1: waited for 'ASM file metadata operation'
       msgop=0x12, locn=0x0, =0x0
       wait_id=4667 seq_num=4859 snap_id=2
       wait times: snap=0.000002 sec, exc=0.000005 sec, total=0.000506 sec
       wait times: max=infinite
       wait counts: calls=0 os=0
       occurred after 0.000000 sec of elapsed time
    2: waited for 'KSV master wait'
       =0x0, =0x0, =0x0
       wait_id=4668 seq_num=4858 snap_id=1
       wait times: snap=0.000501 sec, exc=0.000501 sec, total=0.000501 sec
       wait times: max=infinite
       wait counts: calls=1 os=1
       occurred after 0.000000 sec of elapsed time
    3: waited for 'ASM file metadata operation'
       msgop=0x12, locn=0x0, =0x0
       wait_id=4667 seq_num=4857 snap_id=1
       wait times: snap=0.000003 sec, exc=0.000003 sec, total=0.000003 sec
       wait times: max=infinite
       wait counts: calls=0 os=0
       occurred after 0.000000 sec of elapsed time
    4: waited for 'Disk file operations I/O'
       FileOperation=0x5, fileno=0x1, filetype=0x3
       wait_id=4666 seq_num=4856 snap_id=1
       wait times: snap=0.000142 sec, exc=0.000142 sec, total=0.000142 sec
       wait times: max=infinite
       wait counts: calls=0 os=0
......

Block header dump:  0x0400f521 Data

Block header dump:  0x2317a579 Index

Block header dump:  0x2317a577 " "

Block header dump:  0x048c8c3c " "

Block header dump:  0x2317a1bb " "

Block header dump:  0x048c78ad " "

Block header dump:  0x0400f51f Data

Block header dump:  0x2317a33b Index

Block header dump:  0x048c78f3 " "

Block header dump:  0x07541a44 " "

Block header dump:  0x07577b92 " "

Block header dump:  0x078a4eb7 " "

Block header dump:  0x2317a4b7 " "

Block header dump:  0x040fe621 " "

Block header dump:  0x2317a47b " "

同时应用人员发现此系统中另一SQL语句也会导致ORA-600[kdsgrp1]错误的出现,如下:

SELECT
F.DIM_BIZ_SECTOR_ID AS DIM_BIZ_SECTOR_ID,
F.DW_REVENUE_ID ,
F.DIM_ENT_ITEM_ID AS DIM_ENT_ITEM_ID,
F.DIM_REV_PCH_KEY_ACCT_ID AS DIM_PCH_KEY_ACCOUNT_ID,
CT.DIM_PGH_COUNTRY_GROUP_ID AS DIM_PGH_COUNTRY_GROUP_ID,
F.DIM_REVENUE_DATE_ID AS DIM_FORECAST_DATE_ID,
NEXT_DAY(SYSDATE-4.000000000000000,'FRI') AS SNAPSHOT_DATE,
F.REVENUE_DT AS FORECAST_DATE,
F.REVENUE_QTY AS REVENUE_QTY
FROM
EIMABS.FACT_REVENUE F,
EIMABS.DIM_BIZ_SECTOR B,
EIMABS.DIM_ENT_ITEM E,
EIMABS.DIM_PCH_KEY_ACCOUNT PCH,
EIMABS.DIM_COUNTRY CT,
EIMABS.DIM_FISCAL_CAL_DATE CAL
WHERE
F.DIM_BIZ_SECTOR_ID = B.DIM_BIZ_SECTOR_ID
AND F.DIM_ENT_ITEM_ID = E.DIM_ENT_ITEM_ID
AND F.DIM_REV_PCH_KEY_ACCT_ID = PCH.DIM_PCH_KEY_ACCOUNT_ID
AND F.DIM_ULT_DEST_COUNTRY_ID = CT.DIM_COUNTRY_ID
AND UPPER(B.BIZ_SECTOR_CODE) = 'MDB'
AND F.DIM_REVENUE_DATE_ID = CAL.DIM_CALENDAR_DATE_ID
AND CAL.FISCAL_MONTH_NUM IN
(SELECT FISCAL_MONTH_NUM FROM EIMABS.DIM_FISCAL_CAL_MONTH
WHERE DIM_CALENDAR_MONTH_ID IN (
(SELECT B.DIM_CALENDAR_MONTH_ID -1 FROM EIMABS.DIM_FISCAL_CAL_DATE A , EIMABS.DIM_FISCAL_CAL_MONTH B
WHERE CALENDAR_DT = TRUNC(SYSDATE) AND A.DIM_CALENDAR_MONTH_ID = B.DIM_CALENDAR_MONTH_ID),
(SELECT B.DIM_CALENDAR_MONTH_ID -2 FROM EIMABS.DIM_FISCAL_CAL_DATE A , EIMABS.DIM_FISCAL_CAL_MONTH B
WHERE CALENDAR_DT = TRUNC(SYSDATE) AND A.DIM_CALENDAR_MONTH_ID = B.DIM_CALENDAR_MONTH_ID)));

ERROR at line 12:
ORA-00600: internal error code, arguments: [kdsgrp1], [], [], [], [], [], [],
[], [], [], [], []

/*相关trace文件如下*/

Trace file /u01/app/oracle/diag/rdbms/utdw016/utdw016a/trace/utdw016a_ora_26473.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/112utdw016
System name:	Linux
Node name:	x42k600
Release:	2.6.18-164.el5
Version:	#1 SMP Tue Aug 18 15:51:48 EDT 2009
Machine:	x86_64
Instance name: utdw016a
Redo thread mounted by this instance: 1
Oracle process number: 62
Unix process pid: 26473, image: oracle@x42k600


*** 2010-07-30 04:10:18.249
*** SESSION ID:(1993.31898) 2010-07-30 04:10:18.249
*** CLIENT ID:() 2010-07-30 04:10:18.249
*** SERVICE NAME:(utdw016-edw) 2010-07-30 04:10:18.249
*** MODULE NAME:(pmdtm@x42k604-zone2 (TNS V1-V3)) 2010-07-30 04:10:18.249
*** ACTION NAME:() 2010-07-30 04:10:18.249

* kdsgrp1-1: *************************************************
           row 0x0400f521.1a continuation at
           0x0400f521.1a file# 16 block# 62753 slot 26 not found
KDSTABN_GET: 0 ..... ntab: 1
curSlot: 26 ..... nrows: 28
kdsgrp - dump CR block dba=0x0400f521
Block header dump:  0x0400f521
Object id on Block? Y
seg/obj: 0x11527d  csc: 0xa19.61e20b3c  itc: 2  flg: E  typ: 1 - DATA
    brn: 0  bdba: 0x400f500 ver: 0x01 opc: 0
    inc: 0  exflg: 0

Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0040.02f.0001bfcd  0x2822b8ea.0224.34  C-U-    0  scn 0x0a19.61e1aa84
0x02   0x003f.01c.00028920  0x2822f9de.01e0.6b  --U-   26  fsc 0x0000.61e21527
bdba: 0x0400f521
data_block_dump,data header at 0x2d63ec064

这个case同时提交了SR,Oracle GCS支持分析日志后认为告警日志中曾经出现kewastUnPackStats记录,说明可能由11.2.0.1上的Bug 8967729 引起的:

I researched the issue further based upon the error that followed the log switch command,

Tue Aug 03 10:00:04 2010
ALTER SYSTEM ARCHIVE LOG
Tue Aug 03 10:00:05 2010
Thread 1 advanced to log sequence 8652 (LGWR switch)
Current log# 4 seq# 8652 mem# 0: +UAT_DATA/utdw016/redo041a.log
Current log# 4 seq# 8652 mem# 1: +UAT_ARCH/utdw016/redo042a.log
Tue Aug 03 10:00:14 2010
Archived Log entry 16346 added for thread 1 sequence 8651 ID 0x8d616825 dest 1:
Tue Aug 03 10:00:21 2010
ALTER SYSTEM ARCHIVE LOG
Tue Aug 03 10:00:23 2010
Thread 1 advanced to log sequence 8653 (LGWR switch)
Current log# 5 seq# 8653 mem# 0: +UAT_DATA/utdw016/redo051a.log
Current log# 5 seq# 8653 mem# 1: +UAT_ARCH/utdw016/redo052a.log
Tue Aug 03 10:00:23 2010
Archived Log entry 16348 added for thread 1 sequence 8652 ID 0x8d616825 dest 1:
Tue Aug 03 10:00:45 2010
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> kewastUnPackStats(): bad magic 1 (0x2b29e289bf13, 0)

We need to resolve this issue and then determine whether these indexes corrupt again within the database.

I found Bug 8967729 11.2.0.1 Abstract: KEWASTUNPACKSTATS(): BAD MAGIC MESSAGE IN ALERT.LOG.

Basically, there is a archivelog switch issue that is causes string corruption.

This issue was introduced by the fix of bug #8715387 and has been fully fixed as part of Bug 8730312 11.2 Abstract: FWD MERGE FOR BASE Bug 8715387 FOR 12G.

Please download and install patch 8730312 for your Oracle and OS versions.
However, if you have installed patches in this 11.2 database, then upload the results of the Opatch inventory.
We will check the installed database patches against patch 8730312 for any contradictions.

Hdr: 8967729 11.2.0.1 RDBMS 11.2.0.1 SVRMAN AWR PRODID-5 PORTID-226 8730312
Abstract: KEWASTUNPACKSTATS(): BAD MAGIC MESSAGE IN ALERT.LOG
PROBLEM:
--------
In a two-node RAC cluster (+ Data Guard), the rac instances write many
strange messages in alert log, such:
kewastUnPackStats(): bad magic 1 (0x2ac893121390, 0)
The hex address changes.

DIAGNOSTIC ANALYSIS:
--------------------
I don't see any error associated with this message.
It looks like Bug 8730312 description, but the base bug 8715387 should be
already fixed in 11.2.0.1 version.

WORKAROUND:
-----------
n/a

RELATED BUGS:
-------------
8715387, 8730312

REPRODUCIBILITY:
----------------

TEST CASE:
----------

STACK TRACE:
------------
Tue Sep 22 09:15:34 2009
ALTER SYSTEM ARCHIVE LOG
Tue Sep 22 09:15:34 2009
LGWR: Standby redo logfile selected to archive thread 1 sequence 1244
LGWR: Standby redo logfile selected for thread 1 sequence 1244 for
destination LOG_ARCHIVE_DEST_2
Thread 1 advanced to log sequence 1244 (LGWR switch)
  Current log# 2 seq# 1244 mem# 0:
+DGCTRL/saneons/onlinelog/group_2.264.697133919
Archived Log entry 3903 added for thread 1 sequence 1243 ID 0x5186bbfd dest
1:
Tue Sep 22 10:00:02 2009
kewastUnPackStats(): bad magic 1 (0x2b1d760d3038, 0)
kewastUnPackStats(): bad magic 1 (0x2b1d760d3038, 0)

MOS认为应用补丁8730312可以解决我们的问题,但实际apply patch后EIMABS.FACT_OPEN_SALES_ORDER上的DELETE语句可以正常执行了,而之后发现的查询语句仍会报ORA-00600:[kdsgrp1]错误:

We have applied the patch. And we're in process of analyze all the partitions. So far there's no error reported. We analyzed all the partitions in table EIMABS.FACT_REVENUE, there's no error either. However, when we run the query, we still get the same error. Please note the other tables in the query are not partitioned.

SELECT
F.DIM_BIZ_SECTOR_ID AS DIM_BIZ_SECTOR_ID,
F.DW_REVENUE_ID ,
F.DIM_ENT_ITEM_ID AS DIM_ENT_ITEM_ID,
F.DIM_REV_PCH_KEY_ACCT_ID AS DIM_PCH_KEY_ACCOUNT_ID,
CT.DIM_PGH_COUNTRY_GROUP_ID AS DIM_PGH_COUNTRY_GROUP_ID,
F.DIM_REVENUE_DATE_ID AS DIM_FORECAST_DATE_ID,
NEXT_DAY(SYSDATE-4.000000000000000,'FRI') AS SNAPSHOT_DATE,
F.REVENUE_DT AS FORECAST_DATE,
F.REVENUE_QTY AS REVENUE_QTY
FROM
EIMABS.FACT_REVENUE F,
EIMABS.DIM_BIZ_SECTOR B,
EIMABS.DIM_ENT_ITEM E,
EIMABS.DIM_PCH_KEY_ACCOUNT PCH,
EIMABS.DIM_COUNTRY CT,
EIMABS.DIM_FISCAL_CAL_DATE CAL
WHERE
F.DIM_BIZ_SECTOR_ID = B.DIM_BIZ_SECTOR_ID
AND F.DIM_ENT_ITEM_ID = E.DIM_ENT_ITEM_ID
AND F.DIM_REV_PCH_KEY_ACCT_ID = PCH.DIM_PCH_KEY_ACCOUNT_ID
AND F.DIM_ULT_DEST_COUNTRY_ID = CT.DIM_COUNTRY_ID
AND UPPER(B.BIZ_SECTOR_CODE) = 'MDB'
AND F.DIM_REVENUE_DATE_ID = CAL.DIM_CALENDAR_DATE_ID
AND CAL.FISCAL_MONTH_NUM IN
(SELECT FISCAL_MONTH_NUM FROM EIMABS.DIM_FISCAL_CAL_MONTH
WHERE DIM_CALENDAR_MONTH_ID IN (
(SELECT B.DIM_CALENDAR_MONTH_ID -1 FROM EIMABS.DIM_FISCAL_CAL_DATE A , EIMABS.DIM_FISCAL_CAL_MONTH B
WHERE CALENDAR_DT = TRUNC(SYSDATE) AND A.DIM_CALENDAR_MONTH_ID = B.DIM_CALENDAR_MONTH_ID),
(SELECT B.DIM_CALENDAR_MONTH_ID -2 FROM EIMABS.DIM_FISCAL_CAL_DATE A , EIMABS.DIM_FISCAL_CAL_MONTH B
WHERE CALENDAR_DT = TRUNC(SYSDATE) AND A.DIM_CALENDAR_MONTH_ID = B.DIM_CALENDAR_MONTH_ID)));

SELECT
*
ERROR at line 1:
ORA-00600: internal error code, arguments: [kdsgrp1], [], [], [], [], [], [],
[], [], [], [], []

/*以下为trace文件*/
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/112utdw016
System name:	Linux
Node name:	x42k600
Release:	2.6.18-164.el5
Version:	#1 SMP Tue Aug 18 15:51:48 EDT 2009
Machine:	x86_64
Instance name: utdw016a
Redo thread mounted by this instance: 1
Oracle process number: 64
Unix process pid: 7170, image: oracle@x42k600 (TNS V1-V3)


*** 2010-08-05 19:10:19.776
*** SESSION ID:(10.4634) 2010-08-05 19:10:19.776
*** CLIENT ID:() 2010-08-05 19:10:19.776
*** SERVICE NAME:(SYS$USERS) 2010-08-05 19:10:19.776
*** MODULE NAME:(sqlplus@x42k600 (TNS V1-V3)) 2010-08-05 19:10:19.776
*** ACTION NAME:() 2010-08-05 19:10:19.776

* kdsgrp1-1:
*************************************************
           row 0x04608b75.40 continuation at
           0x04608b75.40 file# 17 block# 2132853 slot 64 not found
KDSTABN_GET: 0 ..... ntab: 1
curSlot: 64 ..... nrows: 130
kdsgrp - dump CR block dba=0x04608b75
Block header dump:  0x04608b75
Object id on Block? Y
seg/obj: 0x1c8071  csc: 0xa19.622a6023  itc: 2  flg: E  typ: 1 - DATA
    brn: 0  bdba: 0x4608b40 ver: 0x01 opc: 0
    inc: 0  exflg: 0

Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x000f.040.0001267d  0x01067067.022e.1e  --U-   64  fsc 0x0000.622a621d
0x02   0x0029.026.0001be36  0x282115c8.0223.0a  C---    0  scn 0x0a19.62297970  <---------- this TX shows in the index too
bdba: 0x04608b75
data_block_dump,data header at 0x47c16c064
===============
tsiz: 0x3f98
hsiz: 0x116
pbl: 0x47c16c064
    76543210
flag=--------
ntab=1
nrow=130
frre=64
..
..
tab 0, row 63, @0x3a65
tl: 110 fb: --H-FL-- lb: 0x1  cc: 22
col  0: [ 5]  c4 0e 31 32 04
col  1: [ 2]  c1 02
col  2: [ 5]  c4 02 44 33 44
col  3: [ 5]  c4 03 14 10 23
col  4: [ 5]  c4 09 5f 35 38
col  5: [ 5]  c4 05 32 42 0b
col  6: [ 2]  c2 03
col  7: [ 5]  c4 03 2e 36 49
col  8: [ 1]  80
col  9: [ 1]  80
col 10: [ 7]  32 30 34 31 39 32 35
col 11: [ 1]  4e
col 12: [ 7]  78 6e 06 18 01 01 01
col 13: [ 2]  c1 06
col 14: [ 3]  c2 4d 33
col 15: [ 7]  78 6e 07 1b 0a 0d 04
col 16: [ 4]  c3 05 2f 25
col 17: [ 2]  c1 09
col 18: [ 3]  c2 02 50
col 19: [ 3]  c2 02 50
col 20: [ 2]  c1 0e
col 21: [ 8]  38 30 30 31 31 38 35 38
end_of_block_dump


Block dump from cache:
Dump of buffer cache at level 4 for tsn=13, rdba=73436021
BH (0x47fd84178) file#: 17 rdba: 0x04608b75 (17/2132853) class: 1 ba: 0x47c16c000
 set: 47 pool 3 bsz: 16384 bsi: 0 sflg: 1 pwc: 0,25
 dbwrid: 0 obj: 1867889 objn: 1130693 tsn: 13 afn: 17 hint: f
 hash: [0x54be43860,0x54be43860] lru: [0x49beca1a0,0x3b7e094c0]
 ckptq: [NULL] fileq: [NULL] objq: [0x52a0e8580,0x52a0e8580]
 use: [0x54271be40,0x54271be40] wait: [NULL]
 st: SCURRENT md: SHR tch: 0 le: 0x3effd22c8
 flags:
 LRBA: [0x0.0.0] LSCN: [0x0.0] HSCN: [0xffff.ffffffff] HSUB: [65535]
 cr pin refcnt: 0 sh pin refcnt: 0
Block dump from disk:
buffer tsn: 13 rdba: 0x04608b75 (17/2132853)
scn: 0x0a19.622a621d seq: 0x01 flg: 0x06 tail: 0x621d0601
frmt: 0x02 chkval: 0xdf67 type: 0x06=trans data

Block header dump:  0x04608b75
Object id on Block? Y
seg/obj: 0x1c8071  csc: 0xa19.622a6023  itc: 2  flg: E  typ: 1 - DATA
    brn: 0  bdba: 0x4608b40 ver: 0x01 opc: 0
    inc: 0  exflg: 0

Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x000f.040.0001267d  0x01067067.022e.1e  --U-   64  fsc 0x0000.622a621d
0x02   0x0029.026.0001be36  0x282115c8.0223.0a  C---    0  scn 0x0a19.62297970
bdba: 0x04608b75

Incident 322216 created, dump file: /u01/app/oracle/diag/rdbms/utdw016/utdw016a/incident/incdir_322216/utdw016a_ora_7170_i322216.trc
ORA-00600: internal error code, arguments: [kdsgrp1], [], [], [], [], [], [], [], [], [], [], []

utdw016a_ora_7170_i322218.trc
-------------------------------
----- Current SQL Statement for this session (sql_id=88kca6rwpm9pc) -----
SELECT
F.DIM_BIZ_SECTOR_ID AS DIM_BIZ_SECTOR_ID,
F.DW_REVENUE_ID ,
F.DIM_ENT_ITEM_ID AS DIM_ENT_ITEM_ID,
 F.DIM_REV_PCH_KEY_ACCT_ID AS DIM_PCH_KEY_ACCOUNT_ID,
 CT.DIM_PGH_COUNTRY_GROUP_ID AS DIM_PGH_COUNTRY_GROUP_ID,
  F.DIM_REVENUE_DATE_ID AS DIM_FORECAST_DATE_ID,
 NEXT_DAY(SYSDATE-4.000000000000000,'FRI') AS SNAPSHOT_DATE,
 F.REVENUE_DT AS FORECAST_DATE,
 F.REVENUE_QTY AS REVENUE_QTY
FROM
 EIMABS.FACT_REVENUE F,
 EIMABS.DIM_BIZ_SECTOR B,
 EIMABS.DIM_ENT_ITEM E,
 EIMABS.DIM_PCH_KEY_ACCOUNT PCH,
 EIMABS.DIM_COUNTRY CT,
 EIMABS.DIM_FISCAL_CAL_DATE CAL
WHERE
   F.DIM_BIZ_SECTOR_ID = B.DIM_BIZ_SECTOR_ID
AND F.DIM_ENT_ITEM_ID = E.DIM_ENT_ITEM_ID
AND F.DIM_REV_PCH_KEY_ACCT_ID = PCH.DIM_PCH_KEY_ACCOUNT_ID
AND F.DIM_ULT_DEST_COUNTRY_ID = CT.DIM_COUNTRY_ID
AND UPPER(B.BIZ_SECTOR_CODE) = 'MDB'
AND F.DIM_REVENUE_DATE_ID = CAL.DIM_CALENDAR_DATE_ID
AND CAL.FISCAL_MONTH_NUM IN
(SELECT FISCAL_MONTH_NUM FROM EIMABS.DIM_FISCAL_CAL_MONTH
 WHERE DIM_CALENDAR_MONTH_ID IN (
      (SELECT B.DIM_CALENDAR_MONTH_ID -1 FROM EIMABS.DIM_FISCAL_CAL_DATE A , EIMABS.DIM_FISCAL_CAL_MONTH B
          WHERE CALENDAR_DT = TRUNC(SYSDATE) AND A.DIM_CALENDAR_MONTH_ID = B.DIM_CALENDAR_MONTH_ID),
          (SELECT B.DIM_CALENDAR_MONTH_ID -2 FROM EIMABS.DIM_FISCAL_CAL_DATE A , EIMABS.DIM_FISCAL_CAL_MONTH B
          WHERE CALENDAR_DT = TRUNC(SYSDATE) AND A.DIM_CALENDAR_MONTH_ID = B.DIM_CALENDAR_MONTH_ID)))

----- Call Stack Trace -----
 kdsgrp1  kdsgrp  qetlbr  qertbFetchByRowID  qerjotRowProc  qerbtFetch  wProc  qergiFetch

  BH (0x47fd84178) file#: 17 rdba: 0x04608b75 (17/2132853) class: 1 ba: 0x47c16c000
       set: 47 pool 3 bsz: 16384 bsi: 0 sflg: 1 pwc: 0,25
       dbwrid: 0 obj: 1867889 objn: 1130693 tsn: 13 afn: 17 hint: f

addr: 0x47fd84178 obj: 1867889 cls: DATA bscn: 0xa19.622a621d
       buffer tsn: 13 rdba: 0x04608b75 (17/2132853)
       scn: 0x0a19.622a621d seq: 0x01 flg: 0x06 tail: 0x621d0601
       frmt: 0x02 chkval: 0xdf67 type: 0x06=trans data

Block header dump:  0x04608b75
Object id on Block? Y
seg/obj: 0x1c8071  csc: 0xa19.622a6023  itc: 2  flg: E  typ: 1 - DATA
    brn: 0  bdba: 0x4608b40 ver: 0x01 opc: 0
    inc: 0  exflg: 0

Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x000f.040.0001267d  0x01067067.022e.1e  --U-   64  fsc 0x0000.622a621d
0x02   0x0029.026.0001be36  0x282115c8.0223.0a  C---    0  scn 0x0a19.62297970
bdba: 0x04608b75
data_block_dump,data header at 0x47c16c064
===============
tsiz: 0x3f98
hsiz: 0x116
pbl: 0x47c16c064
    76543210
flag=--------
ntab=1
nrow=130
frre=64


     BH (0x49fe84af8) file#: 29 rdba: 0x076e5058 (29/3035224) class: 1 ba: 0x49ee0c000
       set: 44 pool 3 bsz: 16384 bsi: 0 sflg: 1 pwc: 0,25
       dbwrid: 1 obj: 1893758 objn: 1893758 tsn: 17 afn: 29 hint: f
       addr: 0x49fe84af8 obj: 1893758 cls: DATA bscn: 0xa19.62297970
       buffer tsn: 17 rdba: 0x076e5058 (29/3035224)
       scn: 0x0a19.62297970 seq: 0x01 flg: 0x06 tail: 0x79700601
       frmt: 0x02 chkval: 0xe878 type: 0x06=trans data

Block header dump:  0x076e5058
Object id on Block? Y
seg/obj: 0x1ce57e  csc: 0xa19.6229787e  itc: 2  flg: E  typ: 2 - INDEX
    brn: 0  bdba: 0x76e5054 ver: 0x01 opc: 0
    inc: 0  exflg: 0

Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
0x02   0x0029.026.0001be36  0x282115de.0223.2a  --U-   14  fsc 0x0000.62297970  <--------------- same TX as in the table


之后MOS又有回复,认为设置隐式参数_row_cr=FALSE可以解决问题:

There are few bugs that could raise the ora-600[KDSGRP1]  in 11.2

1) based on the stack --> Bug:8771916 ORA-600 [KDSGRP1] WHEN DOING AN UPDATE


Abstract:            OERI [kdsgrp1] during CR read
Fixed-Releases:     C100
Tags:               OERI
Details:
 ORA-600 [kdsgrp1] can occur intermittently when using
 a query access path to a row in a table via an index
 due to a consistent read problem.
 Workaround:
   Disabling rowCR (which is an optimization to reduce consistent-read
   rollbacks during queries) by setting "_row_cr"=FALSE in the
   initialization files in one workaround. However, this could cause
   performance degradation of queries - the statistics "RowCR hits" /
   "RowCR attempts" can help show if this workaround may be detrimental
   to performance.


2) based on the fact it is hit on partitioned tables

Bug 8546356  ORA-8102/ORA-1499/OERI[kdsgrp1] Composite Partitioned Index corruption after rebuild ONLINE
Details:
  When a COMPOSITE PARTITIONED index is rebuild ONLINE and concurrent DML on
  the same table is run on separate RAC instances, index corruption might
  happen where the index is missing some keys. This is only pertaining to
  composite partitioned indexes.
  Wrong results or the next errors can be produced by SQL statements:
  ORA-8102 by a delete/update
  ORA-1499 by "analyze table validate structure cascade"
  ORA-600 [kdsgrp1]
  ORA-600 [qertbFetchByRowID]
  Workaround:
  Do not run concurrent DML from any instance other than the one where index
  online rebuild is happening or rebuild the index without the ONLINE clause.
  To fix it: Rebuild the index.

Please set in init.ora this parameter _row_cr=FALSE and bounce database,
 see after that if OERI[kdsgrp1] still reproduces.

There is one-off patch available for Bug 8771916 for 11.2.0.1 on LInux x86_64
                                              and for Bug 8546356 the one-off patch is done for 11.2.0.1.2

There is also Bug:8951812 hit a lot in 11.2.0.1, one-off patch available
An index can become corrupt during index rebuild online producing
 ORA-600 errors or other external like ORA-8102 by an update/delete,
 ORA-1499 by "analyze table validate structure cascade".

这个case仍在继续,to be continued .....

rman hang on SQL*Net message from client

有这样一个问题,平台为HP-UX(B.11.31 U ia64),Oracle版本为10.2.0.4 single instance,RMAN自动备份autobackup controlfile时出现hang症状,等待事件为SQL*Net message from client, 这还仅仅是使用最简单的NOCATALOG+ Disk Device的情况,没有MML层面的活动。

针对该问题对RMAN服务进程做了后台TRACE,发现stack call总是hang在_read_sys=>KERNEL内核态函数上,感觉与ORACLE的关系不大,应当是HP-UX C函数调用造成的问题,例如:

10046 trace:

PARSING IN CURSOR #3 len=278 dep=0 uid=0 oct=3 lid=0 tim=9513124502191 hv=3071086789 ad=’bd7447d0′
select sofar, context, start_time from v$session_longops where (start_time > nvl(:1, sysdate-100) or start_time = nvl(:2, sysdate+100)) and sid = :3 and serial# = :4 and opname like ‘RMAN:%’ order by start_time desc, context desc
END OF STMT
PARSE #3:c=0,e=3005,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=9513124502186
WAIT #3: nam=’SQL*Net message to client’ ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=9513124502275
WAIT #3: nam=’SQL*Net message from client’ ela= 234 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=9513124502527
BINDS #3:
kkscoacd
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=00 siz=64 off=0
kxsbbbfp=9fffffffbf3d73b0 bln=07 avl=00 flg=05
Bind#1
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=00 siz=0 off=8
kxsbbbfp=9fffffffbf3d73b8 bln=07 avl=00 flg=01
Bind#2
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=00 siz=0 off=16
kxsbbbfp=9fffffffbf3d73c0 bln=22 avl=03 flg=01
value=1875
Bind#3
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=00 siz=0 off=40
kxsbbbfp=9fffffffbf3d73d8 bln=22 avl=04 flg=01
value=50006
EXEC #3:c=10000,e=2859,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=9513124505442
FETCH #3:c=0,e=6030,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=9513124511493
WAIT #3: nam=’SQL*Net message to client’ ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=9513124511560
WAIT #3: nam=’SQL*Net message from client’ ela= 56 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=9513124511690
BINDS #3:
kkscoacd
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=00 siz=64 off=0
kxsbbbfp=9fffffffbf3d6360 bln=07 avl=00 flg=05
Bind#1
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=00 siz=0 off=8
kxsbbbfp=9fffffffbf3d6368 bln=07 avl=00 flg=01
Bind#2
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=00 siz=0 off=16
kxsbbbfp=9fffffffbf3d6370 bln=22 avl=03 flg=01
value=1875
Bind#3
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=00 siz=0 off=40
kxsbbbfp=9fffffffbf3d6388 bln=22 avl=04 flg=01
value=50006
EXEC #3:c=0,e=275,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=9513124512027
FETCH #3:c=10000,e=5688,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=9513124517733
WAIT #3: nam=’SQL*Net message to client’ ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=9513124517765
WAIT #3: nam=’SQL*Net message from client’ ela= 35 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=9513124517853
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=0 op=’SORT ORDER BY (cr=0 pr=0 pw=0 time=11729 us)’
STAT #3 id=2 cnt=0 pid=1 pos=1 obj=0 op=’FIXED TABLE FULL X$KSULOP (cr=0 pr=0 pw=0 time=11697 us)’
WAIT #0: nam=’SQL*Net message to client’ ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=9513124517949
WAIT #0: nam=’SQL*Net message from client’ ela= 1629803 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=9513126147781
BINDS #2:
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=00 siz=72 off=0
kxsbbbfp=9fffffffbf3d7ef8 bln=22 avl=03 flg=05
value=1782
Bind#1
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=00 siz=0 off=24
kxsbbbfp=9fffffffbf3d7f10 bln=22 avl=04 flg=01
value=62996
Bind#2
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=01 fl2=1000000 frm=00 csi=00 siz=0 off=48
kxsbbbfp=9fffffffbf3d7f28 bln=22 avl=02 flg=01
value=2

………….

RMAN DEBUG

DBGRCVMAN: resetAll
DBGRCVMAN: setRAflags kindMask=255 containerMask=15 actionMask=63
DBGRCVMAN: ENTERING setComputeRecoveryActionMasks
DBGRCVMAN: EXITING setComputeRecoveryActionMasks
DBGRCVMAN: allIncarnations is set to FALSE
DBGRCVMAN: reset transclause
DBGRCVMAN: *****BsRecCache Statistics*****
DBGRCVMAN: Cache size=0 hit=0
DBGRCVMAN: rcvRecBackupAge= 0
DBGRCVMAN: thisBackupAge= 0
DBGRCVMAN: ENTERING setRedoLogDeletionPolicy
DBGRCVMAN: setRedoLogDeletionPolicy with policy = TO NONE
DBGRCVMAN: setRedoLogDeletionPolicy with alldest = 0
DBGRCVMAN: ENTERING validateStandbyConfig1
DBGRCVMAN: policy = TO NONE
DBGRCVMAN: alldest = 0
DBGRCVMAN: EXITING validateStandbyConfig1 with target = NULLwith status = 1
DBGRCVMAN: EXITING setRedoLogDeletionPolicy with policy = TO NONE with target = NULL with bind = MANDATORY
DBGMISC: krmknmtr: the parse tree after name translation is: [13:13:53.118]
DBGMISC: EXITED krmknmtr with status Control File and SPFILE Autobackup [13:13:53.118] elapsed time [00:00:00:00.021]
DBGMISC: krmkdps: this_reset_scn=56498483682 [13:13:53.118]
DBGMISC: krmkdps: this_reset_time=02-SEP-09 [13:13:53.119]
DBGMISC: krmkdps: untilSCN= [13:13:53.119]
DBGMISC: krmkdps: untilTime= [13:13:53.119]
DBGMISC: krmkdps: getRA_completedAfter= [13:13:53.119]
DBGMISC: krmkdps: getRA_completedBefore= [13:13:53.119]
DBGMISC: krmkdps: getRA_likePattern= [13:13:53.120]
DBGMISC: krmkdps: getRA_containerMask=15 [13:13:53.120]
DBGMISC: krmkdps: getRA_actionMask=63 [13:13:53.120]
DBGMISC: krmkdps: computeRA_allRecords0 [13:13:53.120]
DBGMISC: krmkdps: computeRA_fullBackups=1 [13:13:53.120]
DBGMISC: krmkdps: allIncarnations=0 [13:13:53.120]
DBGMISC: ENTERED krmkbaut [13:13:53.121]
DBGMISC: Entering krmkgconf [13:13:53.121]

DBGSQL: EXEC SQL AT TARGET select controlfile_type ,controlfile_change# ,controlfile_sequence# ,controlfile_created ,decode(offr.records_used,0,0,((offr.last_recid-offr.records_used)+1)) into :b1,:b2,:b3,:b4,:b5 from v$database ,v$controlfile_record_section offr where offr.type=’OFFLINE RANGE’ [13:13:53.121]
DBGSQL: sqlcode=0 [13:13:53.125]
DBGSQL: :b1 = “CURRENT”
DBGSQL: :b2 = 152792315080
DBGSQL: :b3 = 7538564
DBGSQL: :b4 = “09-AUG-09″
DBGSQL: :b5 = 0
DBGMISC: krmkgconf: Configuration is ENCRYPTION FOR DATABASE [13:13:53.126]

DBGSQL: EXEC SQL AT TARGET declare first boolean ; conf# number ; begin if ( :first > 0 ) then first := TRUE ; else first := FALSE ; end if ; dbms_rcvman . getConfig ( conf# , :name:name_i , :value:value_i , first ) ; end ; [13:13:53.126]
DBGSQL: sqlcode=1403 [13:13:53.127]
DBGMISC: Function kmkgconf created the following tree: [13:13:53.128]
DBGMISC: EXIT
DBGMISC: Exiting krmkgconf [13:13:53.128]
DBGMISC: Configured NoEncrypt at db level [13:13:53.128]
DBGMISC: No Encrypt backup init(60000000) for cfile [13:13:53.128]
DBGMISC: EXITED krmkbaut [13:13:53.128] elapsed time [00:00:00:00.007]
DBGMISC: EXITED krmkomp [13:13:53.128] elapsed time [00:00:00:00.032]
DBGPLSQL: the compiled command tree is: [13:13:53.129] (krmicomp)
DBGPLSQL: 1 CMD type=Control File and SPFILE Autobackup id=1 status=NOT STARTED
DBGPLSQL: 1 STEP id=1 status=NOT STARTED
DBGPLSQL: 1 TEXTNOD = declare
DBGPLSQL: 2 TEXTNOD = ncopies number;
DBGPLSQL: 3 TEXTNOD = copyno number;
DBGPLSQL: 4 TEXTNOD = handle varchar2(512);
DBGPLSQL: 5 TEXTNOD = comment varchar2(80);
DBGPLSQL: 6 TEXTNOD = media varchar2(80);
DBGPLSQL: 7 TEXTNOD = lcfaudate date;
DBGPLSQL: 8 TEXTNOD = lsequence binary_integer;
DBGPLSQL: 9 TEXTNOD = lbautfmt varchar2(512);
DBGPLSQL: 10 TEXTNOD = rsid number;
DBGPLSQL: 11 TEXTNOD = rsts number;
DBGPLSQL: 12 TEXTNOD = p1 binary_integer := 0;
DBGPLSQL: 13 TEXTNOD = p2 binary_integer;
DBGPLSQL: 14 TEXTNOD = p3 binary_integer;
DBGPLSQL: 15 TEXTNOD = p4 binary_integer;
DBGPLSQL: 16 TEXTNOD = p5 binary_integer;
DBGPLSQL: 17 TEXTNOD = t1 varchar2(1025);
DBGPLSQL: 18 TEXTNOD = t2 varchar2(1);
DBGPLSQL: 19 TEXTNOD = t3 varchar2(1);
DBGPLSQL: 20 TEXTNOD = begin
DBGPLSQL: 21 TEXTNOD =
DBGPLSQL: 22 PRMVAL = lsequence := null;
DBGPLSQL: 23 TEXTNOD =
DBGPLSQL: 24 PRMVAL = lcfaudate := null;
DBGPLSQL: 25 TEXTNOD =
DBGPLSQL: 26 PRMVAL = lbautfmt := null;
DBGPLSQL: 27 TEXTNOD =
DBGPLSQL: 28 PRMVAL = rsid := 5708; rsts := 791817232;
DBGPLSQL: 29 TEXTNOD = setBackupParams(FALSE);
DBGPLSQL: 30 TEXTNOD = if (krmicd.getParams(1, p2, p3, p4, p5, t1, t2, t3)) then
DBGPLSQL: 31 TEXTNOD = p1 := 1;
DBGPLSQL: 32 TEXTNOD = end if;
DBGPLSQL: 33 TEXTNOD = sys.dbms_backup_restore.setRmanStatusRowId(rsid=>rsid, rsts=>rsts);
DBGPLSQL: 34 TEXTNOD = sys.dbms_backup_restore.DoAutobackup(ncopies => ncopies,
DBGPLSQL: 35 TEXTNOD = cfaudate => lcfaudate,
DBGPLSQL: 36 TEXTNOD = seq => lsequence,
DBGPLSQL: 37 TEXTNOD = format => lbautfmt,
DBGPLSQL: 38 TEXTNOD = p1 => p1,
DBGPLSQL: 39 TEXTNOD = p2 => p2,
DBGPLSQL: 40 TEXTNOD = p3 => p3,
DBGPLSQL: 41 TEXTNOD = p4 => t1);
DBGPLSQL: 42 TEXTNOD = copyno := 0;
DBGPLSQL: 43 TEXTNOD = loop
DBGPLSQL: 44 TEXTNOD = exit when copyno=ncopies;
DBGPLSQL: 45 TEXTNOD = sys.dbms_backup_restore.backupPieceCrtDupGet(copyno,
DBGPLSQL: 46 TEXTNOD = handle,
DBGPLSQL: 47 TEXTNOD = comment,
DBGPLSQL: 48 TEXTNOD = media);
DBGPLSQL: 49 TEXTNOD = if comment is null then comment := ‘NONE’; end if;
DBGPLSQL: 50 TEXTNOD = krmicd.writeMsg(8503, handle, comment);
DBGPLSQL: 51 TEXTNOD = copyno := copyno + 1;
DBGPLSQL: 52 TEXTNOD = end loop;
DBGPLSQL: 53 TEXTNOD = sys.dbms_backup_restore.setRmanStatusRowId(rsid=>0, rsts=>0);
DBGPLSQL: 54 TEXTNOD = end;
DBGMISC: executing command Control File and SPFILE Autobackup [13:13:53.138]
DBGRPC: krmxpoq: xc=6917529027645961080, action=”0000003 FINISHED66″, col_l=18, ind=0, sid=1475
DBGRPC: krmxr: xc=6917529027645961080 chid=default rpc count=3
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000021 FINISHED129″, col_l=19, ind=0, sid=1870
DBGRPC: krmxr: xc=6917529027645974080 chid=ORA_DISK_1 rpc count=21
DBGRPC: ENTERED krmqgns
DBGRPC: krmqgns: looking for work for channel default (krmqgns)
DBGRPC: krmqgns: commands remaining to be executed: (krmqgns)
DBGRPC: CMD type=Control File and SPFILE Autobackup id=1 status=NOT STARTED
DBGRPC: 1 STEP id=1 status=NOT STARTED
DBGRPC: krmqgns: no work found for channel default (krmqgns)
DBGRPC: (krmqgns)
DBGRPC: EXITED krmqgns with status 1
DBGRPC: ENTERED krmqgns
DBGRPC: krmqgns: looking for work for channel ORA_DISK_1 (krmqgns)
DBGRPC: krmqgns: commands remaining to be executed: (krmqgns)
DBGRPC: CMD type=Control File and SPFILE Autobackup id=1 status=NOT STARTED
DBGRPC: 1 STEP id=1 status=NOT STARTED
DBGRPC: krmqgns: channel ORA_DISK_1 assigned step 1 (krmqgns)
DBGRPC: (krmqgns)
DBGRPC: EXITED krmqgns with status 0
DBGRPC: krmxcic: xc=6917529027645974080 chid=ORA_DISK_1 calling peidcs
DBGRPC: krmxcis: xc=6917529027645974080 chid=ORA_DISK_1 calling pcicmp
DBGRPC: krmxr: xc=6917529027645974080 chid=ORA_DISK_1 calling peicnt
DBGMISC: ENTERED krmzgparms [13:13:53.152]
DBGMISC: Step id = 1; Code = 1 [13:13:53.152] (krmzgparms)
DBGMISC: EXITED krmzgparms with status 0 (FALSE) [13:13:53.152] elapsed time [00:00:00:00.000]
DBGMISC: ENTERED krmzgparms [13:13:53.152]
DBGMISC: Step id = 1; Code = 1 [13:13:53.152] (krmzgparms)
DBGMISC: EXITED krmzgparms with status 0 (FALSE) [13:13:53.152] elapsed time [00:00:00:00.000]
DBGRPC: krmxrpc: xc=6917529027645974080 kpurpc2 rc=0 db=target proc=DBMS_BACKUP_RESTORE.SETRMANSTATUSROWID
DBGRPC: krmxrpc: xc=6917529027645974080 chid=ORA_DISK_1 rpc count(non-blocking)=22
DBGRPC: krmxrpc: xc=6917529027645974080 RPC #22 completed immediately
DBGRPC: krmxrpc: xc=6917529027645974080 kpurpc2 rc=3123 db=target proc=DBMS_BACKUP_RESTORE.DOAUTOBACKUP
DBGRPC: krmxrpc: xc=6917529027645974080 chid=ORA_DISK_1 rpc count=23
DBGRPC: krmxrpc: xc=6917529027645974080 starting longrunning RPC #23 to target: DBMS_BACKUP_RESTORE.DOAUTOBACKUP
DBGRPC: krmxr: xc=6917529027645974080 started long running rpc
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000022 FINISHED129″, col_l=19, ind=0, sid=1870
DBGRPC: krmxr: callback returned TRUE, skipping sleep
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 1 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 2 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 4 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 8 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111″, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds
DBGRPC: krmxpoq: xc=6917529027645974080, action=”0000023 STARTED111”, col_l=18, ind=0, sid=1870
DBGRPC: krmxr: sleeping for 10 seconds

对RMAN相关进程做stack call的追踪

select action from gv$session where sid=1782 and serial#=62996 and inst_id=2

rman.log

-rw-r—– 1 oracle oinstall 56475 Aug 20 13:13 mac_ora_29364.trc
-rw-r—– 1 oracle oinstall 439863 Aug 20 13:13 mac_ora_28147.trc

mac> select spid from v$process where addr in ( select paddr from v$session where module like ‘rman%’);

SPID
————
27957
26914

mac>
mac>
mac> oradebug setospid 27957;
Oracle pid: 275, Unix process pid: 27957, image: oracle@mfs138 (TNS V1-V3)
mac> oradebug short_stack;
ksdxfstk()+48<-ksdxcb()+5776<-sspuser()+640<-<-_read_sys()+48<-_read()+224<-sntpread()+80<-ntprd()+192<-nsprecv()+736<-nsrdr()+272<-nsdo()+12512<-nsbrecv()+80<-nioqrc()+704<-opikndf2()+1216<-opitsk()+1280<-opiino()+1840<-opiodr()+2128<-opidrv()+1088<-sou2o()+336<-opimai_real()+224<-main()+368 oradebug short_stack;
ksdxfstk()+48<-ksdxcb()+5776<-sspuser()+640<-<-_read_sys()+48<-_read()+224<-sntpread()+80<-ntprd()+192<-nsprecv()+736<-nsrdr()+272<-nsdo()+12512<-nsbrecv()+80<-nioqrc()+704<-opikndf2()+1216<-opitsk()+1280<-opiino()+1840<-opiodr()+2128<-opidrv()+1088<-sou2o()+336<-opimai_real()+224<-main()+368 oradebug short_stack;
ksdxfstk()+48<-ksdxcb()+5776<-sspuser()+640<-<-_read_sys()+48<-_read()+224<-sntpread()+80<-ntprd()+192<-nsprecv()+736<-nsrdr()+272<-nsdo()+12512<-nsbrecv()+80<-nioqrc()+704<-opikndf2()+1216<-opitsk()+1280<-opiino()+1840<-opiodr()+2128<-opidrv()+1088<-sou2o()+336<-opimai_real()+224<-main()+368
mac> oradebug setospid 26914
Oracle pid: 463, Unix process pid: 26914, image: oracle@mfs138 (TNS V1-V3)
mac> oradebug short_stack
ksdxfstk()+48<-ksdxcb()+5776<-sspuser()+640<-<-_read_sys()+48<-_read()+224<-sntpread()+80<-ntprd()+192<-nsprecv()+736<-nsrdr()+272<-nsdo()+12512<-nsbrecv()+80<-nioqrc()+704<-opikndf2()+1216<-opitsk()+1280<-opiino()+1840<-opiodr()+2128<-opidrv()+1088<-sou2o()+336<-opimai_real()+224<-main()+368 oradebug short_stack
ksdxfstk()+48<-ksdxcb()+5776<-sspuser()+640<-<-_read_sys()+48<-_read()+224<-sntpread()+80<-ntprd()+192<-nsprecv()+736<-nsrdr()+272<-nsdo()+12512<-nsbrecv()+80<-nioqrc()+704<-opikndf2()+1216<-opitsk()+1280<-opiino()+1840<-opiodr()+2128<-opidrv()+1088<-sou2o()+336<-opimai_real()+224<-main()+368 oradebug short_stack
ksdxfstk()+48<-ksdxcb()+5776<-sspuser()+640<-<-_read_sys()+48<-_read()+224<-sntpread()+80<-ntprd()+192<-nsprecv()+736<-nsrdr()+272<-nsdo()+12512<-nsbrecv()+80<-nioqrc()+704<-opikndf2()+1216<-opitsk()+1280<-opiino()+1840<-opiodr()+2128<-opidrv()+1088<-sou2o()+336<-opimai_real()+224<-main()+368<-main_opd_entry()+80

oradebug dump errorstack 3;
Statement processed.

oradebug tracefile_name
/apps/oracle/admin/mac/udump/mac_ora_26914.trc

pstack 27957
27957: /apps/oracle/product/10.2.0/bin/oracle

——————————– lwpid : 5899967 ——————————-

0: c000000000405690 : _read_sys() + 0x30 (/usr/lib/hpux64/libc.so.1)
1: c000000000419f00 : _read() + 0xe0 (/usr/lib/hpux64/libc.so.1)
2: 40000000020d7ad0 : sntpread() + 0x50 (/apps/oracle/product/10.2.0/bin/oracle)
3: 40000000020d7a20 : ntprd() + 0xc0 (/apps/oracle/product/10.2.0/bin/oracle)
4: 400000000aa3b7c0 : nsprecv() + 0x2e0 (/apps/oracle/product/10.2.0/bin/oracle)
5: 4000000002307bb0 : nsrdr() + 0x110 (/apps/oracle/product/10.2.0/bin/oracle)
6: 4000000002300180 : nsdo() + 0x30e0 (/apps/oracle/product/10.2.0/bin/oracle)
7: 40000000022fcfa0 : nsbrecv() + 0x50 (/apps/oracle/product/10.2.0/bin/oracle)
8: 4000000002aff570 : nioqrc() + 0x2c0 (/apps/oracle/product/10.2.0/bin/oracle)
9: 4000000002bd3c80 : opikndf2() + 0x4c0 (/apps/oracle/product/10.2.0/bin/oracle)
10: 4000000002d9f3f0 : opitsk() + 0x500 (/apps/oracle/product/10.2.0/bin/oracle)
11: 400000000268c3f0 : opiino() + 0x730 (/apps/oracle/product/10.2.0/bin/oracle)
12: 4000000002cd6ec0 : opiodr() + 0x850 (/apps/oracle/product/10.2.0/bin/oracle)
13: 400000000260fd80 : opidrv() + 0x440 (/apps/oracle/product/10.2.0/bin/oracle)
14: 400000000260f390 : sou2o() + 0x150 (/apps/oracle/product/10.2.0/bin/oracle)
15: 40000000025fbfc0 : opimai_real() + 0xe0 (/apps/oracle/product/10.2.0/bin/oracle)
16: 400000000250c880 : main() + 0x170 (/apps/oracle/product/10.2.0/bin/oracle)
17: c000000000032f90 : main_opd_entry() + 0x50 (/usr/lib/hpux64/dld.so)

pstack 26914
26914: /apps/oracle/product/10.2.0/bin/oracle

——————————– lwpid : 5898924 ——————————-

0: c000000000405690 : _read_sys() + 0x30 (/usr/lib/hpux64/libc.so.1)
1: c000000000419f00 : _read() + 0xe0 (/usr/lib/hpux64/libc.so.1)
2: 40000000020d7ad0 : sntpread() + 0x50 (/apps/oracle/product/10.2.0/bin/oracle)
3: 40000000020d7a20 : ntprd() + 0xc0 (/apps/oracle/product/10.2.0/bin/oracle)
4: 400000000aa3b7c0 : nsprecv() + 0x2e0 (/apps/oracle/product/10.2.0/bin/oracle)
5: 4000000002307bb0 : nsrdr() + 0x110 (/apps/oracle/product/10.2.0/bin/oracle)
6: 4000000002300180 : nsdo() + 0x30e0 (/apps/oracle/product/10.2.0/bin/oracle)
7: 40000000022fcfa0 : nsbrecv() + 0x50 (/apps/oracle/product/10.2.0/bin/oracle)
8: 4000000002aff570 : nioqrc() + 0x2c0 (/apps/oracle/product/10.2.0/bin/oracle)
9: 4000000002bd3c80 : opikndf2() + 0x4c0 (/apps/oracle/product/10.2.0/bin/oracle)
10: 4000000002d9f3f0 : opitsk() + 0x500 (/apps/oracle/product/10.2.0/bin/oracle)
11: 400000000268c3f0 : opiino() + 0x730 (/apps/oracle/product/10.2.0/bin/oracle)
12: 4000000002cd6ec0 : opiodr() + 0x850 (/apps/oracle/product/10.2.0/bin/oracle)
13: 400000000260fd80 : opidrv() + 0x440 (/apps/oracle/product/10.2.0/bin/oracle)
14: 400000000260f390 : sou2o() + 0x150 (/apps/oracle/product/10.2.0/bin/oracle)
15: 40000000025fbfc0 : opimai_real() + 0xe0 (/apps/oracle/product/10.2.0/bin/oracle)
16: 400000000250c880 : main() + 0x170 (/apps/oracle/product/10.2.0/bin/oracle)
17: c000000000032f90 : main_opd_entry() + 0x50 (/usr/lib/hpux64/dld.so)

uname -a
HP-UX B.11.31 U ia64 unlimited-user license

Workaround:

没有找到直接解决该问题的方法, (从HP-UX上迁移走似乎是一种不可行的方案),可以通过configure autobackup off绕过该问题,在RMAN备份脚本中加入backup current controlfile可以起来类似的作用。

如何跟踪Oracle动态服务注册

如何trace Oracle PMON进程动态注册过程?这个问题我想到2个答案,对PMON做event trace或者采用Oracle Network Server因该都可以达到目的。
让我们来实践一下!

Oracle Network Server Trace模式

1. 启用Oracle SqlNet服务器端trace,这需要我们修改sqlnet.ora配置文件

[maclean@rh2 ~]$ echo "TRACE_LEVEL_SERVER = 16
> TRACE_FILE_SERVER = SERVER
> TRACE_DIRECTORY_SERVER= /home/maclean/ntrc"  > $ORACLE_HOME/network/admin/sqlnet.ora
[maclean@rh2 ~]$ cat $ORACLE_HOME/network/admin/sqlnet.ora
TRACE_LEVEL_SERVER = 16
TRACE_FILE_SERVER = SERVER
TRACE_DIRECTORY_SERVER= /home/maclean/ntrc

2. 触发trace

SQL> conn / as sysdba
Connected.

SQL>  select spid from V$process, V$session where audsid=userenv('SESSIONID') and paddr=addr;
SPID
------------
4264

SQL> alter system register;
System altered.

/*在之前指定的TRACE_DIRECTORY_SERVER目录下将出现形如server_$spid.trc的trace文件*/

[maclean@rh2 ntrc]$ cat server_4290.trc|grep nsprecv|grep -A 2 -B 2 reg
[20-AUG-2010 10:42:53:896] nsprecv: 00 00 00 00 00 15 61 6C  |......al|
[20-AUG-2010 10:42:53:896] nsprecv: 74 65 72 20 73 79 73 74  |ter.syst|
[20-AUG-2010 10:42:53:896] nsprecv: 65 6D 20 72 65 67 69 73  |em.regis|
[20-AUG-2010 10:42:53:896] nsprecv: 74 65 72 01 00 00 00 01  |ter.....|
[20-AUG-2010 10:42:53:896] nsprecv: 00 00 00 00 00 00 00 00  |........|

/*分析该trace文件后可以匹配到以上动态注册语句*/

/*记得将server端sqlnet trace设置disable掉*/

[maclean@rh2 ntrc]$ echo "" > $ORACLE_HOME/network/admin/sqlnet.ora

PMON TRACE模式
1.找出PMON的进程号

SQL> select spid ,program from v$process where program like '%PMON%';

SPID         PROGRAM
------------ ------------------------------------------------
4050         oracle@rh2 (PMON)

2.执行10257事件trace

SQL> oradebug setospid 4050;
Oracle pid: 2, Unix process pid: 4050, image: oracle@rh2 (PMON)

SQL> oradebug event 10257 trace name context forever,level 16;
Statement processed.

SQL> alter system register;
System altered.

SQL> oradebug event 10257 trace name context off;
Statement processed.

SQL> oradebug tracefile_name;
/s01/10gdb/admin/YOUYUS/bdump/youyus_pmon_4050.trc

cat /s01/10gdb/admin/YOUYUS/bdump/youyus_pmon_4050.trc
.......................
kmmlrl: register now
kmmgdnu: cXDB
         goodness=0, delta=1,
         flags=0x5:unblocked/not overloaded, update=0x6:G/D/-
kmmgdnu: YOUYUS
         goodness=0, delta=1,
         flags=0x4:unblocked/not overloaded, update=0x6:G/D/-
kmmlrl: nsgr update returned 0
kmmlrl: nsgr register returned 0

/*可以看到注册了YOUYUS和cXDB2个service的过程*/

若无法正常注册可以按照以下步骤检查:
1. 检查Oracle Net命名方式是否正确设置,该参数由sqlnet.ora配置文件中的NAMES.DIRECTORY_PATH指定。
2. 确认SQL NET配置文件如sqlnet.ora,tnsnames.ora等的位置正确配载。
3. 检查是否设置了TNS_ADMIN环境变量,该变量将影响配置文件的正确路径。
4. 确认LOCAL_LISTENER或REMOTE_LISTENER中指定的service可以被正常tnsping通,若以上参数未指定值则尝试步骤6。
5. 确认主机名可以被正确解析为ip地址,如以下示例:

C:\Users\weisly>nslookup www.oracle.com
服务器:  dir-605
Address:  192.168.0.1

非权威应答:
名称:    a398.g.akamai.net.0.1.cn.akamaitech.net
Addresses:  117.104.136.98
          117.104.136.128
Aliases:  www.oracle.com
          www.oracle.com.edgesuite.net
          a398.g.akamai.net

6. 修改LOCAL_LISTENER为非服务别名解析的形式,这样可以排除配置文件可能造成的影响,从而确认问题是否由配置文件设置不当而引起:

SQL> conn / as sysdba
Connected.

SQL> alter system set local_listener='(DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=rh2)(PORT=1521)))';
System altered.

SQL> alter system set REMOTE_LISTENER=' (ADDRESS_LIST =(ADDRESS = (PROTOCOL = TCP)(HOST = rh1)(PORT = 1521))(ADDRESS = (PROTOCOL = TCP)(HOST = rh2)(PORT = 1521)))';
System altered.

7. 将主机名替换为ip地址并测试是否解决问题。
8. 以IPC协议替代常见的TCP协议测试,绕过TCP和主机名等因素可能造成的问题,以确认问题是否由这些因素引起:

SQL> alter system set local_listener='(DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=KEY1)))';
System altered.

/*其中KEY值需要和listener.ora中指定的一致。*/

SQL> host
[maclean@rh2 admin]$ lsnrctl status KEY1

LSNRCTL for Linux: Version 10.2.0.4.0 - Production on 20-AUG-2010 11:30:06
Copyright (c) 1991, 2007, Oracle.  All rights reserved.
Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=KEY1)))
STATUS of the LISTENER
------------------------
Alias                     KEY1
Version                   TNSLSNR for Linux: Version 10.2.0.4.0 - Production
Start Date                20-AUG-2010 11:29:15
Uptime                    0 days 0 hr. 0 min. 50 sec
Trace Level               off
Security                  ON: Local OS Authentication
SNMP                      OFF
Listener Parameter File   /s01/10gdb/network/admin/listener.ora
Listener Log File         /s01/10gdb/network/log/key1.log
Listening Endpoints Summary...
  (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=KEY1)))
Services Summary...
Service "YOUYUS" has 1 instance(s).
  Instance "YOUYUS", status READY, has 1 handler(s) for this service...
Service "YOUYUS_XPT" has 1 instance(s).
  Instance "YOUYUS", status READY, has 1 handler(s) for this service...
Service "cXDB" has 1 instance(s).
  Instance "YOUYUS", status READY, has 10 handler(s) for this service...
The command completed successfully

实在不行的话,我们还是提SR吧!

ORA-07445: [__lwp_kill()+8] [SIGIOT]错误一例

这是一套SunOS 5.10上的10.2.0.3的RAC系统,8月初告警日志中陆续出现以下记录:

Tue Aug  3 15:17:04 2010
Errors in file /u01/app/oracle/admin/prsi061/udump/prsi061a_ora_27774.trc:
ORA-07445: exception encountered: core dump [__lwp_kill()+8] [SIGIOT] [unknown code] [0x6C7E00000000] [] []

SIGIOT信号伴随7445错误出现并不多见,因为该信号一般是用来实现相关的硬件异常的。
我们可以欣赏一下这个trace文件
trace文件中的堆栈信息如下:

ksedmp()+744         CALL     ksedst()             000000840 ? 1066C60CC ?
                                                   000000000 ? 1066C2BC0 ?
                                                   1066C1928 ? 1066C2328 ?
ssexhd()+1240        CALL     ksedmp()             000106400 ? 106530764 ?
                                                   106530000 ? 000106530 ?
                                                   000106400 ? 106530764 ?
__sighndlr()+12      PTR_CALL 0000000000000000     10652D000 ? 1066C9EF0 ?
                                                   10652A72C ? 00010652D ?
                                                   000000006 ? 000000067 ?
call_user_handler()  CALL     __sighndlr()         000000006 ? 1066C9EF0 ?
+992                                               1066C9C10 ? 10033B1C0 ?
                                                   000000000 ? 000000005 ?
sigacthandler()+84   CALL     call_user_handler()  FFFFFFFF7D500200 ?
                                                   FFFFFFFF7D500200 ?
                                                   1066C9C10 ? 000000009 ?
                                                   000000000 ? 000000000 ?
__lwp_kill()+8       PTR_CALL 0000000000000000     000000000 ? 1066C9EF0 ?
                                                   1066C9C10 ?
                                                   FFFFFFFF7D500200 ?
                                                   000000000 ?
                                                   FFFFFFFF7C73C000 ?
raise()+16           FRM_LESS _pthread_kill()      000000000 ? 000000006 ?
                                                   FFFFFFFF7F60AC48 ?
                                                   FFFFFFFF7C54B048 ?
                                                   000000005 ?
                                                   FFFFFFFF7C74CB50 ?
abort()+208          CALL     raise()              000000006 ? 000000006 ?
                                                   000000005 ?
                                                   FFFFFFFF7C748500 ?
                                                   FFFFFFFF7D500200 ?
                                                   000000005 ?
vcsipc_poll()+1724   CALL     FFFFFFFF7F5477E0     000001DA0 ?
                                                   FFFFFFFF7F550D00 ?
                                                   FFFFFFFF7F4205A8 ?
                                                   0001F107C ? 000000001 ?
                                                   000000000 ?
skgxpwait()+5604     CALL     vcsipc_poll()        FFFFFFFF7FFECE90 ?
                                                   106747378 ? 000001FD0 ?
                                                   FFFFFFFF7FFE78C8 ?
                                                   000001C00 ? 000200000 ?
ksxpwait()+1804      CALL     0000000106524980     FFFFFFFF7F54FC28 ?
                                                   106747378 ? 000000000 ?
                                                   FFFFFFFF7FFECF68 ?
                                                   0000004E2 ?
                                                   FFFFFFFF7FFECE90 ?
ksliwat()+2952       CALL     ksxpwait()           000000000 ? 000101000 ?
                                                   000000000 ? 10652DB98 ?
                                                   000001000 ? 106533FC8 ?
kslwaitns_timed()+4  CALL     ksliwat()            000000000 ? 000000002 ?
8                                                  00000007D ? 5798B6C18 ?
                                                   5798B6BA0 ? 000032033 ?
kskthbwt()+232       CALL     kslwaitns_timed()    00000007D ? 000000001 ?
                                                   00000007C ? 000000000 ?
                                                   FFFFFFFF7FFED3B8 ?
                                                   000000001 ?
kslwait()+116        CALL     kskthbwt()           00000007D ? 00000007C ?
                                                   000000000 ? 000000007 ?
                                                   000032033 ? 000000001 ?
ksxprcv()+916        CALL     kslwait()            0925A2B0A ? 000000000 ?
                                                   00000000A ? 00000000A ?
                                                   000032033 ? 000000001 ?
kclwcrs()+960        CALL     ksxprcv()            0001056DE ? 10652B118 ?
                                                   00000007D ? 1056DE598 ?
                                                   00010652A ? 1056DE000 ?
kclgclk()+10052      CALL     kclwcrs()            3800143A8 ? 000000000 ?
                                                   000000000 ? 519F716A0 ?
                                                   000000007 ? 000106535 ?
kcbzib()+19288       CALL     kclgclk()            000106400 ? 00000000C ?
                                                   FFFFFFFF7FFF5EB8 ?
                                                   000000000 ? 000000000 ?
                                                   000105400 ?
kcbgtcr()+10528      CALL     kcbzib()             5665FB520 ?
                                                   FFFFFFFF7C058170 ?
                                                   000105C00 ? 000000000 ?
                                                   000000006 ?
                                                   FFFFFFFF7FFF44A0 ?
ktrget()+260         CALL     kcbgtcr()            FFFFFFFF7FFF5028 ?
                                                   FFFFFFFF7FFF502C ?
                                                   5665FB520 ? 000000000 ?
                                                   000000000 ? 57FF6DA18 ?
kdst_fetch()+872     CALL     ktrget()             FFFFFFFF7C058160 ?
                                                   FFFFFFFF7C0580E0 ?
                                                   00000023F ? 000000000 ?
                                                   FFFFFFFF7C058170 ?
                                                   3800172B8 ?
kdstf0100101km()+50  CALL     kdst_fetch()         FFFFFFFF7C058158 ?
4                                                  000000000 ?
                                                   FFFFFFFF7FFF5688 ?
                                                   000106528 ? 00000023F ?
                                                   00000FC00 ?
kdsttgr()+27872      CALL     kdstf0100101km()     FFFFFFFF7C058158 ?
                                                   4E6AB809E ? 000000001 ?
                                                   000000000 ? 54C540BB8 ?
                                                   FFFFFFFF7C058038 ?
qertbFetch()+720     CALL     kdsttgr()            000000000 ? 000000000 ?
                                                   FFFFFFFF7C054EA8 ?
                                                   FFFFFFFF7C058158 ?
                                                   000000004 ? 1032109C0 ?
qerflFetch()+172     PTR_CALL 0000000000000000     000000001 ? 000000001 ?
                                                   1056DE068 ?
                                                   FFFFFFFF7FFF6348 ?
                                                   10652B298 ? 000000002 ?
opifch2()+8204       PTR_CALL 0000000000000000     FFFFFFFF7C058898 ?
                                                   102527EE0 ?
                                                   FFFFFFFF7FFF69D0 ?
                                                   000000001 ? 103210000 ?
                                                   10320CA00 ?
opifch()+52          CALL     opifch2()            FFFFFFFF7FFF6878 ?
                                                   000000090 ? 000000000 ?
                                                   000000001 ? 000000000 ?
                                                   105A2C000 ?
opipls()+3532        CALL     opifch()             000000005 ? 000000002 ?
                                                   FFFFFFFF7FFF6F20 ?
                                                   000000002 ? 000000000 ?
                                                   000000001 ?
opiodr()+1548        PTR_CALL 0000000000000000     000106400 ? 10653A000 ?
                                                   000105800 ? 000000010 ?
                                                   00010653A ?
                                                   FFFFFFFF7B6392D8 ?
rpidrus()+196        CALL     opiodr()             10576DC08 ? 000000066 ?
                                                   10652B000 ? 000000001 ?
                                                   FFFFFFFF7C03A830 ?
                                                   00010652D ?
skgmstack()+168      PTR_CALL 0000000000000000     FFFFFFFF7FFF8350 ?
                                                   000000006 ?
                                                   FFFFFFFF7FFF8100 ?
                                                   10652A000 ? 000000066 ?
                                                   1056DE000 ?
rpidru()+172         CALL     skgmstack()          10034D1E0 ?
                                                   FFFFFFFF7FFF8350 ?
                                                   00000F618 ? 10034D1E0 ?
                                                   FFFFFFFF7FFF8350 ?
                                                   FFFFFFFF7FFF8328 ?
rpiswu2()+500        PTR_CALL 0000000000000000     FFFFFFFF7FFF8B18 ?
                                                   1056C3000 ? 1056C2B90 ?
                                                   1056C0F50 ? 000000C10 ?
                                                   000000182 ?
rpidrv()+1696        CALL     rpiswu2()            000000000 ? 10652B298 ?
                                                   000000000 ?
                                                   FFFFFFFF7FFF84E8 ?
                                                   1056DE000 ? 00010652A ?
psddr0()+516         CALL     rpidrv()             FFFFFFFF7FFF8EC0 ?
                                                   000105C00 ?
                                                   FFFFFFFF7FFF89C4 ?
                                                   000000002 ?
                                                   FFFFFFFF7B615F60 ?
                                                   00010652D ?
psdnal()+512         CALL     psddr0()             106541CE0 ? 10652B298 ?
                                                   000000066 ? 1056DE068 ?
                                                   000000008 ? 00000000A ?
pevm_BFTCHC()+308    PTR_CALL 0000000000000000     FFFFFFFF7FFF9CA8 ?
                                                   00000000A ? 000000000 ?
                                                   FFFFFFFF7B6396F8 ?
                                                   106537000 ? 10652B000 ?
pfrinstr_FTCHC()+18  CALL     pevm_BFTCHC()        000000000 ? 105AE7600 ?
0                                                  555E62580 ?
                                                   FFFFFFFF7C069EE8 ?
                                                   FFFFFFFF7B6396F8 ?
                                                   000000000 ?
pfrrun_no_tool()+72  PTR_CALL 0000000000000000     000000000 ? 000000000 ?
                                                   FFFFFFFF7C069F50 ?
                                                   FFFFFFFF7C069EE8 ?
                                                   0000001EE ? 555E62892 ?
pfrrun()+832         CALL     pfrrun_no_tool()     FFFFFFFF7C069EE8 ?
                                                   555E6288E ?
                                                   FFFFFFFF7C069F50 ?
                                                   105B1BF50 ? 000002001 ?
                                                   000002001 ?
plsql_run()+696      CALL     pfrrun()             FFFFFFFF7C035420 ?
                                                   FFFFFFFF7C069EE8 ?
                                                   000002001 ? 000200000 ?
                                                   FFFFFFFF7C069EE8 ?
                                                   0001056DE ?
peicnt()+260         CALL     plsql_run()          000000006 ? 000000000 ?
                                                   FFFFFFFF7B63BBF8 ?
                                                   FFFFFFFF7FFF9888 ?
                                                   000000180 ? 000000007 ?
kkxexe()+616         CALL     peicnt()             FFFFFFFF7FFFA808 ?
                                                   10652B298 ? 106541CE0 ?
                                                   106762258 ? 10652B000 ?
                                                   10652B000 ?
opiexe()+12736       CALL     kkxexe()             FFFFFFFF7B63F4B8 ?
                                                   106537000 ? 000106537 ?
                                                   FFFFFFFF7FFF9CA8 ?
                                                   000000000 ? 54C0616F0 ?
kpoal8()+1912        CALL     opiexe()             000106400 ?
                                                   FFFFFFFF7C056EC0 ?
                                                   000000000 ? 000000000 ?
                                                   000000000 ? 57FDB9250 ?
opiodr()+1548        PTR_CALL 0000000000000000     0BFFFFC00 ? 000040008 ?
                                                   000000000 ? 000000820 ?
                                                   000105800 ? 106538260 ?
ttcpip()+1284        PTR_CALL 0000000000000000     10576DC08 ? 00000005E ?
                                                   10652B000 ? 000000001 ?
                                                   FFFFFFFF7C03A830 ?
                                                   00010652D ?
opitsk()+1432        CALL     ttcpip()             000000017 ?
                                                   FFFFFFFF7FFFCFB0 ?
                                                   1056C3F6C ? 1056C1750 ?
                                                   000000000 ? 10652B118 ?
opiino()+1128        CALL     opitsk()             106538268 ? 000000001 ?
                                                   000000000 ? 106538260 ?
                                                   1058884D0 ? 0FFFFFFFD ?
opiodr()+1548        PTR_CALL 0000000000000000     000106400 ? 10652DB98 ?
                                                   000106400 ? 10652D000 ?
                                                   000106400 ? 106538260 ?
opidrv()+896         CALL     opiodr()             1065373D8 ? 00000003C ?
                                                   000106400 ? 1065381E0 ?
                                                   000106538 ? 00010652D ?
sou2o()+80           CALL     opidrv()             10653A960 ? 000000000 ?
                                                   00000003C ? 106537698 ?
                                                   00000003C ? 000000000 ?
opimai_real()+124    CALL     sou2o()              FFFFFFFF7FFFF708 ?
                                                   00000003C ? 000000004 ?
                                                   FFFFFFFF7FFFF730 ?
                                                   105E12000 ? 000105E12 ?
main()+152           CALL     opimai_real()        000000002 ?
                                                   FFFFFFFF7FFFF808 ?
                                                   104054D6C ? 1064D3220 ?
                                                   00247E3B4 ? 000014800 ?
_start()+380         CALL     main()               000000002 ? 000000008 ?
                                                   000000000 ?
                                                   FFFFFFFF7FFFF818 ?
                                                   FFFFFFFF7FFFF928 ?
                                                   FFFFFFFF7D500200 ?

经过和MOS确认,认为是apply了Patch 5165885后引起的新问题:

I have checked our internal bug database and issue seems to be occuring due to fix for Bug.5165885.

Action plan:
=============

Apply patch for 6678154

https://updates.oracle.com/download/6678154.html

Workaround:
————–

Remove the patch for 5165885 .

Yes, Symptoms are pointing finger towards this bug. I would recommend to apply the patch rather than going for workarounds.

这个case目前实施了补丁6678154,仍在观察期。
录以记之!

利用FORCE_MATCHING_SIGNATURE捕获非绑定变量SQL

做为一个DBA,你大概习惯了定期要抓取数据库中的非绑定变量SQL,这些SQL经常扮演着一箱苹果中蛀虫的角色。
看到下列SQL你必定觉得眼熟:

SELECT substr(sql_text, 1, 80), count(1)
  FROM v$sql
 GROUP BY substr(sql_text, 1, 80)
HAVING count(1) > 10
 ORDER BY 2

是的,以上这段抓取literal sql的脚本大约从8i时代就开始流行了,在那时它很popular也很休闲,使用它或许还会给你的雇主留下一丝神秘感。不过今天我要告诉你的是,它彻底过时了,落伍了,已经不是fashion master了。
10g以后v$SQL动态性能视图增加了FORCE_MATCHING_SIGNATURE列,其官方定义为”The signature used when the CURSOR_SHARING parameter is set to FORCE”,也就是Oracle通过将原SQL_TEXT转换为可能的FORCE模式后计算得到的一个SIGNATURE值。这么说可能不太形象,我们来具体看一下:

SQL> create table YOUYUS (t1 int);
Table created.

SQL> alter system flush shared_pool;
System altered.

SQL>select /*test_matching_a*/ * from YOUYUS where t1=1;
no rows selected

SQL>select /*test_matching_a*/ * from YOUYUS where t1=2;
no rows selected

SQL>select /*test_matching_a*/ * from YOUYUS where t1=3;
no rows selected

SQL> col sql_text format a55;
SQL> select sql_text, FORCE_MATCHING_SIGNATURE, EXACT_MATCHING_SIGNATURE
  2    FROM V$SQL
  3   WHERE sql_text like '%test_matching_a%'
  4     and sql_text not like '%like%';

SQL_TEXT                                                FORCE_MATCHING_SIGNATURE EXACT_MATCHING_SIGNATURE
------------------------------------------------------- ------------------------ ------------------------
select /*test_matching_a*/ * from YOUYUS where t1=2          4.59124694481197E18      1.00267830752731E19
select /*test_matching_a*/ * from YOUYUS where t1=3          4.59124694481197E18      1.61270448861426E19
select /*test_matching_a*/ * from YOUYUS where t1=1          4.59124694481197E18      1.36782048270058E18

/*以上将变量硬编码至SQL中的游标,FORCE_MATCHING_SIGNATURE值完全相同,而EXACT_MATCHING_SIGNATURE值各有不同。FORCE_MATCHING_SIGNATURE值相同说明在游标共享FORCE模式下,这些游标满足CURSOR SHARING的条件 */

SQL> alter system flush shared_pool;
System altered.
SQL> alter session set cursor_sharing=FORCE;
Session altered.

SQL>select /*test_matching_a*/ * from YOUYUS where t1=1;
no rows selected

SQL>select /*test_matching_a*/ * from YOUYUS where t1=2;
no rows selected

SQL>select /*test_matching_a*/ * from YOUYUS where t1=3;
no rows selected

SQL> col sql_text for a70
SQL> select sql_text, FORCE_MATCHING_SIGNATURE, EXACT_MATCHING_SIGNATURE
  2    FROM V$SQL
  3   WHERE sql_text like '%test_matching_a%'
  4     and sql_text not like '%like%';

SQL_TEXT                                                               FORCE_MATCHING_SIGNATURE EXACT_MATCHING_SIGNATURE
---------------------------------------------------------------------- ------------------------ ------------------------
select /*test_matching_a*/ * from YOUYUS where t1=:"SYS_B_0"                4.59124694481197E18      4.59124694481197E18

/*FORCE模式下将SQL文本中的变量值转换成了:SYS_B形式,EXACT_MATCHING_SIGNATURE也随之等同于FORCE_MATCHING_SIGNATURE了*/

以上演示说明了FORCE_MATCHING_SIGNATURE列可以帮助我们找出那些潜在可以共享的游标(也包括了因非绑定问题造成的游标无法共享),现在我们利用它来完善捕获非绑定变量SQL的脚本:

SQL> alter system flush shared_pool;
System altered.

SQL> select  /*test_matching_b*/ * from YOUYUS where t1=1;
no rows selected

SQL> select  /*test_matching_b*/ * from YOUYUS where t1='1';            //我有引号,我与众不同!
no rows selected

SQL> col sql_text for a70

SQL> select sql_text, FORCE_MATCHING_SIGNATURE, EXACT_MATCHING_SIGNATURE
  2    FROM V$SQL
  3   WHERE sql_text like '%test_matching_b%'
  4     and sql_text not like '%like%';

SQL_TEXT                                                               FORCE_MATCHING_SIGNATURE EXACT_MATCHING_SIGNATURE
---------------------------------------------------------------------- ------------------------ ------------------------
select  /*test_matching_b*/ * from YOUYUS where t1='1'                      1.43666633406896E19      1.83327833675856E19
select  /*test_matching_b*/ * from YOUYUS where t1=1                       1.43666633406896E19      8.05526057286178E18

/*多余的引号也会导致游标无法共享,此时的FORCE_MATCHING_SIGNATURE 也会是一致的*/

select FORCE_MATCHING_SIGNATURE, count(1)
  from v$sql
 where FORCE_MATCHING_SIGNATURE > 0
   and FORCE_MATCHING_SIGNATURE != EXACT_MATCHING_SIGNATURE
 group by FORCE_MATCHING_SIGNATURE
having count(1) > &a
 order by 2;

Enter value for a: 10
old   6: having count(1) > &a
new   6: having count(1) > 10

FORCE_MATCHING_SIGNATURE   COUNT(1)
------------------------ ----------
     8.81463386552502E18         12

So We find it!

在这里再推荐一种来自MOS,find Literal SQL的方法:

How to Find Literal SQL in Shared Pool


Applies to:

PL/SQL – Version: 8.1.7 to 10.2
Information in this document applies to any platform.

Goal

There is no direct way to query the dictionary for literal SQL only.

However the following example will try to exclude all SQL statements in the
shared pool that do use bind variables.

There still might be situations, with statements using subqueries, where the
example still will show SQL statements using bind variables.

Solution

Create the following PL/SQL block:

[maclean@rh2 bin]$ cat  find_literal.sql

set serveroutput on
set linesize 120
--
-- This anonymous PL/SQL block must be executed as INTERNAL or SYS
-- Execute from : SQL*PLUS
-- CAUTION:
-- This sample program has been tested on Oracle Server - Enterprise Edition
-- However, there is no guarantee of effectiveness because of the possibility
-- of error in transmitting or implementing it. It is meant to be used as a
-- template, and it may require modification.
--
declare
b_myadr VARCHAR2(20);
b_myadr1 VARCHAR2(20);
qstring VARCHAR2(100);
b_anybind NUMBER;

cursor my_statement is
select address from v$sql
group by address;

cursor getsqlcode is
select substr(sql_text,1,60)
from v$sql
where address = b_myadr;

cursor kglcur is
select kglhdadr from x$kglcursor
where kglhdpar = b_myadr
and kglhdpar != kglhdadr
and kglobt09 = 0;

cursor isthisliteral is
select kkscbndt
from x$kksbv
where kglhdadr = b_myadr1;

begin

dbms_output.enable(10000000);

open my_statement;
loop
Fetch my_statement into b_myadr;
open kglcur;
fetch kglcur into b_myadr1;
if kglcur%FOUND Then
open isthisliteral;
fetch isthisliteral into b_anybind;
if isthisliteral%NOTFOUND Then
open getsqlcode;
fetch getsqlcode into qstring;
dbms_output.put_line('Literal:'||qstring||' address: '||b_myadr);
close getsqlcode;
end if;
close isthisliteral;
end if;
close kglcur;
Exit When my_statement%NOTFOUND;
End loop;
close my_statement;
end;
/

/*尝试执行*/

SQL> @find_literal
Literal:select inst_id, java_size, round(java_size / basejava_size,  address: 00000000BC6E94E8
Literal:select reason_id, object_id, subobject_id, internal_instance address: 00000000BC5F1D60
Literal:select  DBID, NAME, CREATED, RESETLOGS_CHANGE#, RESETLOGS_TI address: 00000000BC6000B0
Literal:select di.inst_id,di.didbi,di.didbn,to_date(di.dicts,'MM/DD/ address: 00000000BC530DA8
Literal:      declare          vsn  varchar2(20);             begin  address: 00000000BC85A9F8
Literal:SELECT INCARNATION#, RESETLOGS_CHANGE#, RESETLOGS_TIME, PRIO address: 00000000BC829978
Literal:select pos#,intcol#,col#,spare1,bo#,spare2 from icol$ where  address: 00000000BCA84D00
Literal:select SYS_CONTEXT('USERENV', 'SERVER_HOST'), SYS_CONTEXT('U address: 00000000BC771BF0
Literal: select sql_text, FORCE_MATCHING_SIGNATURE, EXACT_MATCHING_S address: 00000000BC4673A8
Literal:select streams_pool_size_for_estimate s,           streams_p address: 00000000BCA58848
Literal:         select open_mode from v$database address: 00000000BC5DF2D0
Literal:select FORCE_MATCHING_SIGNATURE, count(1)   from v$sql  wher address: 00000000BCA91628
Literal:select inst_id, tablespace_name, segment_file, segment_block address: 00000000BC66EF38
Literal:select sum(used_blocks), ts.ts#   from GV$SORT_SEGMENT gv, t address: 00000000BCAA01B0
Literal:BEGIN DBMS_OUTPUT.ENABLE(NULL); END; address: 00000000BC61D2D8
Literal:select value$ from props$ where name = 'GLOBAL_DB_NAME' address: 00000000BC570500
Literal:select count(*) from sys.job$ where (next_date > sysdate) an address: 00000000BC6C53F8
Literal:select java_pool_size_for_estimate s,           java_pool_si address: 00000000BCA65070
Literal:select local_tran_id, global_tran_fmt, global_oracle_id, glo address: 00000000BC5900B8
Literal:select inst_id,kglnaobj,kglfnobj,kglobt03, kglobhs0+kglobhs1 address: 00000000BC921538
Literal:select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname, address: 00000000BCA83E90
Literal:SELECT * FROM V$SQL address: 00000000BCA58BC0
Literal:SELECT ADDRESS FROM V$SQL GROUP BY ADDRESS address: 00000000BC565BE8
Literal:      begin          dbms_rcvman.resetAll;       end; address: 00000000BC759858
Literal:declare b_myadr VARCHAR2(20); b_myadr1 VARCHAR2(20); qstring address: 00000000BC928FF8
Literal:select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, address: 00000000BC898BF8
Literal:select CONF#, NAME, VALUE from GV$RMAN_CONFIGURATION where i address: 00000000BC8CB7F8
Literal:select f.file#, f.block#, f.ts#, f.length from fet$ f, ts$ t address: 00000000BC8CDFE8
Literal:select u.name, o.name, trigger$.sys_evts, trigger$.type#  fr address: 00000000BCA877B8
Literal:select id, name, block_size, advice_status,                  address: 00000000BC636B38
Literal:select incarnation#, resetlogs_change#, resetlogs_time,      address: 00000000BCA94250
Literal:select  INSTANCE_NUMBER , INSTANCE_NAME , HOST_NAME , VERSIO address: 00000000BC62A678
Literal:select ks.inst_id,ksuxsins,ksuxssid,ksuxshst,ksuxsver,ksuxst address: 00000000BC8E5440
Literal:select timestamp, flags from fixed_obj$ where obj#=:1 address: 00000000BC916C78
Literal:select size_for_estimate,                      size_factor * address: 00000000BCA5F830
Literal:select shared_pool_size_for_estimate s,          shared_pool address: 00000000BCA5A350
Literal:select  SQL_TEXT , SQL_FULLTEXT , SQL_ID,  SHARABLE_MEM , PE address: 00000000BC76B3A0
Literal:lock table sys.col_usage$ in exclusive mode nowait address: 00000000BCA05978
Literal:select 'x' from dual  address: 00000000BC583818
Literal:      select name, resetlogs_time,              resetlogs_ch address: 00000000BCA9D430
Literal:select inst_id, sp_size, round(sp_size / basesp_size, 4),  k address: 00000000BC65A9F0
Literal:select userenv('Instance'),  icrid, to_number(icrls),        address: 00000000BC692260
Literal:select shared_pool_size_for_estimate, shared_pool_size_facto address: 00000000BCAE0750
Literal:select INST_ID, RMRNO, RMNAM, RMVAL from X$KCCRM where RMNAM address: 00000000BC8CD778
Literal:select metadata from kopm$  where name='DB_FDO' address: 00000000BC9EBB98
Literal:select java_pool_size_for_estimate, java_pool_size_factor,   address: 00000000BC5B27D0
Literal:SELECT INCARNATION#, INCARNATION#, RESETLOGS_CHANGE#, RESETL address: 00000000BC829C48
Literal:select file# from file$ where ts#=:1 address: 00000000BC87CF18
Literal:select A.inst_id, A.bpid, B.bp_name, A.blksz,                address: 00000000BC802248
Literal:lock table sys.mon_mods$ in exclusive mode nowait address: 00000000BC5CBE68
Literal:lock table sys.mon_mods$ in exclusive mode nowait address: 00000000BC5CBE68

ORA-00600:[qctcte1]内部错误一例

一套AIX上的4节点10.2.0.4 RAC系统在1月份出现实例hang住的现象,并伴随有ORA-00600:[qctcte1]内部错误,trace文件内容如下:

siposrc1_ora_102944.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options
ORACLE_HOME = /oracle/product/10.2.0/db_1
System name: AIX
Node name: jszydb1
Release: 3
Version: 5
Machine: 00CE31834C00
Instance name: siposrc1
Redo thread mounted by this instance: 1
Oracle process number: 34
Unix process pid: 102944, image: oracle@jszydb1

*** ACTION NAME:() 2010-01-18 15:53:11.530
*** MODULE NAME:(JDBC Thin Client) 2010-01-18 15:53:11.530
*** SERVICE NAME:(siposrc) 2010-01-18 15:53:11.530
*** SESSION ID:(2175.6953) 2010-01-18 15:53:11.530
*** 2010-01-18 15:53:11.530
ksedmp: internal or fatal error
ORA-00600: 内部错误代码, 参数: [qctcte1], [0], [], [], [], [], [], []
Current SQL statement for this session:
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_00000"), NVL(SUM(C2),:"SYS_B_00001") FROM (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("SIPO_ECLA$_TEMP") FULL("SIPO_ECLA$_TEMP") NO_PARALLEL_INDEX("SIPO_ECLA$_TEMP") */ :"SYS_B_00002" AS C1, CASE WHEN "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00003" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00004" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00005" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00006" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00007" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00008" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00009" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00010" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00011" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00012" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00013" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00014" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00015" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00016" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00017" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_00018" OR "SIPO_ECLA
.

.
$_TEMP"."SEQ_ID"=:"SYS_B_40000" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_40001" OR "SIPO_ECLA$_TEMP"."SEQ_ID"=:"SYS_B_40002" THEN :"SYS_B_40003" ELSE :"SYS_B_40004" END AS C2 FROM "SIPO_ECLA$_TEMP" SAMPLE BLOCK (:"SYS_B_40005" , :"SYS_B_40006") SEED (:"SYS_B_40007") "SIPO_ECLA$_TEM

STACK
qctcte qctocssm qctcopn qctcopn xtyxcssr xtyopncb qctcopn qctcpqb <- qctcpqbl <- xtydrv <- opitca <- kksFullTypeCheck <- rpiswu2 <- kksSetBindType <- kksfbc <- opiexe <- opiall0 <- opikpr <- opiodr <- rpidrus <- skgmstack <- rpidru <- rpiswu2 <- kprball <- IPRA <- IPRA <- kkedsSel <- kkecdn <- kkotap <- kkoiqb <- kkooqb <- kkoqbc <- apakkoqb <- apaqbdDescendents <- 3d4 <- apaqbdListReverse <- 06c <- apaqbd <- apadrv <- opitca <- kksLoadChild <- kxsGetRuntimeLock <- 810 <- kksfbc <- kkspsc0 <- kksParseCursor <- opiosq0 <- opiall0 <- opial7 <- opiodr <- ttcpip <- opitsk <- opiino <- opiodr <- opidrv

提交SR,MOS认为可能是Bug 6666870,给出以下方案:
There are a large number of possible bugs but Bug 6666870 is the most likely culprit. There is no one off patch available. 10205 is not yet available.

ACTION PLAN:
=============
1.Please disable Cost Based Transformation as a workaround, this can be done in the init.ora/spfile or at the session level, for example:
SQL> alter session set "_optimizer_cost_based_transformation"=off ;

2.Apply the 10205 patch set when it becomes available.

3.If the optimiser change fails to resolve your issue, please advise us of any recent changes to your DB or server?

4.In particular, did you recently apply the CPUJAN2008 Patch?
If so, please see Note.558901.1 Ext/Mod ORA-00600 internal error code, arguments [qctcte1] After Applying CPUJAN2008 Patch

5.If there is a function based index involved, please see;
Note.788124.1 Ext/Pub ORA-00600 [qctcte1] With Function Based Index Access

6.Changing your code to eliminate the parallel clauses may also act as a workaround.

ddl操作是否会产生undo?

ddl是否会产生undo?
这可能是每一个初学Oracle的人都会有的疑问;ddl操作又不能rollback回滚,要什么undo数据呢?
事实是几乎每个ddl操作都会产生undo,我们来探究一下:

SQL> select vs.name, ms.value
  2    from v$mystat ms, v$sysstat vs
  3   where ms.statistic# = vs.statistic#
  4     and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                                   0

SQL> create table YOUYUS (t1 int);
Table created.

SQL>   select vs.name, ms.value
  2      from v$mystat ms, v$sysstat vs
  3     where ms.statistic# = vs.statistic#
  4       and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                                1992

/*create table的ddl语句产生了大约1992 bytes的撤销变化向量*/

SQL> drop table YOUYUS;
Table dropped.

SQL>   select vs.name, ms.value
  2      from v$mystat ms, v$sysstat vs
  3     where ms.statistic# = vs.statistic#
  4       and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                                4528

/* drop table语句产生2563 bytes的undo数据,多于create table;我们可以猜测create table时Oracle需要向基表中insert数据,而drop table时则需要delete/update数据,显然后者产生更多的undo*/

/*我们尝试创建一个由254个列组成的表*/

SQL>     select vs.name, ms.value
  2        from v$mystat ms, v$sysstat vs
  3       where ms.statistic# = vs.statistic#
  4         and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                                   0

create table YOUYUS (
t1 int,
t2 char(4) default 'oooo',
t3 char(4) default 'oooo',
t4 char(4) default 'oooo',
t5 char(4) default 'oooo',
t6 char(4) default 'oooo',
t7 char(4) default 'oooo',
t8 char(4) default 'oooo',
t9 char(4) default 'oooo',
............................
t248 char(4) default 'oooo',
t249 char(4) default 'oooo',
t250 char(4) default 'oooo',
t251 char(4) default 'oooo',
t252 char(4) default 'oooo',
t253 char(4) default 'oooo',
t254 char(4) default 'oooo'
);

SQL>     select vs.name, ms.value
  2        from v$mystat ms, v$sysstat vs
  3       where ms.statistic# = vs.statistic#
  4         and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                               85832

/*产生了83k的undo,ddl所产生的undo量视乎其所要维护数据字典的操作类型和操作量*/

SQL> oradebug setmypid;
Statement processed.

SQL> oradebug event 10046 trace name context forever,level 1;
Statement processed.

SQL> drop table YOUYUS;
Table dropped.

SQL>     select vs.name, ms.value
  2        from v$mystat ms, v$sysstat vs
  3       where ms.statistic# = vs.statistic#
  4         and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                              214020

/*drop 产生了125k的undo*/

SQL> oradebug tracefile_name;
/home/maclean/app/maclean/diag/rdbms/prod/PROD/trace/PROD_ora_5433.trc

/* 我们来看看drop table 到底做了哪些递归操作? */

[maclean@rh2 ~]$ cat PROD_ora_5433.trc|egrep "delete|update"
         'Need use delete_topo_geometry_layer() to deregister table '
select decode(u.type#, 2, u.ext_username, u.name), o.name,        t.update$, t.insert$, t.delete$, t.enabled,        decode(bitand(t.property, 8192),8192, 1, 0),        decode(bitand(t.property, 65536), 65536, 1, 0),       decode(bitand(t.property, 131072), 131072, 1, 0),       (select o.name from obj$ o          where o.obj# = u.spare2 and o.type# =57)  from sys.obj$ o, sys.user$ u, sys.trigger$ t, sys.obj$ bo where t.baseobject=bo.obj# and bo.name = :1 and bo.spare3 = :2  and bo.namespace = 1  and t.obj#=o.obj# and o.owner#=u.user#  and o.type# = 12 and bitand(property,16)=0 and bitand(property,8)=0  order by o.obj#
delete from object_usage where obj# in  (select a.obj# from object_usage a, ind$ b where  a.obj# = b.obj# and b.bo# = :1)
delete from sys.cache_stats_1$ where dataobj# = :1
delete com$ where obj#=:1
delete from hist_head$ where obj# = :1
delete from dependency$ where d_obj#=:1
delete from source$ where obj#=:1
delete from compression$ where obj#=:1
   m_stmt:='delete from sdo_geor_ddl__table$$ where id=2';
   m_stmt:='delete from sdo_geor_ddl__table$$';
delete from sdo_geor_ddl__table$$ where id=2
delete from col$ where obj#=:1
delete from icol$ where bo#=:1
delete from icoldep$ where obj# in (select obj# from ind$ where bo#=:1)
delete from jijoin$ where obj# in ( select obj# from jijoin$ where tab1obj# = :1 or tab2obj# = :1)
delete from jirefreshsql$ where iobj# in ( select iobj# from jirefreshsql$ where tobj# = :1)
delete from ccol$ where obj#=:1
delete from ind$ where bo#=:1
delete from cdef$ where obj#=:1
delete ecol$ where tabobj# = :1
delete from tab$ where obj#=:1
delete from idl_ub1$ where obj#=:1 and part=:2
delete from idl_char$ where obj#=:1 and part=:2
delete from idl_ub2$ where obj#=:1 and part=:2
delete from idl_sb4$ where obj#=:1 and part=:2
delete from ncomp_dll$ where obj#=:1 returning dllname into :2
delete from idl_ub1$ where obj#=:1 and part=:2
delete from idl_char$ where obj#=:1 and part=:2
delete from idl_ub2$ where obj#=:1 and part=:2
delete from idl_sb4$ where obj#=:1 and part=:2
delete from ncomp_dll$ where obj#=:1 returning dllname into :2
delete from idl_ub1$ where obj#=:1 and part=:2
delete from idl_char$ where obj#=:1 and part=:2
delete from idl_ub2$ where obj#=:1 and part=:2
delete from idl_sb4$ where obj#=:1 and part=:2
delete from ncomp_dll$ where obj#=:1 returning dllname into :2
delete from col$ where obj#=:1
delete coltype$ where obj#=:1
delete from subcoltype$ where obj#=:1
delete ntab$ where obj#=:1
delete lob$ where obj#=:1
delete refcon$ where obj#=:1
delete from opqtype$ where obj#=:1
delete from cdef$ where obj#=:1
delete from objauth$ where obj#=:1
delete from obj$ where obj# = :1
update seg$ set type#=:4,blocks=:5,extents=:6,minexts=:7,maxexts=:8,extsize=:9,extpct=:10,user#=:11,iniexts=:12,lists=decode(:13, 65535, NULL, :13),groups=decode(:14, 65535, NULL, :14), cachehint=:15, hwmincr=:16, spare1=DECODE(:17,0,NULL,:17),scanhint=:18, bitmapranges=:19 where ts#=:1 and file#=:2 and block#=:3
update seg$ set type#=:4,blocks=:5,extents=:6,minexts=:7,maxexts=:8,extsize=:9,extpct=:10,user#=:11,iniexts=:12,lists=decode(:13, 65535, NULL, :13),groups=decode(:14, 65535, NULL, :14), cachehint=:15, hwmincr=:16, spare1=DECODE(:17,0,NULL,:17),scanhint=:18, bitmapranges=:19 where ts#=:1 and file#=:2 and block#=:3
delete from seg$ where ts#=:1 and file#=:2 and block#=:3

/*如果ddl操作执行失败又会如何呢?*/

SQL> oradebug setmypid;
Statement processed.
SQL> oradebug event 10046 trace name context forever,level 1;
Statement processed.

SQL>     select vs.name, ms.value
  2        from v$mystat ms, v$sysstat vs
  3       where ms.statistic# = vs.statistic#
  4         and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                                   0

SQL> drop table YOUYUS;
drop table YOUYUS
           *
ERROR at line 1:
ORA-00942: table or view does not exist

SQL>     select vs.name, ms.value
  2        from v$mystat ms, v$sysstat vs
  3       where ms.statistic# = vs.statistic#
  4         and name = 'undo change vector size';
NAME                                                                  VALUE
---------------------------------------------------------------- ----------
undo change vector size                                                 264
/*同样产生了undo,量较少*/


SQL> oradebug tracefile_name;
/home/maclean/app/maclean/diag/rdbms/prod/PROD/trace/PROD_ora_5494.trc
[maclean@rh2 trace]$ cat PROD_ora_5494.trc|egrep "update|insert|delete"
         'Need use delete_topo_geometry_layer() to deregister table '
   m_stmt:='insert into sdo_geor_ddl__table$$ values (1)';
   m_stmt:='insert into sdo_geor_ddl__table$$ values (2)';
insert into sdo_geor_ddl__table$$ values (2)
   m_stmt:='delete from sdo_geor_ddl__table$$';
delete from sdo_geor_ddl__table$$

/*执行少量递归操作后,Oracle发现所要drop的对象并不存在,将会rollback之前的"部分"递归dml操作*/

其实我们可以把ddl操作分解为以下步骤:

begin
commit;
--编译ddl
begin
--实现ddl,包括一系列递归的数据字典维护操作及其他操作
commit;
exception
when others then
rollback;
end;
end;

ddl操作无需也不允许手动commit或rollback参与,但这并不代表ddl操作不产生undo。

沪ICP备14014813号-2

沪公网安备 31010802001379号