11g告警日志中大量ORA-12170错误

在11g数据库的告警日志中,经常可以看到ORA-12170错误信息。
如果这个错误是偶然出现,问题可能是网络问题所致,但是如果这个错误短时间内频繁出现,那么问题就不一定是网络不畅那么简单了。
客户的数据库出现了应用无法连接的错误,而应用程序日志出现下面的错误信息:

ORA-12519, TNS:no appropriate service handler found

在告警日志中比较频繁的出现了下面的错误:

Fatal NI CONNECT error 12170.
Sat Sep 03 12:43:43 2011
VERSION INFORMATION:
TNS FOR Linux: Version 11.2.0.2.0 - Production
Oracle Bequeath NT Protocol Adapter FOR Linux: Version 11.2.0.2.0 - Production
TCP/IP NT Protocol Adapter FOR Linux: Version 11.2.0.2.0 - Production
TIME: 03-SEP-2011 12:43:43
TIME: 03-SEP-2011 12:43:43
Tns error struct:
Tns error struct:
Tracing NOT turned ON.
Tracing NOT turned ON.
ns main err code: 12535
ns main err code: 12535
ns main err code: 12535
TIME: 03-SEP-2011 12:43:43
Tns error struct:
Tns error struct:
ns main err code: 12535
Tracing NOT turned ON.
ns main err code: 12535
TNS-12535: TNS:operation timed OUT
TNS-12535: TNS:operation timed OUT
 
Tns error struct:
TNS-12535: TNS:operation timed OUT
ns secondary err code: 12606
ns secondary err code: 12606
TNS-12535: TNS:operation timed OUT
TNS-12535: TNS:operation timed OUT
nt main err code: 0
nt main err code: 0
ns secondary err code: 12606
ns secondary err code: 12606
ns main err code: 12535
ns secondary err code: 12606
nt secondary err code: 0
nt secondary err code: 0
nt main err code: 0
nt main err code: 0
nt main err code: 0
nt OS err code: 0
nt OS err code: 0
nt secondary err code: 0
nt secondary err code: 0
Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.90.102)(PORT=33196))
Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.90.102)(PORT=33191))
nt OS err code: 0
nt secondary err code: 0
nt OS err code: 0
Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.90.102)(PORT=33201))
TNS-12535: TNS:operation timed OUT
Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.90.102)(PORT=33195))
nt OS err code: 0
ns secondary err code: 12606
Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.90.102)(PORT=33174))
nt main err code: 0
WARNING: inbound connection timed OUT (ORA-3136)
Sat Sep 03 12:48:28 2011
WARNING: inbound connection timed OUT (ORA-3136)
Sat Sep 03 12:48:28 2011
WARNING: inbound connection timed OUT (ORA-3136)
Sat Sep 03 12:48:28 2011
WARNING: inbound connection timed OUT (ORA-3136)
Sat Sep 03 12:48:30 2011
Active SESSION History (ASH) performed an emergency FLUSH. This may mean that ASH IS undersized. IF emergency flushes are a recurring issue, you may consider increasing ASH SIZE BY setting the VALUE OF _ASH_SIZE TO a sufficiently LARGE VALUE. Currently, ASH SIZE IS 33554432 bytes. BOTH ASH SIZE AND the total NUMBER OF emergency flushes since instance startup can be monitored BY running the following query:
SELECT total_size,awr_flush_emergency_count FROM v$ash_info;
Sat Sep 03 12:48:32 2011
Sweep [inc][48817]: completed
Sweep [inc2][48817]: completed

检查了监听日志,在12:43的时刻出现了大量的ORA-12518错误,这个错误信息是:TNS:listener could not hand off client connection,随后不到1秒的时间,大量的连接错误导致了ORA-12519 TNS:no appropriate service handler found错误,这说明数据库的对连接的响应能力已经跟不上了。
而导致这两个问题出现的原因是大量的会话在短时间内连接到数据库,根据监听日志,仅12:42分这一分钟,连接数据库的会话就建立了超过2000个连接。而正常情况下,这个数据库一天的总连接数量也不过13000个左右。
Oracle在metalink文档ID 12535.1中,描述了11g告警日志中出现ORA-12170以及ORA-12535错误的原因,由于大量的客户端连接到服务器,导致数据库无法在短时间内处理连接风暴,从而引发了连接超时的错误。
最终发现,可能的中间件的连接重试策略配置存在一定的问题,导致当通信或其他问题引发连接中断后,会短时间内产生大量的连接重试,并不断的增加连接数量,最终引发了签的ORA-12519错误。

Posted in ORACLE | Tagged , , , , , | Leave a comment

外键缺少索引引发的死锁

客户的10.2.0.4 RAC for AIX环境频繁出现ORA-60死锁问题,导致应用程序无法顺利执行。
经过一系列的诊断,发现最终问题是由于外键上没有建立索引所致,由于程序在主子表上删除数据,缺少索引导致行级锁升级为表级锁,最终导致大量的锁等待和死锁。
下面通过一个例子简单模拟一下问题:

