一次ORA-01410故障的解决

Posted by 老熊 on 1月 27th, 2010

在一个表上建索引时,报ORA-01410错误,我们查询这个表来重现这个错误:

Connected to:
Oracle9i Enterprise Edition Release 9.2.0.6.0 - 64bit Production
With the Partitioning option
JServer Release 9.2.0.6.0 - Production

SQL> set timing on
SQL> set time on
14:20:03 SQL> select /*+ full(a) no_index(a) */ count(*) from crm.cust_order a;
select /*+ full(a) no_index(a) */ count(*) from crm.cust_order a
                                                    *
ERROR at line 1:
ORA-01410: invalid ROWID

ORA-01410错误通常见于通过索引访问表,而索引或表由逻辑上的损坏。而这里显示没有通过索引访问表?那问题出在哪里呢?在这种情况下,这个错误与ORA-08103极其类似,参照《记一次ORA-8103错误的处理》

14:27:00 SQL> alter session set max_dump_file_size=unlimited;

Session altered.

Elapsed: 00:00:00.01
14:27:18 SQL> alter session set db_file_multiblock_read_count=1;

Session altered.

Elapsed: 00:00:00.00
14:27:18 SQL> alter session set events 'immediate trace name trace_buffer_on level 1048576';

Session altered.

Elapsed: 00:00:00.00
14:27:18 SQL> alter session set events '10200 trace name context forever, level 1';

Session altered.

Elapsed: 00:00:00.00
14:27:18 SQL> select /*+ full(a) no_index(a) */ count(*) from crm.cust_order a;
ERROR at line 1:
ORA-01410: invalid ROWID

Elapsed: 00:05:50.82
14:33:09 SQL> 14:33:09 SQL> alter session set events 'immediate trace name trace_buffer_off';

Session altered.

在trace文件的最后,我们可以看到:

Consistent read started for block 10 : 2489c394
  env: (scn: 0x0a0d.690ff414  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.000000
00  scn: 0x0000.00000000 0sch: scn: 0x0000.00000000)

这里只有”start“,而没有finish,表明在读2489c394这个块出了问题。
用ODU工具的rdba查看文件号和坏号:

ODU> rdba 2489c394

  rdba   : 0x2489c394=613008276
  rfile# : 146
  block# : 639892

通过”alter sytem dump datafile 146 block 639892”命令发现块中的object_id与CUST_ORDER表的data object id不同,看起来这就是问题所在(此处不再列出数据)。
看起来有坏块了。不过这个库是个查询库,把表TRUNCATE之后重新从生产库同步过来,发现问题仍然存在,甚至把表DROP之后重建也是如此,均是发生在146/639892这个块上。

而TRUNCATE/DROP表都不能解决问题,显然这个块还在内存中,看起来需要刷新buffer cache了:

14:37:07 SQL> alter session set events 'immediate trace name flush_cache level 1';
Session altered.

刷新buffer cache后,问题解决。

总结:这个问题,与ORA-8103类似,都是出现了逻辑坏块,只不过这次的坏块是发生在内存中的块。至于坏块是怎么进入到内存中,为什么在重建表后还在内存中,这就是个谜了,或者是ORACLE的BUG,或者跟用的同步软件DSG有关。在这个案例中,块的object_id与段的实际的data object id不一致。而object_id不一致有时也会报ORA-600错误。

记一次ORA-600[4042]故障的处理

Posted by 老熊 on 10月 17th, 2009

一套运行在Linux下的Oracle 9.2.0.4的库,出现了大量的ORA-600[4042]错误。

ORA-00600: internal error code, arguments: [4042], [31760], [], [], [], [], [], []

关于ORA-600错误,第一个参数,也就是第一个方括号中的标识,通常可以用来定位Oracle错误发生的内部模块。(可以参考Metalink Doc ID 146580.1:What is an ORA-600 Internal Error?)如果是数字,最高位通常是指一个大的模块,而接下来的一位是小的模块。比如这里[4042],4000,最高位是4,是Transaction Layer(事务层),而次高位是0,Transaction Undo(详见Metalink Doc ID : 175982.1 ORA-600 Lookup Error Categories)。

针对这个错误,很明显是跟事务有关。在处理的时候,第一反应肯定是检查TRACE文件:

ORA-00600: internal error code, arguments: [4042], [31760], [], [], [], [], [], []
Current SQL statement for this session:
INSERT INTO XXX .....
....
----- Call Stack Trace -----
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
ksedmp()+269         call     ksedst()+0           0 ? 0 ? 0 ? 0 ? BFFF90A4 ?
                                                   A16D886 ?
