Category Experience

遭遇ORA-17410及ORA-03137:TTC协议内部错误:[12333]

留下评论 ,

早上，项目组同事发过来一则应用系统连接数据库错误的请求技术支持，具体信息可见下述报错截图：

ora-17410

ora-17410

这则错误信息对于我还真是大姑娘上轿–头一回遇到。下面简单记录下处理错误的思路和方法：

环境说明：一套Linux X86_64位环境的Oracle 11gR2【11.2.0.1.0】的单实例数据库。应用系统通过调用Tomcat的JDBC驱动来访问数据，如下：

OS：

[oracle@oracle11g ~]$ uname -rm
2.6.18-194.el5 x86_64
[oracle@oracle11g ~]$

数据库：

SQL> select * from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
PL/SQL Release 11.2.0.1.0 - Production
CORE    11.2.0.1.0      Production
TNS for Linux: Version 11.2.0.1.0 - Production
NLSRTL Version 11.2.0.1.0 - Production

SQL>

同事说，上周五的时候，通过登录应用系统来访问数据库还一切正常，今天早上登录系统就报上述错误，更加觉得蹊跷。

1 首先，让同事登录应用系统，重现错误。然后查看alert日志文件，看到下述错误信息的线索：

Mon Sep 16 09:43:24 2013
Errors in file /u01/app/oracle/diag/rdbms/glndb/GLNDB/trace/GLNDB_ora_11692.trc  (incident=78959):
ORA-03137: TTC 协议内部错误: [12333] [6] [88] [77] [] [] [] []
Incident details in: /u01/app/oracle/diag/rdbms/glndb/GLNDB/incident/incdir_78959/GLNDB_ora_11692_i78959.trc
Mon Sep 16 09:43:27 2013
Trace dumping is performing id=[cdmp_20130916094327]
Mon Sep 16 09:43:28 2013
Sweep [inc][78959]: completed
Sweep [inc2][78959]: completed

2 根据alert日志提示，继续查看/u01/app/oracle/diag/rdbms/glndb/GLNDB/trace/GLNDB_ora_11692.trc文件，看到：

*** 2013-09-16 09:43:24.912
*** SESSION ID:(410.54431) 2013-09-16 09:43:24.912
*** CLIENT ID:() 2013-09-16 09:43:24.912
*** SERVICE NAME:(SYS$USERS) 2013-09-16 09:43:24.912
*** MODULE NAME:(JDBC Thin Client) 2013-09-16 09:43:24.912
*** ACTION NAME:() 2013-09-16 09:43:24.912

--- PROTOCOL VIOLATION DETECTED ---
...
...
...
  NamespaceDump:  
            Child Cursor:  Heap0=0x9fae5148 Heap6=0xb8bc6b48 Heap0 
Load Time=09-16-2013 09:43:24 Heap6 Load Time=09-16-2013 09:43:24 
  NamespaceDump:  
    Parent Cursor:  sql_id=4x3cjtfs37n4v parent=0xb21328e8 maxchild=5 plk=y ppn=n 
      Current Cursor Sharing Diagnostics Nodes:  
        Child Node: 3  ID=40 reason=Bind mismatch(33) size=2x4 
          init ranges in first pass: 1 
          selectivity: 0 
        Child Node: 2  ID=37 reason=Authorization Check failed(4) size=5x4 
          translation table position: 0 
          original handle: 3055622408 
          temp handle: 2705674440 
          schema: 161 
          synonym object number: 0 
        Child Node: 1  ID=3 reason=Optimizer mismatch(13) size=3x4 
          kxscflg: 32 
          kxscfl4: 4194560 
          dnum_kksfcxe: 1 
      Aged Out Cursor Sharing Diagnostic Nodes:  
        Child Node: 3  ID=37 reason=Authorization Check failed(4) size=5x4 
          translation table position: 0 
          original handle: 2705674440 
          temp handle: 3055622408 
          schema: 160 
          synonym object number: 0 
        Child Node: 2  ID=40 reason=Bind mismatch(25) size=0x0 
          extended cursor sharing:   
        Child Node: 1  ID=3 reason=Optimizer mismatch(13) size=3x4 
          kxscflg: 32 
          kxscfl4: 4194560 
          dnum_kksfcxe: 1 
        Child Node: 0  ID=37 reason=Authorization Check failed(4) size=5x4 
          translation table position: 0 
          original handle: 3055622408 
          temp handle: 2705674440 
          schema: 161 
          synonym object number: 0 
        Child Node: 0  ID=3 reason=Optimizer mismatch(13) size=3x4 
          kxscflg: 32 
          kxscfl4: 4194560 
          dnum_kksfcxe: 0 
        Child Node: 3  ID=37 reason=Authorization Check failed(4) size=5x4 
          translation table position: 0 
          original handle: 3055622408 
          temp handle: 2705674440 
          schema: 161 
          synonym object number: 0 
        Child Node: 2  ID=3 reason=Optimizer mismatch(13) size=3x4 
          kxscflg: 32 
          kxscfl4: 4194560 
          dnum_kksfcxe: 2 
        Child Node: 1  ID=37 reason=Authorization Check failed(4) size=5x4 
          translation table position: 0 
          original handle: 2705674440 
          temp handle: 3055622408 
          schema: 160 
          synonym object number: 0 
        Child Node: 0  ID=3 reason=Optimizer mismatch(13) size=3x4 
          kxscflg: 32 
          kxscfl4: 4194560 
          dnum_kksfcxe: 0 
        Child Node: 1  ID=37 reason=Authorization Check failed(4) size=5x4 
          translation table position: 0 
          original handle: 2705674440 
          temp handle: 3055622408 
          schema: 160 
          synonym object number: 0 
        Child Node: 0  ID=3 reason=Optimizer mismatch(13) size=3x4 
          kxscflg: 32 
          kxscfl4: 4194560 
          dnum_kksfcxe: 0 
        Child Node: 0  ID=3 reason=Optimizer mismatch(13) size=3x4 
          kxscflg: 32 
          kxscfl4: 4194560 
          dnum_kksfcxe: 0 
        Child Node: 0  ID=3 reason=Optimizer mismatch(13) size=3x4 
          kxscflg: 32 
          kxscfl4: 4194560 
          dnum_kksfcxe: 0 
        Child Node: 0  ID=3 reason=Optimizer mismatch(13) size=3x4 
          kxscflg: 32 
          kxscfl4: 4194560 
          dnum_kksfcxe: 0    kkscs=0xb2132df0 nxt=0xb21331f8 flg=11 cld=0 
hd=0xa1a00330 par=0xb21328e8
   Mutex 0xb2132df0(0, 0) idn 3000000000
   ct=19 hsh=0 unp=(nil) unn=0 hvl=b2133798 nhv=0 ses=(nil)
   hep=0xb2132e80 flg=80 ld=0 ob=(nil) ptr=(nil) fex=(nil)
   kkscs=0xb21331f8 nxt=0xb9a94588 flg=1a cld=1 hd=0xaf246848 par=0xb21328e8
   Mutex 0xb21331f8(0, 0) idn 0
   ct=12 hsh=0 unp=(nil) unn=0 hvl=b21336e0 nhv=0 ses=(nil)
   hep=0xb2133288 flg=80 ld=1 ob=0xb2c09860 ptr=0xab22a250 fex=0xab2295f0
   kkscs=0xb9a94588 nxt=0xb9a94930 flg=18 cld=2 hd=0xaf3c53e8 par=0xb21328e8
   Mutex 0xb9a94588(0, 0) idn 0
   ct=13 hsh=0 unp=(nil) unn=0 hvl=b21336a0 nhv=0 ses=(nil)
   hep=0xb9a94618 flg=80 ld=1 ob=0xb97655a0 ptr=0xa4e14f58 fex=0xa4e142f8
   kkscs=0xb9a94930 nxt=0xa840b1b0 flg=14 cld=3 hd=0xa1515da8 par=0xb21328e8
   Mutex 0xb9a94930(0, 0) idn 0
   ct=14 hsh=0 unp=(nil) unn=0 hvl=b2133638 nhv=1 ses=0xc0467f40
   hsv[0]=0
   hep=0xb9a949c0 flg=80 ld=1 ob=0xa81e1108 ptr=0xb16c2ea0 fex=0xb16c2240
   kkscs=0xa840b1b0 nxt=(nil) flg=18 cld=4 hd=0xaf3038c8 par=0xb21328e8
   Mutex 0xa840b1b0(0, 0) idn 0
   ct=19 hsh=0 unp=(nil) unn=0 hvl=b2133660 nhv=0 ses=(nil)
   hep=0xa840b240 flg=80 ld=1 ob=0x9fae5060 ptr=0xb8bc6b48 fex=0xb8bc5ee8
cursor instantiation=0x2ac85fded0d8 used=1379295804 exec_id=16777397 exec=1
 child#4(0xaf3038c8) pcs=0xa840b1b0
  clk=0xb6c31f68 ci=0x9fae5148 pn=0xaf984ba0 ctx=0xb8bc6b48
 kgsccflg=0 llk[0x2ac85fded0e0,0x2ac85fded0e0] idx=0
 xscflg=c0110676 fl2=5d000008 fl3=42222008 fl4=180
 sharing failure(s)=62000
----- Bind Info (kkscoacd) -----
 Bind#0
  oacdty=01 mxl=32(24) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000010 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=2ac85fdecae0  bln=32  avl=00  flg=05
 Frames pfr 0x2ac85fdecea8 siz=27104 efr 0x2ac85fdecd98 siz=27088
 kxscphp=0x2ac85fdc03d8 siz=984 inu=456 nps=408
 kxscbhp=0x2ac85fdc01f8 siz=984 inu=176 nps=56
 kxscwhp=0x2ac85fdc0798 siz=16352 inu=15344 nps=5160
Starting SQL statement dump
SQL Information
user_id=161 user_name=WX_TMS_TEST module=JDBC Thin Client action=
sql_id=4x3cjtfs37n4v plan_hash_value=-785040234 problem_type=4
----- Current SQL Statement for this session (sql_id=4x3cjtfs37n4v) -----
select distinct viewbutton5_.SYS_VIEW_BUTTON_ID as SYS1_155_, 
viewbutton5_.RECORD_VERSION as RECORD2_155_, viewbutton5_.BTN_NAME as BTN3_155_, viewbutton5_.BTN_TITLE_KEY as BTN4_155_, viewbutton5_.BTN_MSG_KEY as BTN5_155_,
viewbutton5_.BUTTON_URL as BUTTON6_155_, viewbutton5_.SYS_MENU_ITEM_ID as SYS7_155_ 
from SYS_ROLE_MENU_BUTTON rolemenubu0_ left outer join SYS_ROLE_MENU_ITEM rolemenuit1_ 
on rolemenubu0_.SYS_ROLE_MENU_ITEM_ID=rolemenuit1_.SYS_ROLE_MENU_ITEM_ID left outer 
join SYS_ROLE role2_ on rolemenuit1_.SYS_ROLE_ID=role2_.SYS_ROLE_ID left outer join 
SYS_ROLE_USER roleusers3_ on role2_.SYS_ROLE_ID=roleusers3_.SYS_ROLE_ID left 
outer join SYS_USER user4_ on roleusers3_.USER_ID=user4_.USER_ID inner join 
SYS_VIEW_BUTTON viewbutton5_ on 
rolemenubu0_.SYS_VIEW_BUTTON_ID=viewbutton5_.SYS_VIEW_BUTTON_ID where user4_.USER_CODE=:1
sql_text_length=837
sql=select distinct viewbutton5_.SYS_VIEW_BUTTON_ID as SYS1_155_, viewbutton5_.RECORD_VERSION as RECORD2_155_, viewbutton5_.BTN_NAME as BTN3_155_, viewbutton5_.BTN_TITLE_KEY as BTN4_155_, viewbutton5_.BTN_MSG_KEY as BTN5_155_, viewbutton5_.BUTTON_URL as BUTTON
sql=6_155_, viewbutton5_.SYS_MENU_ITEM_ID as SYS7_155_ from SYS_ROLE_MENU_BUTTON rolemenubu0_ 
left outer join SYS_ROLE_MENU_ITEM rolemenuit1_ on rolemenubu0_.SYS_ROLE_MENU_ITEM_ID=rolemenuit1_.SYS_ROLE_MENU_ITEM_ID left outer 
join SYS_ROLE role2_ on rolemenuit
sql=1_.SYS_ROLE_ID=role2_.SYS_ROLE_ID left outer join SYS_ROLE_USER roleusers3_ on role2_.SYS_ROLE_ID=roleusers3_.SYS_ROLE_ID left outer join SYS_USER user4_ on roleusers3_.USER_ID=user4_.USER_ID inner join SYS_VIEW_BUTTON viewbutton5_ on 
rolemenubu0_.SYS_VIEW
sql=_BUTTON_ID=viewbutton5_.SYS_VIEW_BUTTON_ID where user4_.USER_CODE=:1
...
...