SQL> CREATE TABLE t_p (id NUMBER PRIMARY KEY, name varchar2(30));
TABLE created.
SQL> CREATE TABLE t_f (fid NUMBER, f_name varchar2(30), FOREIGN KEY (fid) REFERENCES t_p);
TABLE created.
SQL> INSERT INTO t_p VALUES (1, 'a');
1 ROW created.
SQL> INSERT INTO t_f VALUES (1, 'a');
1 ROW created.
SQL> INSERT INTO t_p VALUES (2, 'b');
1 ROW created.
SQL> INSERT INTO t_f VALUES (2, 'c');
1 ROW created.
SQL> commit;
Commit complete.
SQL> DELETE t_f WHERE fid = 2;
1 ROW deleted.

这时在会话2同样对子表进行删除:

SQL2> DELETE t_f WHERE fid = 1;
1 ROW deleted.

回到会话1执行主表的删除:

SQL> DELETE t_p WHERE id = 2;
会话被锁,回到会话2执行主表的删除:
SQL2> DELETE t_p WHERE id = 1;

会话同样被锁,这时会话1的语句被回滚,出现ORA-60死锁错误:

DELETE t_p WHERE id = 2
*
ERROR at line 1:
ORA-00060: deadlock detected while waiting FOR resource
 
SQL> ROLLBACK;
ROLLBACK complete.

将会话1操作回滚,会话2同样回滚并建立外键列上的索引:

1 ROW deleted.
SQL2> ROLLBACK;
ROLLBACK complete.
SQL2> CREATE INDEX ind_t_f_fid ON t_f(fid);
INDEX created.

重复上面的步骤会话1删除子表记录:

SQL> DELETE t_f WHERE fid = 2;
1 ROW deleted.

会话2删除子表记录:

SQL2> DELETE t_f WHERE fid = 1;
1 ROW deleted.

会话1删除主表记录:

SQL> DELETE t_p WHERE id = 2;
1 ROW deleted.

会话2删除主表记录:

SQL> DELETE t_p WHERE id = 1;
1 ROW deleted.

所有的删除操作都可以成功执行,关于两种情况下锁信息的不同这里就不深入分析了,重点就是在外键列上建立索引。
虽然有一些文章提到过,如果满足某些情况,可以不在外键列上建立的索引,但是我的观点一向是,既然创建了外键,就不要在乎再多一个索引,因为一个索引所增加的代价,与缺失这个索引所带来的问题相比,是微不足道的。

Posted in ORACLE | Tagged , , , | Leave a comment

Oracle SecureBackup管理员手册

当第一次使用NETBACKUP配置RMAN备份到带宽时就考虑过,Oracle为什么没有直接备份到带宽的功能,非得需要借助到其他的软件,直到Oracle推出了SecureBackup,解决了这个问题。
记得在10g的时候,Oracle推出了Secure Backup的功能,当时这篇文档还包括在整个数据库的文档之中,似乎是从11g开始,Secure Backup被独立成单独的产品,因此文档和下载等也都与数据库分开,以致于我一度认为这个功能消失了。
简单看了一下目录,感觉SecureBackup无论是结构还是功能都和NETBACKUP差不多,这也不难理解,二者实现的目的本身也没有多大的差别。
在没有看完之前就不进行评价了,照例给出这篇文档的在线阅读网址:http://download.oracle.com/docs/cd/E26569_01/index.htm

Posted in BOOKS | Leave a comment

ORA-1251和ORA-600(kjccgmb:l)错误

客户的数据库出现了ORA-1251错误,进而引发了ORA-600(kjccgmb:l)错误。
数据库版本是9208 RAC for Linux X86-64。客户数据库一个数据文件突然不可用,被置为OFFLINE状态:

ORA-01171: datafile 44 going offline due TO error advancing checkpoint
ORA-01122: DATABASE file 44 failed verification CHECK
ORA-01110: DATA file 44: '/dev/raw/raw77'
ORA-01251: UNKNOWN File Header Version READ FOR file NUMBER 44

随后不久,另一个节点的会话出现ORA-600错误:

Sat Oct 22 20:35:09
OUT OF memory FOR message buffers
Errors IN file /oracle/admin/adb/bdump/adb1_lms3_4982.trc:
ORA-00600: internal error code, arguments: [kjccgmb:l], [], [], [], [], [], [], []
Sat Oct 22 20:35:09
Errors IN file /oracle/admin/adb/bdump/adbl_lms3_4982.trc:
ORA-00603: oracle server SESSION TERMINATED BY fatal error
ORA-00600: internal error code, arguments: [kjccgmb:l], [], [], [], [], [], [], []

在MOS上没有找到任何与这个ORA-600错误有关的信息,根据错误信息和现象可以推断,由于前面的错误导致数据库文件OFFLINE,导致Oracle在处理全局数据块信息的时候出现了异常,从而引发了这个错误。
客户随后尝试了RESIZE以及RECOVER大量的操作都没有解决问题,尝试通过备份进行恢复,却发现上次备份到当前的归档日志中丢失了几个。
对于这个ORA-1251的错误,Oracle的解释是读写丢失或硬件问题或者Oracle的文件头被外部的进程覆盖。
Oracle官方给出的解决方案是利用这个数据文件创建以来所有的归档进行恢复,其实如果有可用的备份和归档,那么直接恢复数据文件就可以了。
对于当前的这个环境,没有什么其他的好办法了,只好通过DUL来抽取客户的数据了。

Posted in BUG | Tagged , , , , , | Leave a comment

ORA-600(6928)错误