ksfdmp()+14          call     ksedmp()+0           3 ? BFFF91B0 ? 98585B4 ?
                                                   AD58FA0 ? 3 ? A4B929C ?
kgeriv()+188         call     ksfdmp()+0           AD58FA0 ? 3 ?
kgeasi()+108         call     kgeriv()+0           AD58FA0 ? AD9AFC0 ? FCA ? 1 ?
                                                   BFFF91EC ?
ktugusc()+787        call     kgeasi()+0           AD58FA0 ? AD9AFC0 ? FCA ? 2 ?
                                                   1 ? 4 ? 7C10 ?
ktuswr()+2049        call     ktugusc()+0          BFFF9394 ? D ? 1 ? 0 ? 0 ?
                                                   0 ? 0 ? 0 ?
ktusmous_online_und  call     ktuswr()+0           D ? 0 ? 0 ? 0 ? 0 ? 1 ?
oseg()+898                                         
ktusmaus_add_us()+3  call     ktusmous_online_und  1 ? 1 ? BFFF94F8 ? 1 ?
27                            oseg()+0             
ktubnd()+7646        call     ktusmaus_add_us()+0  BFFF9CEC ? 0 ?
ktuchg()+581         call     ktubnd()+0           BFFF9678 ? 8468F4F0 ?
                                                   BFFF9CEC ? 0 ?
ktbchg2()+318        call     ktuchg()+0           2 ? 89E91A08 ? 1 ? B7BC3484 ?
                                                   B7BC348C ? AD7BECC ?
                                                   BFFF9CEC ? AD7BE38 ? 0 ? 0 ?
kdtchg()+1406        call     ktbchg2()+0          0 ? 89E91A08 ? B7BC3484 ?
                                                   B7BC348C ? AD7BECC ?
                                                   BFFF9CE4 ? AD7BE38 ? 0 ? 0 ?
kdtwrp()+2272        call     kdtchg()+0           B7BA8638 ? B7BC3484 ?
                                                   B7BC348C ? AD7BECC ?
                                                   AD7BE38 ? 1 ? 1C6 ?
kdtInsRow()+1724     call     kdtwrp()+0           B7BA8638 ? B7BA0000 ?
                                                   60DD40A4 ? B7BC31AC ? C ?
                                                   2C88E28 ?
insrow()+275         call     kdtInsRow()+0        B7BA8638 ? 89E95354 ?
                                                   89E950EC ? B7BA8418 ?
                                                   9840000 ? AD589E8 ?
insdrv()+2566        call     insrow()+0           B7BA8638 ? BFFF9FEC ? 0 ?
insexe()+1665        call     insdrv()+0           B7BA8638 ? 89E950EC ? 0 ?
                                                   B7BA8418 ? 0 ? 0 ?
opiexe()+10831       call     insexe()+0           89E95354 ? BFFFA220 ?
opipls()+6068        call     opiexe()+0           4 ? 3 ? BFFFA98C ?
opiodr()+5238        call     kjxsupd()+987        66 ? 6 ? BFFFB64C ?
rpidrus()+140        call     opiodr()+0           66 ? 6 ? BFFFB64C ? 5 ?
skgmstack()+211      call     rpidrus()+0          BFFFB028 ? 10 ? BFFFB040 ?
                                                   BFFFB3E4 ? BFFFB028 ?
                                                   899782A ?
rpidru()+93          call     skgmstack()+0        BFFFB040 ? AD5A760 ? F618 ?
                                                   899782A ? BFFFB028 ?
rpiswu2()+777        call     rpidru()+0           BFFFB3E4 ? 40 ? 40 ? 0 ?
                                                   40C ? A4B929C ?
rpidrv()+1452        call     rpiswu2()+0          837327D8 ? 40 ? BFFFB4E8 ?
                                                   2 ? BFFFB508 ? 40 ?
psddr0()+113         call     rpidrv()+0           5 ? 66 ? BFFFB64C ? 3A ?
                                                   AD5907C ? BFFFB7F8 ?
psdnal()+173         call     psddr0()+0           5 ? 66 ? BFFFB64C ? 30 ? 20 ?
                                                   B7BBB6B8 ?
pevm_EXECC()+458     call     psdnal()+0           BFFFC844 ? BFFFC834 ?
                                                   AD53500 ? B7BBB6B8 ?
                                                   856EA21C ? 856EA21C ?
pfrrun()+31877       call     pevm_EXECC()+0       B7BBF19C ? AD9E4C0 ? 20 ?
peicnt()+291         call     pfrrun()+0           B7BBF19C ? 0 ? AD9E31C ?
                                                   ADA0464 ? AD5907C ?
                                                   BFFFCC10 ?