3 看到这里，没有太好的解决思路。同事给出提示信息说，同一套库，另外一套应用环境下，通过WebLogic来访问数据库时，则不会报错。难道是因为JDBC的不同驱动导致的？寻求MetaLink，Troubleshooting ORA-3137 [12333] Errors Encountered When Using Oracle JDBC Driver (Doc ID 1361107.1)

通过Metalink上的提示，得到造成该错误的可能原因：

① 部分版本的JDBC驱动会引起该错误：

Bug 9445675  NO MORE DATA TO READ FROM SOCKET WHEN USING END-TO-END METRICS

This bug does affect the JDBC driver.  This bug may be the cause when all of the following conditions are met:

  1. You are using the 10.1.x.x or the 11.2.0.1 JDBC driver; the bug does not affect 10.2.x.x, or 11.1.x.x versions of the driver, nor versions 11.2.0.2 or above
  2. You are using end-to-end metrics in your Java code
  3. The server side ORA-3137 [12333] error is accompanied by the client side Java exception “No more data to read from socket”

This bug is fixed in the 11.2.0.2 version of the JDBC driver and above.  It is discussed in the following notes:

Note 9445675.8 Bug 9445675 – “No more data” / ORA-3137 using end to end metrics with JDBC Thin

Note 1081275.1 “java.sql.SQLRecoverableException: No more data to read from socket” is Thrown When End-to-end Metrics is Used

② 数据库自身的BUG也会导致该错误：

Unpublished Bug:9703463 – ORA-3137 [12333] or ORA-600 [kpobav-1] When Using Bind Peeking

This bug affects versions 11.1.0.6, 11.1.0.7, and 11.2.0.1 of the RDBMS.  It is fixed in version 11.2.0.2 of the database.

It can also occur intermittently; similarly to unpublished Bug:8625762, this is a bind peeking bug.

==================================================

Unpublished Bug 9373370  DATA BASE RETURNS WRONG CURSORID WHEN THERE IS AN ORA-01013

This bug affects the 10.2, 11.1, 11.2.0.1, and 11.2.0.2 databases.  It is discussed in the following note:

Note 9373370.8 Bug 9373370 – The wrong cursor may be executed by JDBC thin following a query timeout / ORA-3137 [12333]

While the bug primarily manifests in ORA-1006 or ORA-1008 errors, the problem may also result in ORA-600 [12333] or ORA-3137 [12333] errors appearing on the server side.

判断本案例的错误应该是 Bug:9703463导致的，从trace文件中看到该SQL语句的确用到了绑定变量，且数据库版本是11.2.0.1.0。

解决思路：

①  可以通过更换不同版本的JDBC驱动来避免该错误，也说明为什么同事在另外一套环境下，通过Weblogic的JDBC来访问数据库时，则不会遇到该错误；

② 给数据库打patch,初步认为可以通过打Patch:9703463 来解决；

③ 通过修改数据库参数来规避该错误：

修改之后，同事用之前的Tomcat那个版本的驱动来重新访问数据库时，则不再报错；

④ 直接升级数据库版本至11.2.0.3.0，通过导出导入的方式将刚项目组下的schema数据复制一份到一套11.2.0.3.0的库上，重新使用Tomcat那个版本的驱动来重新访问数据库时，亦不再报错。

同时遭遇row cache lock和enq: US – contention的等待事件

留下评论 , , ,

        上周五，接到项目组同事电话通知，说某客户应用系统无法登陆。我在应用服务器端用PL/SQL Developer尝试连接数据库服务器时，报错“ORA-00018:maximum number of sessions exceeded”，显然又是连接数不够用了。

         就电话回复同事说，赶紧检查一下各应用服务器的连接情况，原因是数据库连接数又不够用了。结果，同事接完电话之后，直接关闭了其中的一台IIS应用服务器，然后再启动这台IIS应用服务器。结果是，应用系统恢复了使用，大约20分钟后，却带了整个数据库的性能急剧下降，数据库Hung住，几乎不可用的状态。

        这是一套Windows 2003+10.2.0.5 X64的双节点RAC系统，接下来，就迅速抓取AWR报告，进行问题的定位：

        节点1的报告头：

  Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 6981 01-3月 -13 14:00:17 64 14.9
End Snap: 6982 01-3月 -13 15:00:13 186 17.2
Elapsed:   59.94 (mins)    
DB Time:   2,215.01 (mins)    

        节点2的报告头：

  Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 6981 01-3月 -13 14:00:14 65 14.2
End Snap: 6982 01-3月 -13 15:14:21 178 25.0
Elapsed:   74.12 (mins)    
DB Time:   2,991.16 (mins)    

        从上可以看到，在每个节点上，这一时段的数据库负载都很高，至少要比正常业务期间负载高出很多。同时，也看到，数据库连接数出现较为不太正常的连接。

       节点1的Top 5事件：

Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
db file sequential read 210,093 48,731 232 36.7 User I/O
enq: US – contention 73,040 36,420 499 27.4 Other
log file sync 146,401 14,330 98 10.8 Commit
row cache lock 11,636 13,801 1,186 10.4 Concurrency
CPU time   9,314   7.0  

        节点2的Top 5事件：

Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
row cache lock 33,305 49,524 1,487 27.6 Concurrency
enq: US – contention 94,368 46,710 495 26.0 Other
db file sequential read 450,346 38,795 86 21.6 User I/O
CPU time   16,797   9.4  
direct path write temp 18,587 13,857 746 7.7 User I/O

        看到，在2个节点上均出现了row cache lock和enq: US – contention的等待事件，尤其是第2个节点上更为严重。对于row cache lock等待事件，之前曾遇到过相关案例，原因同样是由于高并发的RAC环境下，sequence没有CACHE，迅速定位并解决了这个问题。

        那么，这个enq: US – contention等待事件究竟是什么呢？Google之，找到了类似的案例：异常终止会话导致系统被Hung，以及ITPUB上的一篇帖子：row cache lock+us contention=宕机
        原来，导致enq: US – contention等待事件的原因是Undo表空间不够导致的。结合上述案例的提示，原来是因为同事直接停止IIS应用服务器，导致Oracle需要回滚之间的事务，这样，如果之前的事务比较大的话，那么整个回滚的时间也将越长。同时，还有一种可能就是，当初的ACTIVE事务因为停止IIS导致了被强制终止，这样一来，该事务占有的回滚段资源没有释放出来。等到IIS重启之后，新连接上来的会话因为事务操作，需要分配新的UNDO表空间，结果导致了enq: US – contention等待事件。

        参照上述的两则案例，找出紧急解决办法，由于是RAC，这里交叉重启了2个节点，最后问题得到解决。         

如何正确手工启动Windows下的Oracle RAC数据库？

如何正确手工启动Windows下的Oracle RAC数据库？有4条评论 , ,

           这是一则来自于某德国客户生产环境的RAC数据库启动出现故障的案例，记录下来一是用于对自己的警醒，二是可以同广大网友分享。

           操作系统环境：Windows Server 2008 R2 Enterprise version 6.1(Build 7601:Service Pack 1)

           数据库环境：10gR2 10.2.0.5.0的64位RAC双节点数据库；

           上周末，在顺利地对RAC数据库的几张分区表做调整之后，正常关闭RAC数据库，并重新启动2台Windows 2008 R2的操作系统之后，尝试启动Oracle CRS时，发现报错：

           1 在任何一个节点的服务项里，启动OracleCRService服务时，报错，其中OracleCSService的状态一直停留在Starting状态，其它服务项无任何变化；

           2 重启Windows服务器后，使用$CRS_HOME\bin\crsctl start crs在命令行尝试启动CRS时，依然报错;

           3 接下去，开始检查CRS的错误日志：在C:\oracle\product\10.2.0\crs\log\dehamora002\crsd\crsd.log日志文件中看到下述报错信息：

              

2012-12-08 11:52:52.606: [  OCRMAS][3876]th_master:13: I AM THE NEW OCR MASTER at incar 2. Node Number 2
2012-12-08 11:52:52.606: [  OCROSD][3876]utgdv:11:could not read reg value ocrmirrorconfig_loc os error= The system could not find the environment option that was entered.

2012-12-08 11:52:52.621: [  OCROSD][3876]utgdv:11:could not read reg value ocrmirrorconfig_loc os error= The system could not find the environment option that was entered.

2012-12-08 11:52:52.637: [  OCRRAW][3876]proprioo: for disk 0 (\\.\ocrcfg), id match (1), my id set (1381592635,1028247821) total id sets (1), 1st set (1381592635,1028247821), 2nd set (0,0) my votes (2), total votes (2)
2012-12-08 11:52:52.715: [  OCRMAS][3876]th_master: Deleted ver keys from cache (master)

从上可以看出，问题应该是出现在服务器访问共享存储时出现的。果然，在远程联系德国汉堡客户IT人员检查后，发现是服务器同存储间出现了问题，协调并解决该错误。

 

           4 再次重启Windows，并尝试启动CRS时，C:\oracle\product\10.2.0\crs\log\dehamora002\cssd\cssdOUT.log日志文件中看到下述报错信息：

Oracle Database 10g CSS Release 10.2.0.5.0 Production Copyright 1996, 2004, Oracle.  All rights reserved.
12/08/12 12:02:06  ssmain_run_css:  launching boot check 1 with c:\oracle\product\10.2.0\crs\bin\crsctl.exe check boot
OCR initialization failed accessing OCR device: PROC-26: Error while accessing the physical storage Operating System error [The system cannot find the file specified.

] [2]
12/08/12 12:02:06  ssmain_run_css:  boot check returned 8, looping
12/08/12 12:02:07  ssmain_run_css:  launching boot check 2 with c:\oracle\product\10.2.0\crs\bin\crsctl.exe check boot
OCR initialization failed accessing OCR device: PROC-26: Error while accessing the physical storage Operating System error [The system cannot find the file specified.

] [2]
12/08/12 12:02:07  ssmain_run_css:  boot check returned 8, looping
12/08/12 12:02:08  ssmain_run_css:  launching boot check 3 with c:\oracle\product\10.2.0\crs\bin\crsctl.exe check boot
OCR initialization failed accessing OCR device: PROC-26: Error while accessing the physical storage Operating System error [The system cannot find the file specified.

] [2]

           通过查询Metalink：

Can not Start CRS on Windows Cluster [ID 1115153.1]

How to Start (or stop) 10gR2 or 11gR1 Oracle Clusterware Services Manually in Windows [ID 729512.1]

OracleCSService does not start – PROC-26 error possible [ID 305093.1]

           找到产生问题的原因：原来这套RAC环境下的所有Oracle服务都是手工启动的方式，正常情况下，手工启动OracleCRService服务时，会自动启动依赖的相关服务。而该环境下，oracle并没有如我们期待的那样去启动与OracleCRService相关的服务。

           准确定位到原因后，解决问题的办法其实也很简单，就是如Metalink文档上说明的方案，手工依次启动.  OracleObjectService 、OracleClusterVolumeService 、OracleCSService、OracleEVMService、OracleCRService  很快，RAC数据库重新正常启动！

        启示：

      1 对于Windows环境下的RAC，最好是将OracleObjectService的启动类型置为自动启动；

        2 如果上述服务是手工启动的，那么正确手工启动Windows下的Oracle RAC数据库的顺序依次是：OracleObjectService 、OracleClusterVolumeService(if using OCFS) 、OracleCSService、OracleEVMService、OracleCRService          