客户的测试环境碰到了这个错误。
告警日志中错误如下:

Sat Oct 15 01:21:40 GMT+08:00 2011ALTER SYSTEM SET service_names='SYS$SYS.KUPC$S_1_20111015004332.DB','db' SCOPE=MEMORY SID='db1';
Sat Oct 15 01:21:40 GMT+08:00 2011ALTER SYSTEM SET service_names='db' SCOPE=MEMORY SID='db1';
Sat Oct 15 01:39:03 GMT+08:00 2011Errors IN file /u01/app/oracle/admin/db/udump/db11_ora_4325842.trc:
ORA-00600: 内部错误代码, 参数: [6928], [886], [], [], [], [], [], []
Sat Oct 15 01:39:45 GMT+08:00 2011Trace dumping IS performing id=[cdmp_20111015013945]
Sat Oct 15 02:16:12 GMT+08:00 2011The VALUE (30) OF MAXTRANS parameter ignored.
Sat Oct 15 02:16:14 GMT+08:00 2011ALTER SYSTEM SET service_names='db','SYS$SYS.KUPC$C_1_20111015021613.DB' SCOPE=MEMORY SID='db';
Sat Oct 15 02:16:14 GMT+08:00 2011ALTER SYSTEM SET service_names='SYS$SYS.KUPC$C_1_20111015021613.DB','db','SYS$SYS.KUPC$S_1_20111015021613.DB' SCOPE=MEMORY SID='db1';
kupprdp: master process DM00 started WITH pid=792, OS id=60686622
TO EXECUTE - SYS.KUPM$MCP.MAIN('SYS_IMPORT_TABLE_01', 'U1', 'KUPC$C_1_20111015021613', 'KUPC$S_1_20111015021613', 0);
kupprdp: worker process DW01 started WITH worker id=1, pid=794, OS id=54002170
TO EXECUTE - SYS.KUPW$WORKER.MAIN('SYS_IMPORT_TABLE_01', 'U1');

从上面的完整的事件信息判断,问题似乎发生在数据泵导入的过程中,进一步检查对应的详细信息:

/u01/app/oracle/admin/db/udump/db1_ora_4325842.trc
Oracle DATABASE 10g Enterprise Edition Release 10.2.0.5.0 - 64bit Production
WITH the Partitioning, REAL Application Clusters, OLAP, DATA Mining
AND REAL Application Testing options
ORACLE_HOME = /u01/app/oracle/product/10.2.0/db
System name:	AIX
Node name:	db1
Release:	1
Version:	6
Machine:	00C73FB64C00
Instance name: db1
Redo thread mounted BY this instance: 1
Oracle process NUMBER: 39
Unix process pid: 4325842, image: oracle@db
*** 2011-10-15 01:38:43.021
*** ACTION NAME:(..\Control\T.ctl) 2011-10-15 01:38:43.017
*** MODULE NAME:(SQL Loader Direct Path LOAD) 2011-10-15 01:38:43.017
*** SERVICE NAME:(db) 2011-10-15 01:38:43.017
*** SESSION ID:(3092.196) 2011-10-15 01:38:43.017
col 0; len 5;  c4 15 0c 08 13
col 1; len 18;  32 30 31 31 30 37 31 38 30 30 30 30 34 30 30 30 30 30
col 0; len 5;  c4 15 0c 08 13
col 1; len 18;  32 30 31 31 30 37 31 38 30 30 30 30 34 30 30 30 30 30
*** 2011-10-15 01:39:03.971
ksedmp: internal OR fatal error
ORA-00600: 内部错误代码, 参数: [6928], [886], [], [], [], [], [], []
CURRENT SQL statement FOR this SESSION:
INSERT /*+ SYS_DL_CURSOR */ INTO U1.T ("BEGIN_DATE","NO","CURRENT_DATE") VALUES (NULL,NULL,NULL)
----- Call Stack Trace -----
calling              CALL     entry                argument VALUES IN hex      
location             TYPE     point                (? means dubious VALUE)     
-------------------- -------- -------------------- ----------------------------
ksedst+001c          bl       ksedst1              700000010003520 ? 11019C008 ?
ksedmp+0290          bl       ksedst               104C20490 ?
ksfdmp+02d8          bl       03F34EF4             
kgeriv+0108          bl       _ptrgl               
kgeasi+0118          bl       kgeriv               000000001 ? 000000000 ?
                                                   1101C0848 ? 1108ECC98 ?
                                                   1108EE1F0 ?
kdblfl+0734          bl       01FC4904             
klafin+010c          bl       kdblfl               000000081 ? 110455A58 ?
                                                   7000000FDC56DA8 ? 1101C0848 ?
kpodpfin+0550        bl       klafin               104D0F250 ?
kpodpmop+0364        bl       kpodpfin             110455180 ?
opiodr+0b2c          bl       _ptrgl               
ttcpip+1020          bl       _ptrgl               
opitsk+117c          bl       01FC70C8             
opiino+09d0          bl       opitsk               0FFFFD2F0 ? 000000000 ?
opiodr+0b2c          bl       _ptrgl               
opidrv+04a4          bl       opiodr               3C1028E398 ? 404C734B0 ?
                                                   FFFFFFFFFFFF2B0 ? 01028E390 ?