kkxexe()+451         call     peicnt()+0           BFFFC844 ? B7BBF19C ? 2 ?
                                                   AD9954C ? 5001AA24 ? 0 ?
opiexe()+12624       call     kkxexe()+0           B7BBD068 ? B7BB022C ?
                                                   AD53504 ? B7BBD068 ? 0 ? 0 ?
opiall0()+4435       call     opiexe()+0           4 ? 3 ? BFFFD064 ?
opial7()+441         call     opiall0()+0          3E ? 22 ? BFFFD164 ?
                                                   BFFFDC0C ? BFFFD1EC ? 0 ?
opiodr()+5238        call     kjxsupd()+987        47 ? F ? BFFFDC0C ?
ttcpip()+2124        call     opiodr()+0           47 ? F ? BFFFDC0C ? 1 ?
Cannot find symbol in /lib/tls/libc.so.6.
opitsk()+1635        call     ttcpip()+0           AD53500 ? 47 ? BFFFDC0C ? 0 ?
                                                   BFFFE4E4 ? BFFFE4E0 ?
opiino()+602         call     opitsk()+0           0 ? 0 ? AD53500 ? AD8D7B8 ?
                                                   83 ? 0 ?
opiodr()+5238        call     kjxsupd()+987        3C ? 4 ? BFFFF8B0 ?
opidrv()+517         call     opiodr()+0           3C ? 4 ? BFFFF8B0 ? 0 ?
sou2o()+25           call     opidrv()+0           3C ? 4 ? BFFFF8B0 ?
main()+182           call     sou2o()+0            BFFFF894 ? 3C ? 4 ?
                                                   BFFFF8B0 ? 1 ? 0 ?
00622DE3             call     main()+0             2 ? BFFFF954 ? BFFFF960 ?
                                                   5FBC66 ? 734FF4 ? 0 ?

从SQL来看,是个简单的INSERT语句,那么就涉及到事务处理了。
从call stack来看,在stack顶端,下面的几行表明错误应该是跟回滚段有关。

# ktugusc()+787        call     kgeasi()+0           AD58FA0 ? AD9AFC0 ? FCA ? 2 ?  
#                                                    1 ? 4 ? 7C10 ?  
# ktuswr()+2049        call     ktugusc()+0          BFFF9394 ? D ? 1 ? 0 ? 0 ?  
#                                                    0 ? 0 ? 0 ?  
# ktusmous_online_und  call     ktuswr()+0           D ? 0 ? 0 ? 0 ? 0 ? 1 ?  
# oseg()+898                                           
# ktusmaus_add_us()+3  call     ktusmous_online_und  1 ? 1 ? BFFF94F8 ? 1 ?  
# 27                            oseg()+0               

这一步的分析其实很快,基本上凭call stack中的函数名字来判断。由于当时有其他的事情在处理,同时也不在这套库的现场,就让DBA重新创建了一个UNDO表空间,并将UNDO_TABLESPACE参数设置为新的UNDO表空间名字,错误就不在出现。

其实这个故障的处理,类似于去年处理的一个案例,详见记一次并行恢复问题导致Oracle数据库Crash故障的处理

一个简单的故障处理过程,记录下来,供朋友们参考。

怎样获取发生错误的会话信息

Posted by 老熊 on 7月 26th, 2009

某些Oracle错误,并不是总是伴随着产生trace文件,这些错误,对Oracle来说并不是严重的错误,比如像ORA-01555这样的错误。

我们可以设置一个事件,在发生错误时,产生一个Trace文件,事件通常使用下面的命令格式:

    alter system set events '<error_number> trace name errorstack level <level>';
    alter session set events '<error_number> trace name errorstack level <level>';

然而,使用alter system命令设置事件后,只会对新连接的会话有效。比如下面的测试:

会话一:
[oracle@xty scripts]$ sqlplus test/test

SQL*Plus: Release 10.2.0.4.0 - Production on Sat Jul 25 23:25:51 2009

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

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

SQL> drop table t1;

Table dropped.

SQL>          
SQL> create table t1 ( a number primary key);

Table created.

SQL> insert into t1 values (1);

1 row created.

SQL> commit;

Commit complete.

会话二:

alter system set events '1 trace name errorstack level 1';

会话一:
SQL> insert into t1 values (1);
insert into t1 values (1)
*
ERROR at line 1:
ORA-00001: unique constraint (TEST.SYS_C005801) violated

