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

            上周二早上,收到项目组的一封邮件:

       早上联代以下时间点用户有反馈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还是蛮重要的。

 

Oracle索引组织表学习系列三(完)

5 索引组织表(IOT Index-Organized Table)的键压缩

      在创建IOT表时,有一个存储选项NOCOMPRESS,这个选项的意思是不压缩,即对IOT表的索引条目不压缩。该选项不单对IOT表有效,同样对B-Tree索引也适用。

      与NOCOMPRESS选项对应的就是COMPRESS N,这个N只能取值整数,表示要压缩的列数,在数据块儿级别提取"公因子",用以避免存储重复值。如IOT表的主键是(col1,col2,col3)的联合主键的话,那么COMPRESS 2就可以表示,如果在表中重复出现多个col1,col2的重复值的话,那么Oracle就只存储col1,col2 1次,对于重复的记录不再存储。所以,达到压缩的目的。

      接下来,看一个示例:

      1 创建一个NOCOMPRESS的IOT表:

[oracle@oracle11g ~]$ sqlplus 

SQL*Plus: Release 11.2.0.1.0 Production on Fri Nov 23 14:21:43 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 iot
  2  ( owner, object_type, object_name,
  3  constraint iot_pk primary key(owner,object_type,object_name)
  4  )
  5  organization index
  6  NOCOMPRESS
  7  as
  8  select distinct owner, object_type, object_name
  9  from all_objects;

Table created.

SQL> select count(*) from iot;

  COUNT(*)
----------
     55646

SQL> select lf_blks, br_blks, used_space, opt_cmpr_count, opt_cmpr_pctsave from index_stats;

no rows selected

SQL> 

 

      看到表里有55646条记录。

      2 用ANALYZE INDEX VALID STRUCTURE来分析这个IOT表的主键:

SQL> analyze index iot_pk validate structure;

Index analyzed.

SQL> select lf_blks, br_blks, used_space, opt_cmpr_count, opt_cmpr_pctsave from index_stats;

   LF_BLKS    BR_BLKS USED_SPACE OPT_CMPR_COUNT OPT_CMPR_PCTSAVE
---------- ---------- ---------- -------------- ----------------
       347          3    2493786              2               33

SQL> 

 

      看到这个IOT表的索引使用了347个叶子块,3个分枝块,占用空间大小是2493786字节,约2.4M。

      3 使用COMPRESS 1选项来重建IOT表:

SQL> alter table iot move compress 1;

Table altered.

SQL> select lf_blks, br_blks, used_space, opt_cmpr_count, opt_cmpr_pctsave from index_stats;

no rows selected

SQL> analyze index iot_pk validate structure;

Index analyzed.

SQL> select lf_blks, br_blks, used_space, opt_cmpr_count, opt_cmpr_pctsave from index_stats;

   LF_BLKS    BR_BLKS USED_SPACE OPT_CMPR_COUNT OPT_CMPR_PCTSAVE
---------- ---------- ---------- -------------- ----------------
       304          3    2178229              2               23

SQL> 

 

         然后,看到这个IOT表的索引现在使用了304个叶子块,3个分枝块,占用空间大小是2178229字节,约2.1M。

      4 使用COMPRESS 2继续压缩这个IOT表:

SQL> alter table iot move compress 2;

Table altered.

SQL> select lf_blks, br_blks, used_space, opt_cmpr_count, opt_cmpr_pctsave from index_stats;

no rows selected

SQL> analyze index iot_pk validate structure;

Index analyzed.

SQL> select lf_blks, br_blks, used_space, opt_cmpr_count, opt_cmpr_pctsave from index_stats;

   LF_BLKS    BR_BLKS USED_SPACE OPT_CMPR_COUNT OPT_CMPR_PCTSAVE
---------- ---------- ---------- -------------- ----------------
       233          1    1670153              2                0

SQL> 

 

      最终,看到这个IOT表的索引现在使用了233个叶子块,1个分枝块,占用空间大小是1670153字节,约1.6M。

      说明:

      从上可以看出,使用不同的压缩级别,索引的占用的空间大小逐渐变小,从最初的2.4M变成1.6M。叶子块从最初的347变成233个,分枝块最终只有1个。

      对于上述分析索引之后的OPT_CMPR_COUNT字段表示最优压缩数,即对于该索引而言如果使用COMPRESS 2来压缩的话,可以得到最优的压缩效果。

       同时OPT_CMPR_PCTSAVE字段值则表示最优压缩节省的空间百分比,针对第一次分析之后的结果,可以看到OPT_CMPR_PCTSAVE为33,即可以节省大约33%的空间。如下,压缩后1670153大约是压缩前2493786的2/3,即节约了1/3的空间:

SQL> select 1670153/2493786 from dual;

1670153/2493786
---------------
     .669725871

SQL>

 

6 索引组织表(IOT Index-Organized Table)的INCLUDING和PCTTHRESHOLD参数选择

     对于IOT表而言,如果在建表的语句中同时使用了INCLUDING和PCTTHRESHOLD参数的话,那么PCTTHRESHOLD参数的级别较高。

       PCTTHRESHOLD:行中的数据量超过数据块的这个百分比时,行中其它的列则存放到OVERFLOW段中;

       INCLUDING:行中从第一列直到INCLUDING子句中指定的列(包括该列)都存放在索引块中,其它的列存放到OVERFLOW段中。

       即,对于大小为8K的数据块而言,有下面的IOT表:

SQL> create table iot1
  2  (id number,
  3  name char(2000),
  4  addr char(2000),
  5  salary number,
  6  constraint iot1_pk primary key(id,name)
  7  )
  8  organization index
  9  pctthreshold 50
 10  overflow
 11  including addr;

Table created.

SQL> 

 

       那么,如果PCTTHRESHOLD参数指定为50的话,那么索引块中至多会使用4K的空间来存放主键字段和非主键字段,其它字段则存放到OVERFLOW段中,而会忽略此时的INCLUDING选项,并非将addr字段随主键字段一起存放,而是将其存放到溢出段中。

       关于IOT表的学习,先到这个地方,以后有新的关于IOT表的知识,再补充在这里!

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

       临近中午,收到某客户生产库的故障请求:数据库出现了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表不适用于使用非主键字段来查询数据。