sou2o+0090           bl       opidrv               3C02A2911C ? 4A0071E60 ?
                                                   FFFFFFFFFFFF2B0 ?
opimai_real+01bc     bl       01FC3934             
main+0098            bl       opimai_real          000000000 ? 000000000 ?
__start+0070         bl       main                 000000000 ? 000000000 ?
--------------------- Binary Stack Dump ---------------------

而从详细TRACE分析,显然这是一个SQLLDR进程,不过考虑到数据泵也是采用直接路径装载,那么很有可能这个直接路径是由数据泵所触发的。
这个问题在MOS上的描述为:Bug 5035742 – SQL*loader direct path sets all local indexes UNUSABLE when an error occurs [ID 5035742.8],显然是由于直接路径的处理过程中存在不完善的地方,导致索引状态不正常所致。
Oracle给出的方法是采用常规路径方式导入,而Oracle目前并没有专门的PATCH来解决这个问题。所幸这个问题对于系统的影响并不大,一般而言进行批量装载的表,在装载的时刻都没有什么并发的访问,除了改变数据泵导入模式外,也可以采用手工修复的方式来解决这个问题。

Posted in BUG | Tagged , , , | Leave a comment

DATA CARTRIDGE开发手册总结

这篇文档看完了,不过其中内容学到不到一成。
以前提到过,如果追溯我第一篇的博客,就是看了这篇文章后,仿写了一个例子,当时觉得这个内容比较复杂,如果不记录下来恐怕自己都会记不住,因此才开始了记录BLOG的习惯。不过这篇文档中的内容还是相当小众的,这篇文档介绍的内容实际上是在Oracle提供的架构上扩展用户自定义的功能。
而对于绝大部分人而言,现有Oracle提供的功能已经足够了,或者应该这么说,绝大部分人都只用数据库最基本的功能就够了,甚至很多Oracle的功能大部分都不清楚,更不用说用了。因此这篇文档的内容对于大部分人而言并不实用,如果没有特殊的要求,可以不必细读。

Posted in BOOKS | Leave a comment

ORA-600(ktecgeb-2)错误

还是一个ORA-600错误,这个错误出现在10.2环境中。
客户的DATA GUARD环境中的物理备库,由于要进行测试,因此设置了FLASHBACK ON,创建了恢复点,然后激活成主库并打开,准备进行测试,但是发现在后台告警日志中出现了这个错误,详细的错误信息如下:

Completed: ALTER DATABASE OPEN
Wed Oct 26 22:08:27 2011
Errors IN file /oracle/admin/standdb/bdump/standdb_j003_446902.trc:
ORA-00600: internal error code, arguments: [ktecgeb-2], [788585233], [0], [], [], [], [], []
Wed Oct 26 22:08:33 2011
Errors IN file /oracle/admin/standdb/bdump/standdb_j003_446902.trc:
ORA-00600: internal error code, arguments: [ORA-00600: internal error code, arguments: [ktecgeb-2], [788585233], [0], [], [], [], [], []
ORA-06512: at "SYS.PRVT_ADVISOR", line 1624
ORA-06512: at "SYS.DBMS_ADVISOR", line 186
ORA-06512: at "SYS.DBMS_SPACE", line 1500
ORA-06512: at "SYS.DBMS_SPACE", line 1566
], [], [], [], [], [], [], []

显然导致错误产生的原因是后台JOB的运行,而这个JOB跑的任务是检查对象空间使用情况。继续检查详细TRACE信息:

oracle@srv4:/oracle/admin/standdb/bdump/more /oracle/admin/standdb/bdump/standdb_j003_446902.trc
/oracle/admin/standdb/bdump/standdb_j003_446902.trc
Oracle DATABASE 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
WITH the Partitioning, OLAP, DATA Mining AND REAL Application Testing options
ORACLE_HOME = /oracle/product/db10gr2
System name:    AIX
Node name:      srv4
Release:        3
Version:        5
Machine:        0055053E4C00
Instance name: standdb
Redo thread mounted BY this instance: 1
Oracle process NUMBER: 20
Unix process pid: 446902, image: oracle@srv4 (J003)
 
*** ACTION NAME:(AUTO_SPACE_ADVISOR_JOB) 2011-10-26 22:08:27.409
*** MODULE NAME:(DBMS_SCHEDULER) 2011-10-26 22:08:27.409
*** SERVICE NAME:(SYS$USERS) 2011-10-26 22:08:27.409
*** SESSION ID:(1081.3) 2011-10-26 22:08:27.409
*** 2011-10-26 22:08:27.409
ksedmp: internal OR fatal error
ORA-00600: internal error code, arguments: [ktecgeb-2], [788585233], [0], [], [], [], [], []
CURRENT SQL statement FOR this SESSION:
SELECT STATUS FROM TABLE( DBMS_SPACE.VERIFY_SHRINK_CANDIDATE_TBF( :B1 , :B2 , :B3 , :B4 , :B5 ))
----- PL/SQL Call Stack -----
  object      line  object
  handle    NUMBER  name