解决一则enq: TX – row lock contention的性能故障

解决一则enq: TX – row lock contention的性能故障有3条评论 , ,

            上周二早上，收到项目组的一封邮件：

       早上联代以下时间点用户有反馈EDI导入“假死”，我们跟踪了EDI导入服务，服务是正常在跑，可能是处理的慢所以用户感觉是“假死”了，请帮忙从数据库中检查跟踪以下时间点是否有“异常”操作，多谢！

        2012-11-20 9:10:10~~~~9:55:13,这个时间点内一共反馈了3次，大概是10~20分钟“假死”一次，请帮忙跟踪检查，多谢！

        这是一套Windows RAC的环境，也是之前处理  解决一则row cache lock引起的性能故障 那套环境。下面记录一下处理的经过：
1 对这一个小时进行AWR的收集和分析，首先，从报告头中看到DB Time达到近500分钟，(DB Time)/Elapsed=8，这个比值偏高：
  Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 15142 20-11月-12 09:00:05 62 5.8
End Snap: 15143 20-11月-12 10:00:56 74 8.3
Elapsed:   60.85 (mins)    
DB Time:   492.88 (mins)    
 
2 再看TOP 5事件：
看到排在第一位的是enq: TX – row lock contention事件，也就是说系统中在这一个小时里产生了较为严重的行级锁等待事件。

Top 5 Timed Events

Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
CPU time   21,215   71.7  
enq: TX – row lock contention 12,232 6,013 492 20.3 Application
gc cr multi block request 14,696,067 1,675 0 5.7 Cluster
gc buffer busy 441,472 719 2 2.4 Cluster
db file sequential read 4,191 25 6 .1 User I/O
 
 
通常，产生enq: TX – row lock contention事件的原因有以下几种可能：
  • 不同的session更新或删除同一条记录；
  • 唯一索引有重复索引；
  • 位图索引同时被更新或同时并发的向位图索引字段上插入相同字段值；
  • 并发的对同一个数据块上的数据进行update操作；
  • 等待索引块完成分裂；

同时，从段的统计信息章节中，也看到下面的信息：
Segments by Row Lock Waits
  • % of Capture shows % of row lock waits for each top segment compared
  • with total row lock waits for all segments captured by the Snapshot
Owner Tablespace Name Object Name Subobject Name Obj. Type Row Lock Waits % of Capture
SUNISCO SUNISCO_DATA1 BIND_PROCESS_LOG_REFNO   INDEX 159 67.66
SUNISCO FDN_EDI_I01 IDX_EDI_WORK_QUEUE_1   INDEX 29 12.34
SUNISCO SUNISCO_DATA1 IND_EDI_CUSTOMER_TYPE_CODE   INDEX 15 6.38
SUNISCO SUNISCO_DATA1 IDX_EDI_MESSAGE_1   INDEX 14 5.96
SUNISCO FDN_BASE_T01 BSE_NUM_LIST   TABLE 6 2.55



看到row lock waits发生在一个索引上。

3 那么，究竟是什么操作导致了这个enq: TX – row lock contention等待事件呢？ 查看系统中，当前有哪些会话产生了enq: TX – row lock contention等待事件？

SQL> select event,sid,p1,p2,p3 from v$session_wait where event='enq: TX - row lock contention';
 
EVENT                                                                   SID         P1         P2         P3
---------------------------------------------------------------- ---------- ---------- ---------- ----------
enq: TX - row lock contention                                           224 1415053316    1441815     144197
enq: TX - row lock contention                                           238 1415053316    1441815     144197
enq: TX - row lock contention                                           247 1415053316    1441815     144197
enq: TX - row lock contention                                           248 1415053316    1441815     144197
enq: TX - row lock contention                                           253 1415053316    1441815     144197
SQL>

看到SID为224,238,247,248,253的会话产生enq: TX – row lock contention等待事件。

4 查看系统中的当前会话，是在哪个对象上产生了产生了enq: TX – row lock contention等待事件？

SQL> select ROW_WAIT_OBJ#,ROW_WAIT_FILE#,ROW_WAIT_BLOCK#,ROW_WAIT_ROW# from v$session where event='enq: TX - row lock contention';
 
ROW_WAIT_OBJ# ROW_WAIT_FILE# ROW_WAIT_BLOCK# ROW_WAIT_ROW#
------------- -------------- --------------- -------------
       369195              0               0             0
       369195              0               0             0
       369195              0               0             0
       369195              0               0             0
       369195              0               0             0
       369195              0               0             0
 
6 rows selected
SQL>


5 那么这个数据库对象为369195的对象究竟是什么呢？

SQL> select object_name,object_id from dba_objects where object_id=369195;
 
OBJECT_NAME                          OBJECT_ID
----------------------------------- ----------
BIND_PROCESS_LOG_REFNO                  369195
SQL> select OWNER,OBJECT_NAME,OBJECT_ID,DATA_OBJECT_ID, OBJECT_TYPE from dba_objects where object_name='BIND_PROCESS_LOG_REFNO';
 
OWNER                          OBJECT_NAME                    OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ----------------------------- ---------- -------------- -------------------
SUNISCO                        BIND_PROCESS_LOG_REFNO            369195         369195 INDEX
SQL>

可以看到，定位到的结果同上述AWR报告中段统计信息吻合，是SUNISCO这个用户下的一个索引。

6 接下来，继续看看SID为224,238,247,248,253的会话到底在执行哪些操作导致enq: TX – row lock contention等待事件？

SQL> select sid,sql_text from v$session a,v$sql b where sid in(224,238,247,248,253) and (b.sql_id=a.sql_id or b.sql_id=a.prev_sql_id);
 
       SID SQL_TEXT