此时检查user_dump_dest目录,没有相应的trace文件产生,如果我们再执行下面的动作:

SQL> conn test/test
Connected.
SQL> insert into t1 values (1);
insert into t1 values (1)
*
ERROR at line 1:
ORA-00001: unique constraint (TEST.SYS_C005801) violated

就可以在user_dump_dest发现产生的trace文件。

那么发生错误的会话已经连接到数据库一段时间了,怎么得到这个会话在的信息?比如某个数据库,数据库中频繁地报下面的错误:

select sysdate create_time from dual
ORA-01555 caused by SQL statement below (Query Duration=0 sec, SCN: 0x09e5.0c3c77b1):
Wed Jul 22 11:17:51 2009
select g.*,m.*  from Tb_Model m right outer join (select t.*,v.table_name from.....

这个ORA-01555错误是非常怪异的,首先是查询DUAL表都会报错,其次,每次报错都是“Query Duration=0 sec, SCN: 0×09e5.0c3c77b1”,这里除了BUG,实在想不到其他的理由 。不过为了查明到底是哪个会话和哪个应用,是不是同一个会话引起,我们需要得到这个引起错误的会话的信息。

这里,我们可以用触发器。以SYS用户执行下面的代码:
Read the rest of this entry »

CRSD自动重启和产生CORE DUMP的故障处理

Posted by 老熊 on 3月 17th, 2009

一套运行在AIX 5.3,HACMP 5.4上的双节点RAC数据库,CRS和数据库的版本均为10.2.0.3;CRSD.BIN自动重启,并产生很多的CORE DUMP。
进入$ORA_CRS_HOME/log/<nodename>/crsd目录下,查看crsd日志文件,可以看到CRSD在重启时的日志如下:

2009-03-13 13:59:49.692: [ OCRRAW][11400]proprdc: backend_ctx->prop_sctx=[0x1017ed10]
2009-03-13 13:59:49.692: [ OCRRAW][11400]proprdc: backend_ctx->prop_sltsmx=[0x0]
2009-03-13 13:59:49.692: [ OCRRAW][11400]proprdc: backend_ctx->prop_sclsctx=[0x10365848]
2009-03-13 13:59:49.692: [ OCRRAW][11400]proprdc: backend_ctx->prop_ctx_ocrctx=[0x10362940]
2009-03-13 13:59:49.692: [ OCRSRV][11400]th_snap:8:failed to take backup prop_retval=26
2009-03-13 13:59:51.480: [ CRSOCR][11240]32OCR api procr_open_key failed for key CRS.CUR.ora!wydb3!ons. OCR error code = 3 OCR error msg:
2009-03-13 13:59:51.480: [ CRSOCR][11240][PANIC]32Failed to open key: CRS.CUR.ora!wydb3!ons(File: caaocr.cpp, line: 319)

2009-03-13 14:00:06.282: [ default][1][ENTER]32
Oracle Database 10g CRS Release 10.2.0.3.0 Production Copyright 1996, 2004, Oracle. All rights reserved
2009-03-13 14:00:06.282: [ default][1]32CRS Daemon Starting
2009-03-13 14:00:06.282: [ CRSMAIN][1]32Checking the OCR device
2009-03-13 14:00:06.285: [ CRSMAIN][1]32Connecting to the CSS Daemon
2009-03-13 14:00:06.705: [ CRSD][1]32Daemon Version: 10.2.0.3.0 Active Version: 10.2.0.3.0
2009-03-13 14:00:06.705: [ CRSD][1]32Active Version and Software Version are same
2009-03-13 14:00:06.705: [ CRSMAIN][1]32Initializing OCR
2009-03-13 14:00:06.713: [ OCRRAW][1]proprioo: for disk 0 (/dev/rwbsdb_ocr1_128m), id match (1), my id set (550012785,1028247821) total id sets (1), 1st set (550012785,1028247821), 2nd set (0,0) my votes (2), total votes (2)
2009-03-13 14:00:06.809: [ CRSD][1]32ENV Logging level for Module: allcomp 0

列出目录中的所有文件可以看到,最近几天都有core dump文件。仔细查看可以发现,每个core dump文件的间隔周期为固定的8.5小时。这是一个周期性的现象。

仔细查看上面的日志,”红色字体“的部分,引起了我的注意。这个错误,表明是在做某个东西的备份的时候报了错。应该是在备份OCR。core dump产生的周期和crsd自动重启的周期,都是固定的,这跟CRS会自动周期性地备份OCR比较吻合。

在METALINK上一番搜索,找到了BUG 5893629与这个故障现象比较符合。METALINK对这个BUG的描述称,CRS在备份OCR时,会在$ORA_CRS_HOME/cdata/<cluster_name>目录下生成一个temp.ocr,如果这个文件之前已经存在,会试图删除这个文件,而如果这个文件由于不是root用户所有,则就会导致crsd crash。这个BUG要在10.2.0.4才会修复。

根据对这个BUG的描述,进入到$ORA_CRS_HOME/cdata目录,这个目录下面有两个目录,一个是“crs”,另一个是”localhost“,一般来说,crs就是CRS集群的名称。进入这个目录,没有发现任何文件,看权限,root用户也可以建立文件。

问题在哪里呢?换一个角度思考,既然BUG描述中称不能删除旧的temp.ocr文件会导致crsd crash,那要是没有$ORA_CRS_HOME/cdata/<cluster_name>这个目录会怎么样,一样不能建立temp.ocr这个文件,那这种情况也会不会crash?这里$ORA_CRS_HOME/cdata目录下只有crs和localhost目录,如果按这种推理,如果cluster_name不是通常的”crs“呢?

不过当时有其他事情,离开了现场,不能得到CRS集群名字。不过幸运的是,我在日志文件中,在上面贴出的那段信息的前面,经过了一大段一大段的无用的信息之后,找到了下面的日志:

2009-03-13 13:59:49.391: [ OCRRAW][11400]rbkp:1: could not create the temp backup file [/oracle/crs/cdata/wydb_crs/temp.ocr]
2009-03-13 13:59:49.391: [ OCRRAW][11400]proprseterror: Error in accessing physical storage [26] Marking context invalid.

这里的日志就更明显了,就是不能创建”/oracle/crs/cdata/wydb_crs/temp.oc“这个文件。而前面的推断却不幸言中,CRS集群名字真的不是默认的”crs”,/oracle/crs/cdata这个目录下也的确没有wydb_crs这个目录。

让数据库维护人员在/oracle/crs/cdata目录中新建一个目录wydb_crs,经过一段时间的观察,故障不再出现,问题解决。

从这个故障中,我们得到一个教训,CRS有时真的很傻,为什么在备份时像这种不能创建文件的错误,不是写个日志忽略过去而是直接将进程crash了,并且还产生了core dump?为什么在安装CRS时,安装软件不自动建好这个目录,而只是按默认的”crs”名字建立目录?看来安装ORACLE软件的时候,CRS集群名字取默认值就行了。严重怀疑那个BUG是不是真的会解决这个问题(根据METALINK的描述,在备份时会随机生成一个文件名,而不再是固定的temp.ocr,但如果像这个案例中的故障,仍然会得不到解决。)

记一次并行恢复问题导致Oracle数据库Crash故障的处理

Posted by 老熊 on 10月 16th, 2008

环境:HP-UX 11.31
Oracle 9.2.0.8

数据库异常崩溃,询问维护人员之前有大量数据操作。查看alert日志:

Thu Oct 9 02:20:18 2008
Errors in file /oracle/OraHome1/rdbms/log/acct_ora_11361.trc:
ORA-00600: internal error code, arguments: [ktprhtnew6], [], [], [], [], [], [], []
Thu Oct 9 02:20:19 2008
Fatal internal error happened while SMON was doing active transaction recovery.
Thu Oct 9 02:20:19 2008
Errors in file /oracle/OraHome1/rdbms/log/acct_ora_11361.trc:
ORA-00600: internal error code, arguments: [ktprhtnew6], [], [], [], [], [], [], []
SMON: terminating instance due to error 600
Instance terminated by SMON, pid = 11361

检查trace文件,没有发现有用的信息。

重启数据库,数据库能打开,但不到一分钟实例就crash。在alert日志中的错误信息均如上所示。
在网上及在metalink中以ktprhtnew6为关键字搜索,没有找到相似的BUG和案例。同时当时手边是用的163拨号上网,速度非常慢,只有通过分析来解决问题。

仔细分析alert日志可以发现是在做事务恢复时SMON出错,导致实际中止:

Fatal internal error happened while SMON was doing active transaction recovery.

我们知道ORA-600错误后面参数,如果像ktprhtnew6这样的均表示出错的函数。这里可以看出是在做并行恢复:

[K]enerl [T]ransaction [P]arallel [R]ecovery

设置fast_start_parallel_rollback参数为false,关闭数据库的并行恢复功能,重启数据库,数据库正常,故障消失。
看起来这应该又是一个BUG。


Copyright © 2007 老熊的三分地-Oracle、UNIX、数据恢复. All rights reserved.