700000243900620      1788  package body SYS.DBMS_SPACE
700000243900620      1806  package body SYS.DBMS_SPACE
700000242c6dc98         1  anonymous block
700000242ea5808      1698  SYS.WRI$_ADV_OBJSPACE_TREND_T
700000242fce6c0      1535  package body SYS.PRVT_ADVISOR
700000242fce6c0      1618  package body SYS.PRVT_ADVISOR
700000242fed300       186  package body SYS.DBMS_ADVISOR
700000243900620      1500  package body SYS.DBMS_SPACE
700000243900620      1566  package body SYS.DBMS_SPACE
----- Call Stack Trace -----
calling              CALL     entry                argument VALUES IN hex      
location             TYPE     point                (? means dubious VALUE)     
-------------------- -------- -------------------- ----------------------------
ksedst+001c          bl       ksedst1              000000000 ? FFFFFFFFFFE5C14 ?
ksedmp+0290          bl       ksedst               104A557A8 ?
ksfdmp+0018          bl       03F4CD24             
kgerinv+00dc         bl       _ptrgl               
kgeasnmierr+004c     bl       kgerinv              000000000 ? FFFFFFFFFFE67D0 ?
                                                   FFFFFFFFFFE6328 ? 02F00DB14 ?
                                                   FFFFFFFFFFE6250 ?
ktecgeb+01bc         bl       kgeasnmierr          1101957F8 ? 1104C40E0 ?
                                                   104D81670 ? 200000002 ?
                                                   000000000 ? 02F00DB11 ?
                                                   000000000 ? 000000000 ?
kteinlast+01b4       bl       ktecgeb              104D816C0 ? 104D816B0 ?
                                                   104D816A0 ? 104D81698 ?
ktsa_verify_shrink_  bl       kteinlast            FFFFFFFFFFE6730 ?
candidate+02f4                                     FFFFFFFFFFE6780 ? 100000000 ?
                                                   700000242C6DC98 ?
ktsaps_verify_shrin  bl       ktsa_verify_shrink_  FFFFFFFFFFE6730 ?
k_candidate+0418              candidate            FFFFFFFFFFE6780 ? 110195978 ?
                                                   02D8C0274 ? 700000242C6DC98 ?
pevm_icd_call_commo  bl       _ptrgl               
n+03f8                                             
pfrinstr_ICAL+00c8   bl       pevm_icd_call_commo  1109064B0 ? 000000000 ?
                              n                    1438BD4EF ? 6000000000000 ?
                                                   6000000000008 ? 0FFFE70A0 ?
                                                   110900230 ?
pfrrun_no_tool+005c  bl       _ptrgl               
pfrrun+1014          bl       pfrrun_no_tool       FFFFFFFFFFE70C0 ?
                                                   7000002421FC0E8 ?
                                                   7000002421FC0E8 ?
plsql_run+06b4       bl       pfrrun               1109064B0 ?
peicnt+0224          bl       plsql_run            1109064B0 ? 100007FFFFFFF ?
                                                   000000000 ?
kkxuexe+0360         bl       peicnt               1108BC3B8 ? 1109064B0 ?
kkxmpsexe+029c       bl       03F4AB20             
kgmexwi+056c         bl       _ptrgl               
kgmexec+0bcc         bl       kgmexwi              1101957F8 ? 000000000 ?
                                                   FFFFFFFFFFE9320 ? 000000000 ?
                                                   000000000 ? 000000000 ?
                                                   07FFFFFF8 ? 000000000 ?

从TRACE文件不难看出,Oracle在验证数据文件是否空间收缩的候选对象时报错。根据metalink记录的bug,并没有和当前现象吻合的记录,不过大部分问题都与ASSM管理表空间有关。
对于这个错误而言,对于备库可以简单的忽略,对于引起错误的JOB也可以停用,但是这个错误反映出备库的状态不正常,因此这个备库作为主库的备份是不安全的,应该通过DBV之类的工具检查数据文件是否存在坏块,建议对报错的数据文件重新从主库获取COPY,来避免坏块或逻辑错误的隐患。

Posted in BUG | Tagged , , , | Leave a comment

ORA-600(kjcsombd:2)错误

又是一个9208 RAC上的错误,事实上这个错误和上一篇文章中描述的错误相关性很大,因为在上一篇节点关闭并报错的同时,这个节点出现了这个ORA-600错误。
ORA-600(kjccgmb:1)错误:https://yangtingkun.net/?p=245
在当前节点上的详细错误信息为:

Thu Oct 13 18:13:10 2011
IPC Send timeout detected. Sender ospid 1228900
Thu Oct 13 18:13:12 2011
Communications reconfiguration: instance 1
Thu Oct 13 18:13:12 2011
Trace dumping IS performing id=[cdmp_20111013181312]
Thu Oct 13 18:13:17 2011
IPC Send timeout detected. Sender ospid 770198
Thu Oct 13 18:13:19 2011
Evicting instance 2 FROM cluster
Thu Oct 13 18:13:22 2011
IPC Send timeout detected. Sender ospid 1032208
Thu Oct 13 18:13:31 2011
IPC Send timeout detected. Sender ospid 1302720
Thu Oct 13 18:13:37 2011
IPC Send timeout detected. Sender ospid 438420
Thu Oct 13 18:13:39 2011
Waiting FOR instances TO leave: 
2 
Thu Oct 13 18:13:47 2011
IPC Send timeout detected. Sender ospid 1474810
Thu Oct 13 18:13:59 2011
Waiting FOR instances TO leave: 
2 
.
.
.
Thu Oct 13 18:17:22 2011
IPC Send timeout detected. Sender ospid 876652
Thu Oct 13 18:17:24 2011
IPC Send timeout detected. Sender ospid 1654878
Thu Oct 13 18:17:27 2011
IPC Send timeout detected. Sender ospid 1425476
Thu Oct 13 18:17:27 2011
IPC Send timeout detected. Sender ospid 970920
Thu Oct 13 18:17:39 2011
Waiting FOR instances TO leave: 
2 
Thu Oct 13 18:17:59 2011
Waiting FOR instances TO leave: 
2 
Thu Oct 13 18:18:19 2011
Waiting FOR instances TO leave: 
2 
Thu Oct 13 18:18:29 2011
Errors IN file /u01/product/admin/RAC/udump/rac1_ora_1032208.trc:
ORA-00600: internal error code, arguments: [kjcsombd:2], [], [], [], [], [], [], []
ORA-03113: end-of-file ON communication channel
Thu Oct 13 18:18:37 2011
Errors IN file /u01/product/admin/RAC/udump/rac1_ora_1032208.trc:
ORA-00603: ORACLE server SESSION TERMINATED BY fatal error
ORA-00600: internal error code, arguments: [kjcsombd:2], [], [], [], [], [], [], []
ORA-03113: end-of-file ON communication channel
Thu Oct 13 18:18:38 2011
Trace dumping IS performing id=[cdmp_20111013181838]

这个600错误一直重复出现,直到另一个实例启动,对应的详细TRACE信息为:

/u01/product/admin/RAC/udump/rac1_ora_1032208.trc
Oracle9i Enterprise Edition Release 9.2.0.8.0 - 64bit Production
WITH the Partitioning, REAL Application Clusters, OLAP AND Oracle DATA Mining options
JServer Release 9.2.0.8.0 - Production
ORACLE_HOME = /u01/product/oracle/9.2.0
System name: AIX
Node name: p55a1
Release: 3
Version: 5
Machine: 0001D007D600
Instance name: RAC1
Redo thread mounted BY this instance: 1
Oracle process NUMBER: 237
Unix process pid: 1032208, image: oracle@p55a1 (TNS V1-V3)
*** SESSION ID:(275.64909) 2011-10-13 18:13:22.043
SKGXPCTX: 0x102c4988 ctx
admono 0x3d9a665b admport:
SSKGXPT 0x102c4c44 flags  active network 0
info FOR network 0
 socket no 7  IP 172.16.12.254  UDP 57496
 HACMP network_id 0 sflags SSKGXPT_WRITESSKGXPT_UP
context TIMESTAMP 0xe5b469
 no ports
    sconno     accono   ertt  state   seq#   sent  async   sync rtrans   acks
0x5c9264d4 0x07c1249a     32      3  33535    772    772      0    296    771
slot 6 rqh=11035df18
seq=33534 len=424 accno=0x7c1249a START TS=0xe102f0 rt TS=0xe5b7c7 X CNT=297
0x5c9264d5 0x60c4351d     32      3  34041   1278   1278      0      0   1278
0x5c9264d6 0x4201cb1f     32      3  32770      7      7      0      0      7
       ach     accono     sconno      admno  state   seq#    rcv rtrans   acks
Submitting synchronized dump request [268435460]
KCL: caught error 3113 during cr LOCK op
*** 2011-10-13 18:18:29.055
ksedmp: internal OR fatal error
ORA-00600: internal error code, arguments: [kjcsombd:2], [], [], [], [], [], [], []
ORA-03113: end-of-file ON communication channel
CURRENT SQL information unavailable - no SESSION.
----- Call Stack Trace -----
calling              CALL     entry                argument VALUES IN hex      
location             TYPE     point                (? means dubious VALUE)     
-------------------- -------- -------------------- ----------------------------
ksedmp+0148          bl       ksedst               102974684 ?
ksfdmp+0018          bl       01FD3FC8             
kgerinv+00e8         bl       _ptrgl               
kgeanmfe+0048        bcl      kglsim_unpin_simhp+  000000200 ? 000000000 ?
                              001c                 700000000017CD8 ? 000000000 ?
kjcsombdi+0974       bl       kgeanmfe             110006288 ? 110357A28 ?
                                                   102A73228 ? 000000000 ?
                                                   10DC9D3665FC00 ?
                                                   8A2477269B180 ?
                                                   12E0BE826D694B2F ?
                                                   000000077 ?
kjcsombd+00a4        bl       kjcsombdi            BADC0FFEE0DDF00D ?
                                                   BADC0FFEE0DDF00D ?
kjpsod+0fbc          bl       kjcsombd             70000034CDEECD8 ? 2000004F8 ?
kssdch_stage+02b8    bl       _ptrgl               
kssdch+0014          bl       kssdch_stage         BADC0FFEE0DDF00D ?
                                                   BADC0FFEE0DDF00D ?
                                                   BADC0FFEE0DDF00D ?
ksudlp+0380          bl       kssdch               7000003796230D0 ? 200000002 ?
opidcl+020c          bl       01FD4824             
opidrv+045c          bl       opidcl               11000D060 ? 0101FAED0 ?
sou2o+0028           bl       opidrv               3C0C000000 ? 4A0142C60 ?
                                                   FFFFFFFFFFFF990 ?