---------- --------------------------------------------------------------------------------
       224 select count(1)  from EDI_MESSAGE_PROCESS_LOG where   (LOG_ID =  :P_0_0  )
       224 INSERT INTO EDI_MESSAGE_PROCESS_LOG(LOG_ID, SERVICE_TYPE, SERVICE_STATUS, INFO_C
       238 select count(1)  from EDI_MESSAGE_PROCESS_LOG where   (LOG_ID =  :P_0_0  )
       238 INSERT INTO EDI_MESSAGE_PROCESS_LOG(LOG_ID, SERVICE_TYPE, SERVICE_STATUS, INFO_C
       247 INSERT INTO EDI_MESSAGE_PROCESS_LOG(LOG_ID, SERVICE_TYPE, SERVICE_STATUS, REFNO,
       247 INSERT INTO EDI_MESSAGE_PROCESS_LOG(LOG_ID, SERVICE_TYPE, SERVICE_STATUS, REFNO,
       248 INSERT INTO EDI_MESSAGE_PROCESS_LOG (LOG_ID, SERVICE_TYPE, SERVICE_STATUS, REFNO
       248 INSERT INTO EDI_MESSAGE_PROCESS_LOG (LOG_ID, SERVICE_TYPE, SERVICE_STATUS, REFNO
       248 SELECT SEQ_NEWID.NEXTVAL FROM DUAL
       253 SELECT SEQ_NEWID.NEXTVAL FROM DUAL
       253 INSERT INTO EDI_MESSAGE_PROCESS_LOG (LOG_ID, SERVICE_TYPE, SERVICE_STATUS, REFNO
 
11 rows selected
 
SQL>

看到有SQL_ID不同的SQL在同时向EDI_MESSAGE_PROCESS_LOG这张表执行INSERT操作。

7 接下去看看EDI_MESSAGE_PROCESS_LOG这张表和索引BIND_PROCESS_LOG_REFNO之间有没有什么关系？

SQL> select index_name,table_name,index_type from user_indexes where table_name='EDI_MESSAGE_PROCESS_LOG';

INDEX_NAME                     TABLE_NAME                     INDEX_TYPE
------------------------------ ------------------------------ ----------
PK_EDI_MESSAGE_PROCESS_LOG     EDI_MESSAGE_PROCESS_LOG        NORMAL
ID_EDI_LOG_INPUT_DATE          EDI_MESSAGE_PROCESS_LOG        NORMAL
BIND_PROCESS_LOG_REFNO         EDI_MESSAGE_PROCESS_LOG        BITMAP

SQL> select index_name,table_name,column_name from user_ind_columns where table_name='EDI_MESSAGE_PROCESS_LOG';

INDEX_NAME                     TABLE_NAME                     COLUMN_NAM
------------------------------ ------------------------------ ----------
PK_EDI_MESSAGE_PROCESS_LOG     EDI_MESSAGE_PROCESS_LOG        LOG_ID
ID_EDI_LOG_INPUT_DATE          EDI_MESSAGE_PROCESS_LOG        INPUT_DATE
BIND_PROCESS_LOG_REFNO         EDI_MESSAGE_PROCESS_LOG        REFNO

SQL> select object_name,object_id,object_type,created from user_objects where object_name='BIND_PROCESS_LOG_REFNO';

OBJECT_NAME                     OBJECT_ID OBJECT_TYPE     CREATED
------------------------------ ---------- --------------- -------------------
BIND_PROCESS_LOG_REFNO             369195 INDEX           2012/11/05 10:18:28

SQL> select index_name,index_type from user_indexes where index_name='BIND_PROCESS_LOG_REFNO';

INDEX_NAME                      INDEX_TYPE
------------------------------- -----------
BIND_PROCESS_LOG_REFNO          BITMAP

SQL>

发现，这个索引BIND_PROCESS_LOG_REFNO是位于EDI_MESSAGE_PROCESS_LOG这张表的REFNO字段上的一个位图索引，而且是2012/11/05 10:18:28创建的，也就是说是近期才创建的1个位图索引。

问题定位到这一步基本比较清晰了，产生enq: TX – row lock contention事件的原因就是上述的第2个可能原因：位图索引同时被更新或同时并发的向位图索引字段上插入相同字段值。

8 那么，解决的办法也比较简单了，就是干掉这个位图索引，因为这个位图索引在这种应用场景下确实不太适合。事后，经过同客户方沟通确认，该索引是他们的一个DBA当初看到系统比较慢，而加上去的一个位图索引。

9 补充，从当时的ADDM报告中，也可以看到数据库给我们的建议：

FINDING 4: 20% impact (6013 seconds)
------------------------------------
发现 SQL 语句正处于行锁定等待。

   RECOMMENDATION 1: Application Analysis, 17% benefit (5131 seconds)
      ACTION: 在 INDEX "SUNISCO.BIND_PROCESS_LOG_REFNO" (对象 ID 为 369195)
         中检测到了严重的行争用。使用指定的阻塞 SQL 语句在应用程序逻辑中跟踪行争
用的起因。
         RELEVANT OBJECT: database object with id 369195
      RATIONALE: SQL_ID 为 "dr4uxu769tmmb" 的 SQL 语句在行锁上被阻塞。
         RELEVANT OBJECT: SQL statement with SQL_ID dr4uxu769tmmb
         INSERT INTO EDI_MESSAGE_PROCESS_LOG(LOG_ID, SERVICE_TYPE,
         SERVICE_STATUS, LOG_DATETIME, REFNO, REF_TYPE, MSG_ID, BL_NO, BL_ID,
         VOYAGE_ID, VESSEL_NAME, IMO_NO, VOYAGE_NO, FUNCTION_TYPE, INPUT_DATE,
         IN_STATUS, SYSTEM_TYPE, ERROR_LOG, FILE_NAME) VALUES ( :B1 , :B2 ,
         :B3 , :B4 , :B5 , :B6 , :B7 , :B8 , :B9 , :B10 , :B11 , :B12 , :B13 ,
         :B14 , :B15 , :B16 , :B17 , :B18 , :B19 )
      RATIONALE: SQL_ID 为 "dxsbgubsb6r4n" 的 SQL 语句在行锁上被阻塞。
         RELEVANT OBJECT: SQL statement with SQL_ID dxsbgubsb6r4n
         INSERT INTO EDI_MESSAGE_PROCESS_LOG(LOG_ID, SERVICE_TYPE,
         SERVICE_STATUS, INFO_CODE, INFORMATION, INFO_LEVEL, LOG_DATETIME,
         REFNO, REF_TYPE, MSG_ID, BL_NO, VOYAGE_ID, VESSEL_NAME, IMO_NO,
         VOYAGE_NO, FUNCTION_TYPE, INPUT_DATE, IN_STATUS, SYSTEM_TYPE,
         ERROR_LOG, FILE_NAME) VALUES ( :B1 , :B2 , :B3 , :B4 , :B5 , :B6 ,
         :B7 , :B8 , :B9 , :B10 , :B11 , :B12 , :B13 , :B14 , :B15 , :B16 ,
         :B17 , :B18 , :B19 , :B20 , :B21 )
      RATIONALE: SQL_ID 为 "b38qhyzvn5bdd" 的 SQL 语句在行锁上被阻塞。
         RELEVANT OBJECT: SQL statement with SQL_ID b38qhyzvn5bdd
         INSERT INTO EDI_MESSAGE_PROCESS_LOG(LOG_ID, SERVICE_TYPE,
         SERVICE_STATUS, LOG_DATETIME, REFNO, REF_TYPE, MSG_ID, BL_NO,
         VOYAGE_ID, VESSEL_NAME, IMO_NO, VOYAGE_NO, FUNCTION_TYPE, INPUT_DATE,
         IN_STATUS, SYSTEM_TYPE, ERROR_LOG, FILE_NAME) VALUES ( :B1 , :B2 ,
         :B3 , :B4 , :B5 , :B6 , :B7 , :B8 , :B9 , :B10 , :B11 , :B12 , :B13 ,
         :B14 , :B15 , :B16 , :B17 , :B18 )
      RATIONALE: SQL_ID 为 "36k2xpx3c6wr5" 的 SQL 语句在行锁上被阻塞。
         RELEVANT OBJECT: SQL statement with SQL_ID 36k2xpx3c6wr5
         INSERT INTO EDI_MESSAGE_PROCESS_LOG(LOG_ID, SERVICE_TYPE,
         SERVICE_STATUS, REFNO, REF_TYPE, MSG_ID, BL_NO, VOYAGE_ID,
         VESSEL_NAME, IMO_NO, VOYAGE_NO, FUNCTION_TYPE, INPUT_DATE, IN_STATUS,
         SYSTEM_TYPE, ERROR_LOG, FILE_NAME) VALUES ( :B1 , :B2 , :B3 , :B4 ,
         :B5 , :B6 , :B7 , :B8 , :B9 , :B10 , :B11 , :B12 , :B13 , :B14 , :B15
         , :B16 , :B17 )
      RATIONALE: 具有 ID "268", 用户 ID "31", 程序 "FC.EdiService.Import.exe" 和
模块
         "FC.EdiService.Import.exe" 的会话是构成此建议案中的优化建议的 51% 的阻
塞会话。
      RATIONALE: 具有 ID "307", 用户 ID "31", 程序 "FC.EdiService.Import.exe" 和
模块
         "FC.EdiService.Import.exe" 的会话是构成此建议案中的优化建议的 11% 的阻
塞会话。
      RATIONALE: 具有 ID "227", 用户 ID "31", 程序 "FC.EdiService.Import.exe" 和
模块
         "FC.EdiService.Import.exe" 的会话是构成此建议案中的优化建议的 11% 的阻
塞会话。
      RATIONALE: 具有 ID "273", 用户 ID "31", 程序 "FC.EdiService.Import.exe" 和
模块
         "FC.EdiService.Import.exe" 的会话是构成此建议案中的优化建议的 9% 的阻塞
会话。


10 最后，从本案例中，可以看到在日常的数据库维护中，添加或修改一些对象信息时，务必要经过严格的测试，尤其是在生产系统上做调整更应如此。同样，可以看出，数据库的一些理论基础知识对于DBA还是蛮重要的。

 

解决一则ORA-00600[kcratr_nab_less_than_odr]的故障

解决一则ORA-00600[kcratr_nab_less_than_odr]的故障有2条评论 , ,

       临近中午，收到某客户生产库的故障请求：数据库出现了ORA-00600的错误！现在数据库启不来，影响业务的运行。

       故障场景描述：这是我之前服务过的一家客户，是一套跑在Linux机器上的11gR2单实例数据库，由于服务器异常断电导致的故障！印象较为深刻的是就在2011年2月14日情人节那天，这个库也曾出现过另外一则ORA-00600的错误。较为不幸的是，就在今天又遭遇到这个ORA-600的错误！

        下面记录一下这次故障的处理过程：

        1 启库时遭遇ORA-600的错误：

[oracle@os5 ~]$ uname -rm
2.6.18-128.el5PAE i686
[oracle@os5 ~]$ ps -ef|grep asm_
oracle    9099  9068  0 10:54 pts/8    00:00:00 grep asm_
[oracle@os5 ~]$ ps -ef|grep ora_
oracle    4797     1  0 10:52 ?        00:00:00 ora_pmon_database
oracle    4799     1  0 10:52 ?        00:00:00 ora_vktm_database
oracle    4803     1  0 10:52 ?        00:00:00 ora_gen0_database
oracle    4805     1  0 10:52 ?        00:00:00 ora_diag_database
oracle    4807     1  0 10:52 ?        00:00:00 ora_dbrm_database
oracle    4809     1  0 10:52 ?        00:00:00 ora_psp0_database
oracle    4811     1  0 10:52 ?        00:00:01 ora_dia0_database
oracle    4813     1  0 10:52 ?        00:00:00 ora_mman_database
oracle    4815     1  0 10:52 ?        00:00:00 ora_dbw0_database
oracle    4817     1  0 10:52 ?        00:00:00 ora_lgwr_database
oracle    4819     1  0 10:52 ?        00:00:00 ora_ckpt_database
oracle    4821     1  0 10:52 ?        00:00:00 ora_smon_database
oracle    4823     1  0 10:52 ?        00:00:00 ora_reco_database
oracle    4825     1  0 10:52 ?        00:00:00 ora_mmon_database
oracle    4827     1  0 10:52 ?        00:00:00 ora_mmnl_database
oracle    4829     1  0 10:52 ?        00:00:00 ora_d000_database
oracle    4831     1  0 10:52 ?        00:00:00 ora_s000_database
oracle    9105  9068  0 11:55 pts/8    00:00:00 grep ora_ 
[oracle@os5 ~]$ sqlplus / as sysdba

SQL*Plus: Release 11.2.0.1.0 Production on Wed Nov 21 10:54:16 2012

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


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options


SQL> alter database open;
alter database open
*
ERROR at line 1:
ORA-00600: internal error code, arguments: [kcratr_nab_less_than_odr], [1],
[3464], [12432], [12534], [], [], [], [], [], [], []


SQL> select open_mode from v$database;

OPEN_MODE
--------------------
MOUNTED

SQL>

          从上可以看到，当前数据库停留在MOUNT状态，没法OPEN，然后，就用RMAN重新做了个全备，并手工拷贝了联机日志文件，保留现场！

         2 接下来，重新尝试以RESETLOGS方式也打不开，尝试RECOVER依然报错！

SQL> alter database open resetlogs;
alter database open resetlogs
*
ERROR at line 1:
ORA-01139: RESETLOGS option only valid after an incomplete database recovery


SQL> recover database;
ORA-00283: recovery session canceled due to errors
ORA-00264: no recovery required


SQL> alter database open;
alter database open
*
ERROR at line 1:
ORA-00600: internal error code, arguments: [kcratr_nab_less_than_odr], [1], [3464], [12432], [12534], [], [], [], [], [], [], []


SQL>

        3  那么接下来，看看ALERT日志都记录哪些有用的信息：

Wed Nov 21 10:59:16 2012
alter database open
Beginning crash recovery of 1 threads
 parallel recovery started with 2 processes
Started redo scan
Completed redo scan
 read 1642 KB redo, 0 data blocks need recovery
Errors in file /oracle/ora11gR2/diag/rdbms/database/database/trace/database_ora_4848.trc  (incident=129790):
ORA-00600: internal error code, arguments: [kcratr_nab_less_than_odr], [1], [3464], [12432], [12534], [], [], [], [], [], [], []
Incident details in: /oracle/ora11gR2/diag/rdbms/database/database/incident/incdir_129790/database_ora_4848_i129790.trc
Aborting crash recovery due to error 600
Errors in file /oracle/ora11gR2/diag/rdbms/database/database/trace/database_ora_4848.trc:
ORA-00600: internal error code, arguments: [kcratr_nab_less_than_odr], [1], [3464], [12432], [12534], [], [], [], [], [], [], []
Errors in file /oracle/ora11gR2/diag/rdbms/database/database/trace/database_ora_4848.trc:
ORA-00600: internal error code, arguments: [kcratr_nab_less_than_odr], [1], [3464], [12432], [12534], [], [], [], [], [], [], []
ORA-600 signalled during: alter database open...
Wed Nov 21 10:59:17 2012
Sweep [inc][129790]: completed
Sweep [inc2][129790]: completed
Wed Nov 21 10:59:17 2012
Trace dumping is performing id=[cdmp_20121121105917]
Wed Nov 21 11:07:50 2012
db_recovery_file_dest_size of 3852 MB is 0.00% used. This is a
user-specified limit on the amount of space that will be used by this
database for recovery-related files, and does not reflect the amount of
space available in the underlying filesystem or ASM diskgroup.

        从alert里，一直看到ORA-00600: internal error code, arguments: [kcratr_nab_less_than_odr], [1], [3464], [12432], [12534], [], [], [], [], [], [], []的错误，还有一些提示就是Errors in file /oracle/ora11gR2/diag/rdbms/database/database/trace/database_ora_4848.trc。

        4 就去看看上述的TRACE文件：

*** 2012-11-21 10:59:16.123
Successfully allocated 2 recovery slaves
Using 66 overflow buffers per recovery slave
Thread 1 checkpoint: logseq 3464, block 4945, scn 203336710
  cache-low rba: logseq 3464, block 9148
    on-disk rba: logseq 3464, block 12534, scn 203340512
  start recovery at logseq 3464, block 9148, scn 0

*** 2012-11-21 10:59:16.144
Started writing zeroblks thread 1 seq 3464 blocks 12432-12439

*** 2012-11-21 10:59:16.144
Completed writing zeroblks thread 1 seq 3464
==== Redo read statistics for thread 1 ====
Total physical reads (from disk and memory): 4096Kb
-- Redo read_disk statistics --
Read rate (ASYNC): 1642Kb in 0.02s => 80.18 Mb/sec
Longest record: 14Kb, moves: 0/1953 (0%)
Change moves: 22/192 (11%), moved: 0Mb
Longest LWN: 445Kb, moves: 0/733 (0%), moved: 0Mb
Last redo scn: 0x0000.0c1eba6c (203340396)
----------------------------------------------
----- Recovery Hash Table Statistics ---------
Hash table buckets = 32768
Longest hash chain = 0
Average hash chain = 0/0 = 0.0
Max compares per lookup = 0
Avg compares per lookup = 0/0 = 0.0
----------------------------------------------
WARNING! Crash recovery of thread 1 seq 3464 is
ending at redo block 12432 but should not have ended before
redo block 12534
Incident 129790 created, dump file: /oracle/ora11gR2/diag/rdbms/database/database/incident/incdir_129790/database_ora_4848_i129790.trc
ORA-00600: internal error code, arguments: [kcratr_nab_less_than_odr], [1], [3464], [12432], [12534], [], [], [], [], [], [], []

ORA-00600: internal error code, arguments: [kcratr_nab_less_than_odr], [1], [3464], [12432], [12534], [], [], [], [], [], [], []
ORA-00600: internal error code, arguments: [kcratr_nab_less_than_odr], [1], [3464], [12432], [12534], [], [], [], [], [], [], []

        5 结合ALERT里的错误ORA-00600: internal error code, arguments: [kcratr_nab_less_than_odr], [1], [3464], [12432], [12534], 和TRACE里的错误提示WARNING! Crash recovery of thread 1 seq 3464 is ending at redo block 12432 but should not have ended before redo block 12534 以及查询MetaLink文档ID 1299564.1获取的指导性信息，应该是由于服务器异常断电，导致LGWR写联机日志文件时失败，下次重新启动数据库时，需要做实例级恢复，而又无法从联机日志文件里获取到这些redo信息，因为上次断电时，写日志失败了。

          那么ORA-00600的错误里，那几个参数 [1], [3464], [12432], [12534]又表示什么呢？ 从EYGLE的网站上查询到类似的案例信息，结合本故障场景分析，原来是实例需要恢复日志序列号为3464的联机日志文件，需要恢复到编号为12534的日志块，而实际上只能恢复到第12432个日志块儿，所以库就启不来了。不过，从当前日志文件信息，可以看到，当前日志组的确是3464：

SQL> alter session set nls_date_format='yyyy/mm/dd hh24:mi:ss';

Session altered.

SQL> select * from v$log;

    GROUP#    THREAD#  SEQUENCE#      BYTES  BLOCKSIZE    MEMBERS ARC STATUS           FIRST_CHANGE# FIRST_TIME          NEXT_CHANGE# NEXT_TIME
---------- ---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- ------------------- ------------ -------------------
         1          1       3463   52428800        512          1 YES INACTIVE             203285629 2012/11/21 03:00:32    203335249 2012/11/21 08:59:46
         3          1       3462   52428800        512          1 YES INACTIVE             203238520 2012/11/20 21:00:52    203285629 2012/11/21 03:00:32
         2          1       3464   52428800        512          1 NO  CURRENT              203335249 2012/11/21 08:59:46   2.8147E+14

SQL>

        6 参照MetaLink文档ID 1299564.1的方案来恢复数据库：

       

SQL> recover database until cancel using backup controlfile;
ORA-00279: change 203360397 generated at 11/21/2012 09:21:51 needed for thread 1
ORA-00289: suggestion : /home/oracle/archive_no_delete/ARC_743097220_0000003464_1.arc
ORA-00280: change 203360397 for thread 1 is in sequence #3464


Specify log: {=suggested | filename | AUTO | CANCEL}
/oracle/ora11gR2/oradata/database/redo02.log
Log applied.
Media recovery complete.
SQL> alter database open ;
alter database open
*
ERROR at line 1:
ORA-01589: must use RESETLOGS or NORESETLOGS option for database open


SQL>  alter database open resetlogs;

Database altered.

SQL>

          至此，这个库是成功恢复，并且启动了。恢复之后，再次对数据库做了备份。看到Alert日志信息：

Wed Nov 21 12:43:44 2012
ALTER DATABASE RECOVER    LOGFILE '/oracle/ora11gR2/oradata/database/redo02.log'  
Media Recovery Log /oracle/ora11gR2/oradata/database/redo02.log
Wed Nov 21 12:43:44 2012
Incomplete recovery applied all redo ever generated.
Recovery completed through change 203360398 time 11/21/2012 09:21:51
Media Recovery Complete (database)
Completed: ALTER DATABASE RECOVER    LOGFILE '/oracle/ora11gR2/oradata/database/redo02.log'  
Wed Nov 21 12:43:55 2012
alter database open 
Errors in file /oracle/ora11gR2/diag/rdbms/database/database/trace/database_ora_10698.trc:
ORA-01589: must use RESETLOGS or NORESETLOGS option for database open
ORA-1589 signalled during: alter database open ...
Wed Nov 21 12:44:37 2012
 alter database open resetlogs
Archived Log entry 3382 added for thread 1 sequence 3463 ID 0xd9842c95 dest 1:
Archived Log entry 3383 added for thread 1 sequence 3464 ID 0xd9842c95 dest 1:
Archived Log entry 3384 added for thread 1 sequence 3462 ID 0xd9842c95 dest 1:
RESETLOGS after complete recovery through change 203360398
Resetting resetlogs activation ID 3649318037 (0xd9842c95)
Wed Nov 21 12:44:43 2012
Setting recovery target incarnation to 4
Wed Nov 21 12:44:43 2012
Assigning activation ID 3706166088 (0xdce79b48)
LGWR: STARTING ARCH PROCESSES
Wed Nov 21 12:44:43 2012
ARC0 started with pid=24, OS id=11236 
ARC0: Archival started
LGWR: STARTING ARCH PROCESSES COMPLETE
ARC0: STARTING ARCH PROCESSES
Wed Nov 21 12:44:44 2012
ARC1 started with pid=25, OS id=11238 
Wed Nov 21 12:44:44 2012
ARC2 started with pid=26, OS id=11240 
Thread 1 opened at log sequence 1
  Current log# 1 seq# 1 mem# 0: /oracle/ora11gR2/oradata/database/redo01.log
Successful open of redo thread 1
MTTR advisory is disabled because FAST_START_MTTR_TARGET is not set
Wed Nov 21 12:44:44 2012
SMON: enabling cache recovery
ARC1: Archival started
ARC2: Archival started
Wed Nov 21 12:44:44 2012
ARC3 started with pid=29, OS id=11242 
ARC1: Becoming the 'no FAL' ARCH
ARC1: Becoming the 'no SRL' ARCH
ARC2: Becoming the heartbeat ARCH
Successfully onlined Undo Tablespace 2.
Dictionary check beginning
Dictionary check complete
Verifying file header compatibility for 11g tablespace encryption..
Verifying 11g file header compatibility for tablespace encryption completed

 

        从Metalink上看到，目前这个ORA-600的错误应该只有在Oracle 11g上才有的。    

记录一则Windows操作系统重装后的Oracle数据库恢复

留下评论 ,

           案例背景：一套跑在Windows 2K3 SP1 32位系统下的Oracle 10g 10.2.0.2.0的单实例数据库，数据库软件和数据库文件都放在D盘。遭遇到该服务器主板故障之后，更换主板，重新安装Windows 2K3 SP1 32位操作系统。成功配置好Windows操作系统之后，下面简单记录一下这个案例的恢复过程。

           1 将之前的数据库安装目录重命名，将D:\oracle 重命名为D:\oracle_old；

           2 重新安装Oracle软件，不建库，数据库版本同之前的版本一致，并且将安装目录指向D:\oracle；

           3 再次将新安装的D:\oracle重命名为D:\oracle_new，重命名第1步骤中的D:\oracle_old为D:\oracle：

           4 重新配置监听，设置ORACLE_SID环境变量，环境变量同之前的ORACLE_SID=cssdb，创建Oracle数据库服务：

C:\Documents and Settings\huangw>set oracle_sid=cssdb

C:\Documents and Settings\huangw>oradim
ORADIM:  [options].  Refer to manual.
Enter one of the following command:
Create an instance by specifying the following options:
     -NEW -SID sid | -SRVC srvc | -ASMSID sid | -ASMSRVC srvc [-SYSPWD pass]
 [-STARTMODE auto|manual] [-SRVCSTART system|demand] [-PFILE file | -SPFILE]
 [-SHUTMODE normal|immediate|abort] [-TIMEOUT secs] [-RUNAS osusr/ospass]
Edit an instance by specifying the following options:
     -EDIT -SID sid | -ASMSID sid [-SYSPWD pass]
 [-STARTMODE auto|manual] [-SRVCSTART system|demand] [-PFILE file | -SPFILE]
 [-SHUTMODE normal|immediate|abort] [-SHUTTYPE srvc|inst] [-RUNAS osusr/ospass]
Delete instances by specifying the following options:
     -DELETE -SID sid | -ASMSID sid | -SRVC srvc | -ASMSRVC srvc
Startup services and instance by specifying the following options:
     -STARTUP -SID sid | -ASMSID sid [-SYSPWD pass]
 [-STARTTYPE srvc|inst|srvc,inst] [-PFILE filename | -SPFILE]
Shutdown service and instance by specifying the following options:
     -SHUTDOWN -SID sid | -ASMSID sid [-SYSPWD pass]
 [-SHUTTYPE srvc|inst|srvc,inst] [-SHUTMODE normal|immediate|abort]
 Query for help by specifying the following parameters: -? | -h | -help

C:\Documents and Settings\huangw>oradim -new -sid cssdb
Instance created.

C:\Documents and Settings\huangw>

           5 调用SQL*PLUS，发现权限不足的错误，重建口令文件，执行口令文件验证登录：

C:\Documents and Settings\huangw>oradim -new -sid cssdb
Instance created.

C:\Documents and Settings\huangw>sqlplus /nolog

SQL*Plus: Release 10.2.0.2.0 - Production on Mon Nov 19 18:21:39 2012

Copyright (c) 1982, 2005, Oracle.  All Rights Reserved.

SQL> conn / as sysdba
ERROR:
ORA-01031: insufficient privileges


SQL> exit

C:\Documents and Settings\huangw>
C:\Documents and Settings\huangw>orapwd file=PWDCSSDB.ora password=dehamdb entri
es=10

C:\Documents and Settings\huangw>sqlplus /nolog

SQL*Plus: Release 10.2.0.2.0 - Production on Mon Nov 19 18:23:49 2012

Copyright (c) 1982, 2005, Oracle.  All Rights Reserved.

SQL> conn / as sysdba
ERROR:
ORA-01031: insufficient privileges


SQL> conn sys/dehamdb as sysdba
Connected to an idle instance.
SQL>

           6 直接启库，完成。


        小结：该案例的幸运之处在于Oracle软件和数据库文件都在D盘，Windows系统崩溃之后，只是影响到C盘下的数据和文件，好在对D盘下的文件没有破坏。其实重命名D:\oracle文件，以及重新安装oracle数据库软件的目的无非就是重新将Oracle软件的注册信息，环境变量等信息重新写到Windows系统和注册表中而已。

        最后，在系统的环境变量中重新添加ORACLE_SID和在系统服务项中将OracleServiceCSSDB服务配置为自动启动。

Oracle索引组织表学习系列二

留下评论 , ,

4 索引组织表(IOT Index-Organized Table)适用什么场景

       在上一篇文章里，提到了IOT表的基本概念和创建的一些注意事项，接下来讨论一下关于IOT表和Heap使用的一个测试对比，用以说明IOT表适用于什么场景。

1 构建一个主表emp表：

[oracle@oracle11g arch_new]$ sqlplus 

SQL*Plus: Release 11.2.0.1.0 Production on Thu Nov 15 10:15:19 2012

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


Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning and Automatic Storage Management options

SQL> conn hr/hr
Connected.
SQL> create table emp
  2  as
  3  select object_id empno,
  4  object_name ename,
  5  created hiredate,
  6  owner job
  7  from all_objects
  8  ;

Table created.

SQL> select count(*) from emp;

  COUNT(*)
----------
     55636

SQL> alter table emp add constraint emp_pk primary key(empno);

Table altered.

SQL> exec dbms_stats.gather_table_stats(user,'EMP',cascade=>true);

PL/SQL procedure successfully completed.

SQL>

 

2  构建一张子表，子表分别通过Heap和IOT两种方式来实现：

构建Heap类型子表：

SQL> create table heap_addresses
  2  ( empno references emp(empno) on delete cascade,
  3  addr_type varchar2(10),
  4  street varchar2(20),
  5  city varchar2(20),
  6  state varchar2(2),
  7  zip number,
  8  primary key (empno,addr_type)
  9  );

Table created.

SQL>

构建IOT类型子表：

SQL> create table iot_addresses
  2  ( empno references emp(empno) on delete cascade,
  3  addr_type varchar2(10),
  4  street varchar2(20),
  5  city varchar2(20),
  6  state varchar2(2),
  7  zip number,
  8  primary key (empno,addr_type)
  9  )
 10  ORGANIZATION INDEX
 11  ;

Table created.

SQL>

3  分别向两种子表里构造数据，插入WORK，HOME，ORIGINAL，SCHOOL地址：

Heap类型子表插入：

SQL> insert into heap_addresses
  2  select empno, 'WORK', '123 main street', 'Washington', 'DC', 20123
  3  from emp;

55636 rows created.

SQL> insert into heap_addresses
  2  select empno, 'HOME', '123 main street', 'Washington', 'DC', 20123
  3  from emp;

55636 rows created.

SQL> insert into heap_addresses
  2  select empno, 'ORIGINAL', '123 main street', 'Washington', 'DC', 20123
  3  from emp;

55636 rows created.

SQL> insert into heap_addresses
  2  select empno, 'SCHOOL', '123 main street', 'Washington', 'DC', 20123
  3  from emp;

55636 rows created.

SQL> select count(*) from heap_addresses;

  COUNT(*)
----------
    222544

SQL>

IOT类型子表插入：

SQL> insert into iot_addresses
  2  select empno, 'WORK', '123 main street', 'Washington', 'DC', 20123
  3  from emp;

55636 rows created.

SQL> insert into iot_addresses
  2  select empno, 'HOME', '123 main street', 'Washington', 'DC', 20123
  3  from emp;

55636 rows created.

SQL> insert into iot_addresses
  2  select empno, 'ORIGINAL', '123 main street', 'Washington', 'DC', 20123
  3  from emp;

55636 rows created.

SQL> insert into iot_addresses
  2  select empno, 'SCHOOL', '123 main street', 'Washington', 'DC', 20123
  3  from emp;

55636 rows created.

SQL> select count(*) from iot_addresses;

  COUNT(*)
----------
    222544

SQL>

4 分别收集两种子表的统计信息：

SQL> exec dbms_stats.gather_table_stats(user,'HEAP_ADDRESSES');

PL/SQL procedure successfully completed.

SQL> exec dbms_stats.gather_table_stats(user,'IOT_ADDRESSES');

PL/SQL procedure successfully completed.

SQL>

5 对比使用不同类型的子表，SQL的执行计划：

SQL> set line 200
SQL> set autot trace
SQL> select *
  2  from emp, heap_addresses
  3  where emp.empno = heap_addresses.empno
  4  and emp.empno = 100;


Execution Plan
----------------------------------------------------------
Plan hash value: 541875893

-----------------------------------------------------------------------------------------------
| Id  | Operation                    | Name           | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                |     4 |   368 |     8   (0)| 00:00:01 |
|   1 |  NESTED LOOPS                |                |     4 |   368 |     8   (0)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| EMP            |     1 |    45 |     2   (0)| 00:00:01 |
|*  3 |    INDEX UNIQUE SCAN         | EMP_PK         |     1 |       |     1   (0)| 00:00:01 |
|   4 |   TABLE ACCESS BY INDEX ROWID| HEAP_ADDRESSES |     4 |   188 |     6   (0)| 00:00:01 |
|*  5 |    INDEX RANGE SCAN          | SYS_C00138141  |     4 |       |     2   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("EMP"."EMPNO"=100)
   5 - access("HEAP_ADDRESSES"."EMPNO"=100)


Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
         11  consistent gets
          0  physical reads
          0  redo size
       1351  bytes sent via SQL*Net to client
        523  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          4  rows processed

SQL> 
SQL> select *
  2  from emp, iot_addresses
  3  WHERE emp.empno = iot_addresses.empno
  4  and emp.empno = 100;


Execution Plan
----------------------------------------------------------
Plan hash value: 1475200359

---------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name               | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                    |     4 |   368 |     4   (0)| 00:00:01 |
|   1 |  NESTED LOOPS                |                    |     4 |   368 |     4   (0)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| EMP                |     1 |    45 |     2   (0)| 00:00:01 |
|*  3 |    INDEX UNIQUE SCAN         | EMP_PK             |     1 |       |     1   (0)| 00:00:01 |
|*  4 |   INDEX RANGE SCAN           | SYS_IOT_TOP_184800 |     4 |   188 |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("EMP"."EMPNO"=100)
   4 - access("IOT_ADDRESSES"."EMPNO"=100)


Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
          8  consistent gets
          0  physical reads
          0  redo size
       1351  bytes sent via SQL*Net to client
        523  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          4  rows processed

SQL>

6 小结：通过分析上述2条“几乎”完全相同的SQL语句的执行计划，我们可以看到：

        对于第1个SQL(子表通过Heap来实现)，首先通过EMP_PK这个主键来访问主表EMP，得到主表的行记录，然后通过得到的主键EMPNO字段来访问子表HEAP_ADDRESS,通过子表HEAP_ADDRESS的索引SYS_C00138141来获取子表记录。整个SQL耗费了11次内存读，COST为8。

        而对于第2个SQL(子表通过IOT来实现)，首先通过EMP_PK这个主键来访问主表EMP，得到主表的行记录，然后直接通过EMPNO字段来访问子表IOT_ADDRESS，而EMPNO字段同时也是子表IOT_ADDRESS的主键字段，这样通过IOT表的主键字段来访问数据就非常快了。整个SQL耗费8次内存读，COST为4，是第1条SQL的1/2。

IOT表适用的场景：

① 应用中有完全由主键字段构成的表；

②  应用中有只会通过主键来访问数据的表；

③  希望数据以某种特定顺序存储的表；

IOT表不适用于使用非主键字段来查询数据。

Oracle splitting partitions简单小结

留下评论 , ,

            本文简单记录在Oracle 10g数据库上对范围分区表的Splitting Partitions测试过程和结论，并不涉及到Oracle数据库中分区技术的详细描述。

1 测试环境及平台：

OS：

[root@localhost ~]# uname -rm
2.6.18-164.el5 x86_64
[root@localhost ~]#

Oracle：

SQL> select * from v$version;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bi
PL/SQL Release 10.2.0.5.0 - Production
CORE    10.2.0.5.0      Production
TNS for Linux: Version 10.2.0.5.0 - Production
NLSRTL Version 10.2.0.5.0 - Production

SQL>

2 创建范围分区表：

SQL> show user;
USER is "SYS"
SQL> create table part_range(id number,name varchar2(30))
  2  partition by range(id)
  3  (partition partmax values less than (maxvalue))
  4  tablespace users;

Table created.

SQL>

3 插入测试数据：

SQL> insert into part_range select object_id,object_name from dba_objects
  2  where object_id<2000;

1953 rows created.

SQL>

4 在分区表part_range上创建2种分区索引：

本地分区索引【Locally partitioned index】：

SQL> create index part_range_id_idx on part_range(id) local;

Index created.

SQL>

全局分区索引【Globally partitioned index】：

SQL> create index part_range_name_idx on part_range(name) tablespace users;

Index created.

SQL>

5 查看分区表信息：

SQL> select table_name,partition_name,tablespace_name from user_tab_partitions
  2  where table_name='PART_RANGE';

TABLE_NAME                     PARTITION_NAME                 TABLESPACE_NAME
------------------------------ ------------------------------ ------------------------------
PART_RANGE                     PARTMAX                        USERS

SQL>

6 查看索引信息：

SQL> select index_name,partition_name,tablespace_name,status from user_ind_partitions
  2  where index_name='PART_RANGE_ID_IDX';

INDEX_NAME                     PARTITION_NAME                 TABLESPACE_NAME                STATUS
------------------------------ ------------------------------ ------------------------------ --------
PART_RANGE_ID_IDX              PARTMAX                        USERS                          USABLE

SQL> select index_name,table_name,tablespace_name,status,partitioned from user_indexes
  2  where table_name='PART_RANGE';

INDEX_NAME                     TABLE_NAME                     TABLESPACE_NAME                STATUS   PAR
------------------------------ ------------------------------ ------------------------------ -------- ---
PART_RANGE_ID_IDX              PART_RANGE                                                    N/A      YES
PART_RANGE_NAME_IDX            PART_RANGE                     USERS                          VALID    NO

SQL>

7 对分区表part_range执行Splitting partitions【分区分裂】操作：

SQL> alter table part_range split partition partmax at (2000) 
  2  into (partition p1,partition partmax);

Table altered.

SQL>

注意，这里的分区分裂操作临界值是2000，即id<2000的记录将全部重组到p1分区，而partmax分区将为空，即0记录。

SQL> select count(*) from part_range;

  COUNT(*)
----------
      1953

SQL> select count(*) from part_range partition(p1);

  COUNT(*)
----------
      1953

SQL> select count(*) from part_range partition(partmax);

  COUNT(*)
----------
         0

SQL>

8 再次分别查看分区表、索引信息：

分区表：

SQL>  select table_name,partition_name,tablespace_name from user_tab_partitions
  2   where table_name='PART_RANGE';

TABLE_NAME                     PARTITION_NAME                 TABLESPACE_NAME
------------------------------ ------------------------------ ------------------------------
PART_RANGE                     PARTMAX                        USERS
PART_RANGE                     P1                             USERS

SQL>

索引信息：

SQL> select index_name,partition_name,tablespace_name,status from user_ind_partitions
  2  where index_name='PART_RANGE_ID_IDX';

INDEX_NAME                     PARTITION_NAME                 TABLESPACE_NAME                STATUS
------------------------------ ------------------------------ ------------------------------ --------
PART_RANGE_ID_IDX              P1                             USERS                          USABLE
PART_RANGE_ID_IDX              PARTMAX                        USERS                          USABLE

SQL> select index_name,table_name,tablespace_name,status,partitioned from user_indexes
  2  where table_name='PART_RANGE';

INDEX_NAME                     TABLE_NAME                     TABLESPACE_NAME                STATUS   PAR
------------------------------ ------------------------------ ------------------------------ -------- ---
PART_RANGE_ID_IDX              PART_RANGE                                                    N/A      YES
PART_RANGE_NAME_IDX            PART_RANGE                     USERS                          VALID    NO

SQL>

小结：对于分区分裂之后，如果包含有空分区的话，那么对于本地分区索引和全局分区索引都是可用的。这种分区分裂的方式通常也叫做快速分裂【Fast Splitting】，索引不需要rebuild。

9 如果在上述步骤7中，执行的分区分裂操作如下：

SQL> alter table part_range split partition partmax at (1000)
  2  into (partition p1,partition partmax);

Table altered.

SQL>

即分区分裂操作临界值是1000，id<1000的记录将重组到p1分区，id>=1000的记录将重组到partmax分区。也就是此时，分裂出来的p1和partmax这两个分区均不为空。

SQL> select count(*) from part_range;

  COUNT(*)
----------
      1953

SQL> select count(*) from part_range partition(p1);

  COUNT(*)
----------
       953

SQL> select count(*) from part_range partition(partmax);

  COUNT(*)
----------
      1000

SQL>

那么，查看到的分区表、索引信息如下：

分区表：

SQL> select table_name,partition_name,tablespace_name from user_tab_partitions
  2  where table_name='PART_RANGE';

TABLE_NAME                     PARTITION_NAME                 TABLESPACE_NAME
------------------------------ ------------------------------ ------------------------------
PART_RANGE                     PARTMAX                        USERS
PART_RANGE                     P1                             USERS

SQL>

索引信息：

SQL> select index_name,partition_name,tablespace_name,status from user_ind_partitions
  2  where index_name='PART_RANGE_ID_IDX';

INDEX_NAME                     PARTITION_NAME                 TABLESPACE_NAME                STATUS
------------------------------ ------------------------------ ------------------------------ --------
PART_RANGE_ID_IDX              P1                             USERS                          UNUSABLE
PART_RANGE_ID_IDX              PARTMAX                        USERS                          UNUSABLE

SQL> select index_name,table_name,tablespace_name,status,partitioned from user_indexes
  2  where table_name='PART_RANGE';

INDEX_NAME                     TABLE_NAME                     TABLESPACE_NAME                STATUS   PAR
------------------------------ ------------------------------ ------------------------------ -------- ---
PART_RANGE_ID_IDX              PART_RANGE                                                    N/A      YES
PART_RANGE_NAME_IDX            PART_RANGE                     USERS                          UNUSABLE NO

SQL>

小结：对于分区分裂之后，如果不包含空分区的话，那么对于本地分区索引和全局分区索引都将不可用，索引的状态都变为UNUSABLE。均需要重建：

SQL> alter index PART_RANGE_ID_IDX rebuild partition p1;

Index altered.

SQL> alter index PART_RANGE_ID_IDX rebuild partition partmax;

Index altered.

SQL> alter index PART_RANGE_NAME_IDX rebuild;

Index altered.

SQL>

重建之后，本地分区索引、全局分区索引信息，已由UNUSABLE变为USABLE：

SQL> select index_name,partition_name,tablespace_name,status from user_ind_partitions
  2  where index_name='PART_RANGE_ID_IDX';

INDEX_NAME                     PARTITION_NAME                 TABLESPACE_NAME                STATUS
------------------------------ ------------------------------ ------------------------------ --------
PART_RANGE_ID_IDX              P1                             USERS                          USABLE
PART_RANGE_ID_IDX              PARTMAX                        USERS                          USABLE

SQL> select index_name,table_name,tablespace_name,status,partitioned from user_indexes
  2  where table_name='PART_RANGE';

INDEX_NAME                     TABLE_NAME                     TABLESPACE_NAME                STATUS   PAR
------------------------------ ------------------------------ ------------------------------ -------- ---
PART_RANGE_ID_IDX              PART_RANGE                                                    N/A      YES
PART_RANGE_NAME_IDX            PART_RANGE                     USERS                          VALID    NO

SQL>

当然，如果在分裂分区的同时带上UPDATE INDEXES的话，可以在分裂分区的同时重建索引【包含本地分区索引和全局分区索引，状态均为USABLE、VALID】：

SQL> alter table part_range split partition partmax at (1000) into (partition p1,partition partmax) update indexes;

Table altered.

SQL>

分裂分区之后，表信息：

SQL> select table_name,partition_name,tablespace_name from user_tab_partitions
  2  where table_name='PART_RANGE';

TABLE_NAME                     PARTITION_NAME                 TABLESPACE_NAME
------------------------------ ------------------------------ ------------------------------
PART_RANGE                     PARTMAX                        USERS
PART_RANGE                     P1                             USERS

SQL>

索引信息：

SQL> select index_name,partition_name,tablespace_name,status from user_ind_partitions where index_name='PART_RANGE_ID_IDX';

INDEX_NAME                     PARTITION_NAME                 TABLESPACE_NAME                STATUS
------------------------------ ------------------------------ ------------------------------ --------
PART_RANGE_ID_IDX              P1                             USERS                          USABLE
PART_RANGE_ID_IDX              PARTMAX                        USERS                          USABLE

SQL> select index_name,table_name,tablespace_name,status,partitioned from user_indexes where table_name='PART_RANGE';

INDEX_NAME                     TABLE_NAME                     TABLESPACE_NAME                STATUS   PAR
------------------------------ ------------------------------ ------------------------------ -------- ---
PART_RANGE_ID_IDX              PART_RANGE                                                    N/A      YES
PART_RANGE_NAME_IDX            PART_RANGE                     USERS                          VALID    NO

SQL>

而如果在分裂分区的同时带上UPDATE GLOBAL INDEXES的话，可以在分裂分区的同时重建全局分区索引【不包含本地分区索引，只有全局分区索引状态为VALID】，而本地分区索引需要重建：

SQL> alter table part_range split partition partmax at (1000) into (partition p1,partition partmax) update global indexes;

Table altered.

SQL>

分裂分区之后，表信息：

SQL> select table_name,partition_name,tablespace_name from user_tab_partitions
  2  where table_name='PART_RANGE';

TABLE_NAME                     PARTITION_NAME                 TABLESPACE_NAME
------------------------------ ------------------------------ ------------------------------
PART_RANGE                     PARTMAX                        USERS
PART_RANGE                     P1                             USERS

SQL>

索引信息：

SQL> select index_name,partition_name,tablespace_name,status from user_ind_partitions where index_name='PART_RANGE_ID_IDX';

INDEX_NAME                     PARTITION_NAME                 TABLESPACE_NAME                STATUS
------------------------------ ------------------------------ ------------------------------ --------
PART_RANGE_ID_IDX              P1                             USERS                          UNUSABLE
PART_RANGE_ID_IDX              PARTMAX                        USERS                          UNUSABLE

SQL> select index_name,table_name,tablespace_name,status,partitioned from user_indexes where table_name='PART_RANGE';

INDEX_NAME                     TABLE_NAME                     TABLESPACE_NAME                STATUS   PAR
------------------------------ ------------------------------ ------------------------------ -------- ---
PART_RANGE_ID_IDX              PART_RANGE                                                    N/A      YES
PART_RANGE_NAME_IDX            PART_RANGE                     USERS                          VALID    NO

SQL>

需要注意的是，在分裂分区的同时重建索引，将会消耗更多时间来完成分裂工作，以及消耗更多的系统资源。如果系统资源较为充足的话，可以考虑带上UPDATE INDEXES选项。

10 最后，再看看另外一种比较特殊的情况。在分裂分区的时候，如果将新分区指向新的表空间【由USERS到EXAMPLE表空间】的话，并且分裂之后，包含空分区的情况。即，分裂的语句如下：

SQL> alter table part_range split partition partmax at (2000)
  2  into (partition p1 tablespace example,partition partmax tablespace example);

Table altered.

SQL> select count(*) from part_range;

  COUNT(*)
----------
      1953

SQL> select count(*) from part_range partition(p1);

  COUNT(*)
----------
      1953

SQL> select count(*) from part_range partition(partmax);

  COUNT(*)
----------
         0

SQL>

那么可以看到分区表：

SQL> select table_name,partition_name,tablespace_name from user_tab_partitions where table_name='PART_RANGE';

TABLE_NAME                     PARTITION_NAME                 TABLESPACE_NAME
------------------------------ ------------------------------ ------------------------------
PART_RANGE                     PARTMAX                        EXAMPLE
PART_RANGE                     P1                             EXAMPLE

SQL>

索引分区信息：

SQL>  select index_name,partition_name,tablespace_name,status from user_ind_partitions where index_name='PART_RANGE_ID_IDX';

INDEX_NAME                     PARTITION_NAME                 TABLESPACE_NAME                STATUS
------------------------------ ------------------------------ ------------------------------ --------
PART_RANGE_ID_IDX              P1                             EXAMPLE                        UNUSABLE
PART_RANGE_ID_IDX              PARTMAX                        EXAMPLE                        USABLE

SQL> select index_name,table_name,tablespace_name,status,partitioned from user_indexes where table_name='PART_RANGE';

INDEX_NAME                     TABLE_NAME                     TABLESPACE_NAME                STATUS   PAR
------------------------------ ------------------------------ ------------------------------ -------- ---
PART_RANGE_ID_IDX              PART_RANGE                                                    N/A      YES
PART_RANGE_NAME_IDX            PART_RANGE                     USERS                          UNUSABLE NO

SQL>

小结：在分裂分区的时候，如果将新分区指向新的表空间的话，并且分裂之后，即使包含空分区的情况下，只有新空分区的本地索引不需要重建，而含有数据的新分区的本地分区索引以及全局分区索引均需重建。这有别于快速分裂，或者说是快速分裂的一种特殊情况。

本文部分内容参考范大师

遇到ORA-600 [kmgs_parameter_update_timeout_1] [1565]的错误 续

留下评论 , ,

刚发完上篇文章之后，又从老杨的一篇文章“http://blog.itpub.net/post/468/450451?SelectActiveLayout=a”中看到一些有所帮助的信息，而这个案例中在alert里看到，在这个600的错误抛出之前一条错误信息中看到：

Wed Jul 25 09:56:46  2012
Thread 1 advanced to log sequence 580 (LGWR switch)
  Current log# 1 seq# 580 mem# 0: +DATA/zhfr8db/onlinelog/group_1.271.783424599
  Current log# 1 seq# 580 mem# 1: +FLASH/zhfr8db/onlinelog/group_1.256.783424601
Wed Jul 25 10:49:39  2012
Unexpected communication failure with ASM instance:
 error 21561 (ORA-21561: 生成 OID 失败
)

的错误信息。

从后续的alert日志里，尝试关闭数据库服务器的时候抛出的错误中也有类似错误：

Wed Jul 25 10:55:03  2012
Trace dumping is performing id=[cdmp_20120725105503]
Wed Jul 25 10:56:06  2012
Restarting dead background process MMON
MMON started with pid=33, OS id=6756
Wed Jul 25 12:46:20  2012
Unexpected communication failure with ASM instance:
 error 21561 (ORA-21561: 生成 OID 失败
)
NOTE: ASMB process state dumped to trace file c:\oracle\product\10.2.0\admin\zhfr8db\udump\zhfr8db1_ora_5552.trc
Wed Jul 25 12:47:03  2012
Unexpected communication failure with ASM instance:
 error 21561 (ORA-21561: 生成 OID 失败
)
NOTE: ASMB process state dumped to trace file c:\oracle\product\10.2.0\admin\zhfr8db\udump\zhfr8db1_ora_2008.trc
Wed Jul 25 12:50:01  2012
Unexpected communication failure with ASM instance:
 error 21561 (ORA-21561: 生成 OID 失败
)

再从c:\oracle\product\10.2.0\admin\zhfr8db\udump\zhfr8db1_ora_5552.trc文件跟踪看到：

*** 2012-07-25 12:46:20.268
*** CLIENT ID:() 2012-07-25 12:46:20.268
      ----------------------------------------
      SO: 000000047111DEF0, type: 2, owner: 0000000000000000, flag: INIT/-/-/0x00
      (process) Oracle pid=31, calls cur/top: 000000047E15DC20/000000047E15DC20, flag: (6) SYSTEM
                int error: 0, call error: 0, sess error: 0, txn error 0
  (post info) last post received: 0 0 33
              last post received-location: ksrpublish
              last process to post me: 7e11e6f8 1 6
              last post sent: 849 0 4
              last post sent-location: kslpsr
              last process posted by me: 7312aef8 1 6
        (latch info) wait_event=0 bits=0
        Process Group: DEFAULT, pseudo proc: 00000004731384B8
        O/S info: user: SYSTEM, term: DATACENTER01, ospid: 4828 
        OSD pid info: Windows thread id: 4828, image: ORACLE.EXE (ASMB)
        Short stack dump: 
ksdxfstk+42<-ksdxcb+1630<-ssthreadsrgruncallback+589<-OracleOradebugThreadStart+975<-0000000077D6B71A
<-0000000077EF047A<-0000000077DA79F3<-0000000008653328<-000000000865190C<-0000000005F564A9
<-0000000005F0CF64<-0000000005EE5D88<-0000000005EE57F9<-0000000005EA5ECB<-ttcdrv+14881
<-0000000005EAAA6D<-xupirtrc+1335<-xupirtr+216<-upirtr+23<-kpurcs+45
<-OCIKDispatch+32<-kfnOpExecute+146<-kfnbRun+1062<-ksbrdp+988<-opirip+700
<-opidrv+856<-sou2o+52<-opimai_real+268<-opimai+96<-BackgroundThreadStart+637<-0000000077D6B71A
        ----------------------------------------
        SO: 000000047114E1A0, type: 4, owner: 000000047111DEF0, flag: INIT/-/-/0x00
        (session) sid: 189 trans: 0000000000000000, creator: 000000047111DEF0, flag: (51) USR/- BSY/-/-/-/-/-
                  DID: 0001-001F-00000003, short-term DID: 0000-0000-00000000
                  txn branch: 0000000000000000
                  oct: 0, prv: 0, sql: 0000000000000000, psql: 0000000000000000, user: 0/SYS
        service name: SYS$BACKGROUND
        waiting for 'ASM background timer' wait_time=0, seconds since wait started=420165
                    =0, =0, =0
                    blocking sess=0x0000000000000000 seq=31
        Dumping Session Wait History
         for 'ASM background timer' count=1 wait_time=4.999949 sec
                    =0, =0, =0
         for 'ASM background timer' count=1 wait_time=4.999893 sec
                    =0, =0, =0
         for 'ASM background timer' count=1 wait_time=5.000022 sec
                    =0, =0, =0
         for 'ASM background timer' count=1 wait_time=4.999948 sec
                    =0, =0, =0
         for 'ASM background timer' count=1 wait_time=4.999924 sec
                    =0, =0, =0
         for 'ASM background timer' count=1 wait_time=5.000012 sec
                    =0, =0, =0
         for 'ASM background timer' count=1 wait_time=4.999948 sec
                    =0, =0, =0
         for 'ASM background timer' count=1 wait_time=4.999858 sec
                    =0, =0, =0
         for 'ASM background timer' count=1 wait_time=4.999991 sec
                    =0, =0, =0
         for 'ASM background timer' count=1 wait_time=5.000000 sec
                    =0, =0, =0
        Sampled Session History of session 189 serial 1
        ---------------------------------------------------
        The sampled session history is constructed by sampling
        the target session every 1 second. The sampling process
        captures at each sample if the session is in a non-idle wait,
        an idle wait, or not in a wait. If the session is in a
        non-idle wait then one interval is shown for all the samples
        the session was in the same non-idle wait. If the
        session is in an idle wait or not in a wait for
        consecutive samples then one interval is shown for all
        the consecutive samples. Though we display these consecutive
        samples  in a single interval the session may NOT be continuously
        idle or not in a wait (the sampling process does not know).
 
        The history is displayed in reverse chronological order.
 
        sample interval: 1 sec, max history 120 sec
        ---------------------------------------------------
          [121 samples,                                    12:44:20 - 12:46:20]
            idle wait at each sample
        temporary object counter: 0
          KTU Session Commit Cache Dump for IDLs: 
          KTU Session Commit Cache Dump for Non-IDLs: 
          ----------------------------------------
          UOL used : 0 locks(used=0, free=0)
          KGX Atomic Operation Log 000000047AECC840
           Mutex 0000000000000000(0, 0) idn 0 oper NONE
           Cursor Pin uid 189 efd 3 whr 11 slp 0
          KGX Atomic Operation Log 000000047AECC888
           Mutex 0000000000000000(0, 0) idn 0 oper NONE
           Library Cache uid 189 efd 0 whr 0 slp 0
          KGX Atomic Operation Log 000000047AECC8D0
           Mutex 0000000000000000(0, 0) idn 0 oper NONE
           Library Cache uid 189 efd 0 whr 0 slp 0
          ----------------------------------------
          SO: 000000045A233D80, type: 41, owner: 000000047114E1A0, flag: INIT/-/-/0x00
          (dummy) nxc=0, nlb=0   
        ----------------------------------------
        SO: 0000000472172A40, type: 11, owner: 000000047111DEF0, flag: INIT/-/-/0x00
        (broadcast handle) flag: (2) ACTIVE SUBSCRIBER, owner: 000000047111DEF0,
                           event: 31, last message event: 31,
                           last message waited event: 31,                            next message: 0000000476225BC8(0), messages read: 0
                           channel: (00000004711640E0) system events broadcast channel
                                    scope: 2, event: 30690, last mesage event: 7413,
                                    publishers/subscribers: 1/45,
                                    messages published: 3
                                    oldest msg (?): 0000000476225BB8 id: 1 pub: 000000047E11F768
                                    heuristic msg queue length: 3
        ----------------------------------------
        SO: 0000000472270FA0, type: 19, owner: 000000047111DEF0, flag: INIT/-/-/0x00
         GES MSG BUFFERS: st=emp chunk=0x0000000000000000 hdr=0x0000000000000000 lnk=0x0000000000000000 flags=0x0 inc=0
          outq=0 sndq=0 opid=0 prmb=0x0 
          mbg[i]=(0 0) mbg[b]=(0 0) mbg[r]=(0 0)
          fmq[i]=(0 0) fmq[b]=(0 0) fmq[r]=(0 0)
          mop[s]=0 mop[q]=0 pendq=0 zmbq=0
          nonksxp_recvs=0
        ------------process 0x0000000472270FA0--------------------
        proc version      : 0
        Local node        : 0
        pid               : 4828
        lkp_node          : 0
        svr_mode          : 0
        proc state        : KJP_FROZEN
        Last drm hb acked : 0
        Total accesses    : 3
        Imm.  accesses    : 0
        Locks on ASTQ     : 0
        Locks Pending AST : 0
        Granted locks     : 0
        AST_Q: 
        PENDING_Q: 
        GRANTED_Q: 
        ----------------------------------------
        SO: 000000047E15DC20, type: 3, owner: 000000047111DEF0, flag: INIT/-/-/0x00
        (call) sess: cur 7114e1a0, rec 0, usr 7114e1a0; depth: 0
          ----------------------------------------
          SO: 000000045ED23770, type: 84, owner: 000000047E15DC20, flag: INIT/-/-/0x00
          (kfgso) flags: 00000000 clt: 3 err: 0 hint: 0
          (kfgpn) rpi: 1 itrn:0000000000000000 gst:0000000000000000 usrp:0000000000000000
          busy: 0 rep: 0 grp: 5d60b840 check: 0/0 glink: 5d60b888 5d60b888
            kfgrp:  number: 0/0 type: 0 compat: 0.0.0.0.0 dbcompat:0.0.0.0.0
            timestamp: 0 state: 0 flags: 2 gpnlist: 5ed237f0 5ed237f0
            KFGPN at 5ed23770 in dependent chain
        ----------------------------------------
        SO: 000000045AEEDD48, type: 16, owner: 000000047111DEF0, flag: INIT/-/-/0x00
        (osp req holder)
PSO child state object changes :
Dump of memory from 0x0000000474167DC0 to 0x0000000474167FC8
474167DC0 00000005 00000000 5AEEDD48 00000004  [........H..Z....]
474167DD0 00000010 000313F4 7E15DC20 00000004  [........ ..~....]
474167DE0 00000003 000313F4 72270FA0 00000004  [..........'r....]
474167DF0 00000013 000312CB 72172A40 00000004  [........@*.r....]
474167E00 0000000B 000313F4 7114E1A0 00000004  [...........q....]
474167E10 00000004 000312CB 00000000 00000000  [................]
474167E20 00000000 00000000 00000000 00000000  [................]
        Repeat 25 times
474167FC0 00000000 00000000                    [........]        
*** 2012-07-25 12:46:37.393
*** CLIENT ID:() 2012-07-25 12:46:37.393
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 320 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 288 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 224 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 192 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 160 for SQL direct I/O. It is set to -1 
*** 2012-07-25 12:47:20.314
*** CLIENT ID:() 2012-07-25 12:47:20.314
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1

难道问题是：

WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 320 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 288 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 224 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 256 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 192 for SQL direct I/O. It is set to -1 
WARNING:Could not lower the asynch I/O limit to 160 for SQL direct I/O. It is set to -1

导致的，这些WARNING又说明什么呢？

遇到ORA-600 [kmgs_parameter_update_timeout_1] [1565]的错误

留下评论 , ,

           今天上午，在一套Windows 2003 64位的双节点10.2.0.5.0的64位RAC数据库上，遇到一则600的错误，ORA-00600: 内部错误代码, 参数: [kmgs_parameter_update_timeout_1], [1565], [], [], [], [], [], []。从(节点1的)alert日志里获取的具体错误信息如下：

Wed Jul 25 10:49:39  2012
Unexpected communication failure with ASM instance:
 error 21561 (ORA-21561: 生成 OID 失败
)
NOTE: ASMB process state dumped to trace file c:\oracle\product\10.2.0\admin\zhfr8db\bdump\zhfr8db1_mmon_4624.trc
System State dumped to trace file c:\oracle\product\10.2.0\admin\zhfr8db\bdump\zhfr8db1_mmon_4624.trc
Wed Jul 25 10:55:02  2012
Errors in file c:\oracle\product\10.2.0\admin\zhfr8db\bdump\zhfr8db1_mmon_4624.trc:
ORA-00600: 内部错误代码, 参数: [kmgs_parameter_update_timeout_1], [1565], [], [], [], [], [], []
ORA-01565: 标识文件 '+DATA/zhfr8db/spfilezhfr8db.ora' 时出错
ORA-17503: ksfdopn: 2 未能打开文件 +DATA/zhfr8db/spfilezhfr8db.ora
ORA-21561: 生成 OID 失败

Wed Jul 25 10:55:03  2012
Trace dumping is performing id=[cdmp_20120725105503]
Wed Jul 25 10:56:06  2012
Restarting dead background process MMON
MMON started with pid=33, OS id=6756

           当时的表现情况是，客户端无法通过应用系统访问数据库，客户端通过tnsping service_name的返回结果也是，有时通，返回10毫秒，而有时挂死了。

           登录到其中的一个节点服务器(节点1)上，执行lsnrctl status，查看监听状态也挂死，而到另外一个节点(节点2)上，执行lsnrctl status一切正常。并且，分别在两个节点上，通过SQL*PLUS连接数据库均正常，执行crs_stat -t返回的结果也都正常。

           接下来，分别在两个节点上作了一个AWR报告，分析了AWR发现并没有发现数据库的异常现象。

           从告警日志里看到跟SPFILE相关的错误，于是在SQL*PLUS里尝试create pfile from spfile,以及使用RMAN工具backup spfile时，都报错了，当时匆忙，具体错误号没有记录下来。

           没辙了，就到节点1上，尝试通过srvctl stop database -d db_unique_name关闭数据库时，挂死了，丝毫没有反应；通过SQL*PLUS在节点1上，尝试shutdown immediate来手工关闭实例，也未果。

           当时，从网络上找到老杨以及惜分飞的文章，不过，貌似都和我遇到的这个情况不太类似。

           然后，在没有更好的办法的前提下，直接重启节点1的Windows服务器，毕竟当时应用已经不可用了，再者是RAC架构，最起码还留着一个实例。重启之后，数据库一切正常了。

           最后，从MetaLink上找到这样的一篇文章：ORA-600 [kmgs_parameter_update_timeout_1], [1565] While Accessing Spfile Managed By ASM [ID 553915.1]该文档描述，该错误影响到10.2及以上版本的数据库，原因是：

This is due to unpublished bug 5399699 where ORA-600 [kmgs_parameter_update_timeout_1] or similar errors can occur in MMON when ASM is being used.

In 10g MMON manages all memory re-size activity by modifying related parameters. If MMON is not running DBW0 will handle this task. The parameter update activity is triggered by a timeout. Basically this error indicates that the MMON process is not able to write to the SPFILE to store some settings required for dynamic SGA parameter adjustments.

           也就是说：这个错误是oracle还未发布的一个bug,bug号是5399699。这个错误是说在10g的数据库里，MMON进程动态的管理内存，MMON（Memory Monitor）是10g数据库的新进程。从10g开始，数据库支持自动调整SGA内存，当需要调整（动态增大或减小）的时候，MMON进程会自动完成，MMON会把这个改变的信息，写入到SPFILE里。

       结合最开始的alert日志文件的内容，是由于当时MMON进程无法把这个信息写入到SPFILE里导致的，导致后来MMON后台进程僵死了，在Wed Jul 25 10:56:06  2012的时候，MMON进程又被重启了。然后数据库一直处于“假死”的状态。

       Oracle Metalink上这篇文章给的解决方案：

Solution

1.  Upgrade to the 10.2.0.4.4 PSU Patch:9352164 or higher where this bug is fixed.

OR

2. Check if Patch:5399699 is available for your RDBMS release and platform.

OR

3.  Use one of the following workarounds:

  • Relocate the spfile either to some other diskgroup on which the archive logs are not being managed.
  • Move the spfile to the file system

          显然，第1个与当前环境下的数据库版本不一致；而第2个方案中，又没有查到Windows 2003 X64平台下的补丁；第3个方案，我当前是RAC的库，如果把SPFILE迁移到文件系统上的话，又不太合适，除非给每个实例单独配置PFILE。

          最后，这个问题，对于我这个Oracle菜鸟而言，依然头痛，没有更好的解决方案，如果大家有遇到过类似的案例的话，请不吝赐教！