main+0138            bl       01FD39E0             
__start+0098         bl       main                 000000000 ? 000000000 ?
--------------------- Binary Stack Dump ---------------------

从TRACE文件不难判断,出现这个问题是由于需要从远端CACHE中获取一致性读的BLOCK,但是在获取过程中碰到了ORA-3113通信中断错误。
显然这个问题与另外的节点关闭直接相关,配合另外节点上的ORA-600错误,怀疑两个节点间的通信在关闭时刻出现异常,从而引发各个节点上出现了不同的ORA-600错误。

Posted in BUG | Tagged , , , , | Leave a comment

ORA-600(kjccgmb:1)错误

在客户的9208 RAC环境中碰到了这个错误。
相信信息如下:

Thu Oct 13 18:07:25 2011
Shutting down instance: further logons disabled
Shutting down instance (immediate)
License high water mark = 369
Thu Oct 13 18:07:45 2011
ALTER DATABASE CLOSE NORMAL
Thu Oct 13 18:07:45 2011
SMON: disabling tx recovery
SMON: disabling cache recovery
Thu Oct 13 18:07:45 2011
Shutting down archive processes
Archiving IS disabled
Thu Oct 13 18:07:45 2011
ARCH shutting down
ARC0: Archival stopped
Thu Oct 13 18:07:45 2011
ARCH shutting down
ARC1: Archival stopped
Thu Oct 13 18:07:45 2011
Thread 2 closed at log SEQUENCE 39936
Successful close OF redo thread 2
Thu Oct 13 18:07:48 2011
Completed: ALTER DATABASE CLOSE NORMAL
Thu Oct 13 18:07:48 2011
ALTER DATABASE DISMOUNT
Completed: ALTER DATABASE DISMOUNT
ARCH: Archiving IS disabled
Shutting down archive processes
Archiving IS disabled
Archive process shutdown avoided: 0 active
ARCH: Archiving IS disabled
Shutting down archive processes
Archiving IS disabled
Archive process shutdown avoided: 0 active
Thu Oct 13 18:12:48 2011
SHUTDOWN: waiting FOR detached processes TO terminate.
Thu Oct 13 18:17:31 2011
IPC Send timeout detected. Sender ospid 446682
OUT OF MEMORY FOR message buffers
Thu Oct 13 18:20:23 2011
Errors IN file /u01/product/admin/RAC/bdump/rac2_lms0_446682.trc:
ORA-00600: internal error code, arguments: [kjccgmb:1], [], [], [], [], [], [], []
Thu Oct 13 18:20:23 2011
Errors IN file /u01/product/admin/RAC/bdump/rac2_lms0_446682.trc:
ORA-00603: ORACLE server SESSION TERMINATED BY fatal error
ORA-00600: internal error code, arguments: [kjccgmb:1], [], [], [], [], [], [], []
OUT OF MEMORY FOR message buffers
Thu Oct 13 18:22:03 2011
Errors IN file /u01/product/admin/RAC/bdump/rac2_lms0_446682.trc:
ORA-00600: internal error code, arguments: [kjccgmb:1], [], [], [], [], [], [], []
ORA-00603: ORACLE server SESSION TERMINATED BY fatal error
ORA-00600: internal error code, arguments: [kjccgmb:1], [], [], [], [], [], [], []
Thu Oct 13 18:22:04 2011
Errors IN file /u01/product/admin/RAC/bdump/rac2_lms0_446682.trc:
ORA-00603: ORACLE server SESSION TERMINATED BY fatal error
ORA-00600: internal error code, arguments: [kjccgmb:1], [], [], [], [], [], [], []
ORA-00603: ORACLE server SESSION TERMINATED BY fatal error
ORA-00600: internal error code, arguments: [kjccgmb:1], [], [], [], [], [], [], []
Thu Oct 13 18:25:31 2011
Starting ORACLE instance (normal)

查询了一下metalink,确实有一篇文章和当前的描述很相似,问题同样是出在LMS进程上。但是区别在于,bug描述的问题导致实例发挥例CRASH,而当前是在手工运行SHUTDOWN IMMEDIATE操作所引发的问题。
由于是关闭实例所触发的问题,因此如果不是经常出现,可以直接忽略掉这个错误。

Posted in BUG | Tagged , , | Leave a comment

11g改变了DELETE语句的执行计划

在11.2中,如果DELETE的时候没有限制条件,且表上存在主键的话,执行计划会变为索引全扫。
在和600聊天的时候听说了这个现象,开始的时候还不是很相信。当时600特意验证了一下,事实确实如此。
于是特意自己也做了个简单的例子:

SQL> SELECT * FROM v$version;
BANNER
--------------------------------------------------------------------------------
Oracle DATABASE 11g Enterprise Edition Release 11.2.0.2.0 - Production
PL/SQL Release 11.2.0.2.0 - Production
CORE 11.2.0.2.0 Production
TNS FOR Linux: Version 11.2.0.2.0 - Production
NLSRTL Version 11.2.0.2.0 - Production
SQL> CREATE TABLE t_del AS SELECT rownum id, a.* FROM dba_objects a, user_tables ;
TABLE created.
SQL> SELECT COUNT(*) FROM t_del;
  COUNT(*)
----------
    110360
SQL> ALTER TABLE t_del ADD PRIMARY KEY (id);
TABLE altered.
SQL> EXPLAIN plan FOR DELETE t_del;
Explained.
SQL> SELECT * FROM TABLE(dbms_xplan.display);
PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------
Plan hash VALUE: 1780357700
--------------------------------------------------------------------------------
| Id  | Operation        | Name        | ROWS  | Bytes | Cost (%CPU)| TIME     |
--------------------------------------------------------------------------------
|   0 | DELETE STATEMENT |             | 89885 |  1141K|   245   (1)| 00:00:03 |
|   1 |  DELETE          | T_DEL       |       |       |            |          |
|   2 |   INDEX FULL SCAN| SYS_C006177 | 89885 |  1141K|   245   (1)| 00:00:03 |
--------------------------------------------------------------------------------
Note
-----
   - dynamic sampling used FOR this statement (level=2)
13 ROWS selected.
SQL> EXPLAIN plan FOR DELETE /*+ full(t_del) */ t_del;
Explained.
SQL> SELECT * FROM TABLE(dbms_xplan.display);
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------
Plan hash VALUE: 2195693323
----------------------------------------------------------------------------
| Id  | Operation          | Name  | ROWS  | Bytes | Cost (%CPU)| TIME     |
----------------------------------------------------------------------------
|   0 | DELETE STATEMENT   |       | 89885 |  1141K|   426   (1)| 00:00:06 |
|   1 |  DELETE            | T_DEL |       |       |            |          |
|   2 |   TABLE ACCESS FULL| T_DEL | 89885 |  1141K|   426   (1)| 00:00:06 |
----------------------------------------------------------------------------
Note
-----
   - dynamic sampling used FOR this statement (level=2)
13 ROWS selected.

Oracle认为全索引扫描的代价接近全表扫描的一半,预估时间也只有全表扫描的一半。这中执行计划对于10g以前是不可想象的,既然所有的记录都要处理,通过全表扫描显然是最合适的方法,而通过索引去定位每条记录显然效率要低很多。
那么到底是Oracle改变了实现方式,还是11.2的CBO在这里犯了错误呢,真正执行一下看看效果:

SQL> SET timing ON
SQL> SET autot trace
SQL> DELETE t_del;
110360 ROWS deleted.
Elapsed: 00:00:01.23
Execution Plan
----------------------------------------------------------
Plan hash VALUE: 1780357700
--------------------------------------------------------------------------------
| Id  | Operation        | Name        | ROWS  | Bytes | Cost (%CPU)| TIME     |
--------------------------------------------------------------------------------
|   0 | DELETE STATEMENT |             |     1 |    13 |   245   (1)| 00:00:03 |
|   1 |  DELETE          | T_DEL       |       |       |            |          |
|   2 |   INDEX FULL SCAN| SYS_C006177 |     1 |    13 |   245   (1)| 00:00:03 |
--------------------------------------------------------------------------------
Note
-----
   - dynamic sampling used FOR this statement (level=2)
 
Statistics
----------------------------------------------------------
        247  recursive calls
     124999  db block gets
        395  consistent gets
        270  physical reads
   43099720  redo SIZE
        678  bytes sent via SQL*Net TO client
        585  bytes received via SQL*Net FROM client
          3  SQL*Net roundtrips TO/FROM client
          2  sorts (memory)
          0  sorts (disk)
     110360  ROWS processed
SQL> ROLLBACK;
ROLLBACK complete.
Elapsed: 00:00:00.92
SQL> DELETE /*+ full(t_del) */ t_del;
110360 ROWS deleted.
Elapsed: 00:00:04.63
Execution Plan
----------------------------------------------------------
Plan hash VALUE: 2195693323
----------------------------------------------------------------------------
| Id  | Operation          | Name  | ROWS  | Bytes | Cost (%CPU)| TIME     |
----------------------------------------------------------------------------
|   0 | DELETE STATEMENT   |       |     1 |    13 |   425   (0)| 00:00:06 |
|   1 |  DELETE            | T_DEL |       |       |            |          |
|   2 |   TABLE ACCESS FULL| T_DEL |     1 |    13 |   425   (0)| 00:00:06 |
----------------------------------------------------------------------------
Note
-----
   - dynamic sampling used FOR this statement (level=2)
 
Statistics
----------------------------------------------------------
        322  recursive calls
     346841  db block gets
       1731  consistent gets
        593  physical reads
   65160536  redo SIZE
        683  bytes sent via SQL*Net TO client
        604  bytes received via SQL*Net FROM client
          3  SQL*Net roundtrips TO/FROM client
          1  sorts (memory)
          0  sorts (disk)
     110360  ROWS processed
SQL> ROLLBACK;
ROLLBACK complete.
Elapsed: 00:00:01.69

显然无论从运行时间,还是db block gets数量,或者是逻辑读或物理读的数量,11.2的全索引扫描执行路径都要远小于全表扫描的方式,甚至连产生的redo的数据量都只有全表扫描的2/3,显然Oracle更改了删除操作的处理机制,才使得全索引扫描这种看上去完全不合理的执行计划可以提高性能。
DELETE操作是Oracle所有DML中代价最大的,看来Oracle认识到了这一点,也在试图改变这种情形。

Posted in ORACLE | Tagged , , | 1 Comment