某些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: 0x09e5.0c3c77b1”,这里除了BUG,实在想不到其他的理由 。不过为了查明到底是哪个会话和哪个应用,是不是同一个会话引起,我们需要得到这个引起错误的会话的信息。

这里,我们可以用触发器。以SYS用户执行下面的代码:

Read the rest of this entry

一套运行在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,但如果像这个案例中的故障,仍然会得不到解决。)

环境: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。

先说说这个数据库的环境:
Oracle 9.2.0.4 RAC,只不过这个RAC只运行了一个节点,另一节点没有开启。
AIX 5.3 TL04
主机为p550,4CPU,16G内存
应用为部署在Weblogic下的WEB应用。

故障现象:
首先是客户端的操作没有响应,从weblogic上看连接数非常高,其日志里面不停报超出连接池的最大连接数。在主机上用sqlplus "/ as sysdba",在显示sqlplus的banner后,停止响应。

从故障现象来看,是数据库hang住了。

由于sqlplus不能操作,那么这个时候没办法通过oracle来dump system state。先看看操作系统里面,用topas命令观察,发现一个oracle进程占用了26%左右的CPU资源,IO等待几乎为0,可用的物理内存还比较多。根据那个占用CPU的进程号用ps命令查看,是一个普通的Server Process。

看来起这个进程陷入死循环了,26%的CPU资源正好是1个CPU(因为系统共4个CPU)。如果一个oracle进程拿到比较重要的资源,比如shared pool latch、library cache latch等,然后陷入了死循环(SPIN)后,其他进程没法解析SQL等,也就只有挂起了。

用kill命令杀掉那个进程,系统恢复正常,看来前面对故障的推断是正确的,不过没过几分钟,又出现了此故障现象。

只有找到oracle当时正在干什么,才能进行处理。用dbx来dump system state:

# dbx -a 446910
Waiting to attach to process 446910 ...
Successfully attached to oracle.
Type 'help' for help.
reading symbolic information ...
stopped in iosl.select at 0x9000000000c94d8 ($t2)
0x9000000000c94d8 (select+0xfffffffffff06318) e8410028 ld r2,0x28(r1)
(dbx) print ksudss(10)

Segmentation fault in slrac at 0x100083aa0 ($t2)
0x100083aa0 (slrac+0xe4) 88030000 lbz r0,0x0(r3)
(dbx) detach

Read the rest of this entry

某客户的一个表在进行分析和建索引一段时间时,均报ORA-8103错误。

让我们先看看ORA-8103错误是个什么样的错误?

[oracle@xty ~]$ oerr ora 8103
08103, 00000, "object no longer exists"
// *Cause: The object has been deleted by another user since the operation
// began, or a prior incomplete recovery restored the database to
// a point in time during the deletion of the object.
// *Action: Delete the object if this is the result of an incomplete
// recovery.

从上面的信息来看,引起这个错误的并不是由于什么对象被删除或者不完全恢复引起的。看来剩下的可能就是BUG或者是坏块了。

select /*+ parallel(a 6) no_index(a) */
count(lrrq) from hz2004.HJXX_RYZPXXB a

由于表很大,100g左右,因此等了好长一段时间,就报了ORA-8103错误。由于不同的SQL语句(建索引、分析表和查询表数据)都报了这个错误,基本可以确定是坏块引起的问题。

由于表中有long raw类型,因此不能通过从主键取得ROWID再根据ROWID读到值以后插入新表,由于查询表有问题,导出也不会成功。因此决定想办法来修复这个问题:

首先要确定是哪个块出现问题:

SQL> alter session set max_dump_file_size=unlimited;
SQL> alter session set db_file_multiblock_read_count=1;
SQL> alter session set events ‘immediate trace name trace_buffer_on level 1048576′;
SQL> alter session set events ‘10200 trace name context forever, level 1′;
SQL> select /*+ no_index(a */ count(*) from hz2004.hjxx_ryzpxxb a;

(注:经测试,在10g中,需要去掉trace_buffer_on那一个语句才会有trace,否则没有trace文件)
再次报错时,检查trace文件,发现如下的信息:

Consistent read started for block 11 : 09c63a9e
env: (scn: 0×0886.245ea878 xid: 0×0000.000.00000000
uba: 0×00000000.0000.00 statement num=0 parent xid:
xid: 0×0000.000.00000000
scn: 0×0000.00000000 0sch: scn: 0×0000.00000000)

从trace文件中可以发现在读文件号39块号408222时报错。

执行:

select * from hz2004.hjxx_ryzpxxb
where rowid=dbms_rowid.rowid_create(1,7415,39,408222,0);

报ORA-08103错误,可以确认是39号文件408222块坏。

然而用dbv命令检查39号文件,没有发现坏块。

通过dd取出39号文件408222块,发现该块居然是一个未格式化的块,但是该块在表的High water mark以下。单从该块来说是一个好的块,所以dbv检查并不会报坏块。

既然如此,我就故意做成一个坏块,然后让oracle跳过这个坏块。关闭库之后,用dd把坏块复制出来保存在一个文件,然后修改该块,使之成为一个坏块(很多的方法,这里我的方法就是修改其checksum值)。然后用dd复制回去。重启库之后,用 dbms_repair.skip_corrupt_blocks过程设置表在读取数据时,跳过坏块。

再次读取该表的所有数据,不再报错。

客户进行建索引和分析时也不再报错,顺利进行。

当然后续的工作,还是需要将数据导出来再导入,这样更稳妥。

前一天遇到一例database link问题,仅供大家参考:

数据库是运行在Windows 2003上的Oracle 9i

先来看看故障现象,维护人员发现数据库上的job不能正常执行。用TOAD手工调用job的存储过程,TOAD一直阻塞。

经过这个故障的过程如下:

1.      在TOAD中手工执行存储过程,TOAD挂起。
2. 用sqlplus连接到数据库,检查v$session_wait,发现执行存储过程的会话正在等待library cache pin。
3. 通过x$kglob与v$session_wait,发现等待library cache pin的SQL语句为:
         select flag from account@zw.world ....
4. 手工执行此SQL,客户端挂起。怀疑是数据链路问题,执行select * from dual@zw.world,客户端也挂起。
5. 在sqlplus下,新建数据库zw_link,执行select * from dual@zw_link,执行此SQL仍然会导致客户端挂起。
6. 怀疑数据库服务器不能正常接连到ZW库。在数据库服务器上用sqlplus连接ZW库:
       sqlplus xxx/xxx@zw
    这时数据库服务器(windows系统)弹出一对话框,windows木马防火墙提示是否允许sqlplus程序访问zw的IP地址的信息。看来是由于木马防火墙引起的问题。
7. 查看系统中运行的进程,发现windows木马防火墙软件是通过线程注入到其他进程的方式,对进程的网络访问进行控制。在进程要访问网络时,弹出对话框选择是否允许访问网络,但ORACLE进程是以服务方式运行的,没有设置为与桌面交互,所以弹 出的对话框不能显示,所以一直处于等待状态。
8. 去掉windows木马防火墙的自动启动,重启服务器,删除windows木马防火墙,检查数据库链接已经正常。
9. 手工执行存储过程,存储过程正常执行。检查存储过程运行产生的日志,也显示正常。至此问题解决。

看来现在的防病毒,防木马的工具也是越来越“厉害”了。

一客户重启主机,启动数据库之后,客户端连接报ORA-12541:没有监听器的错误

环境:ORACLE 10.2.0.1 RAC AIX 5.3

进行测试,发现结点1不正常。客户端通过PUBLIC IP可以连接,但通过VIP不能进行连接,报ORA-12541错误

检查结点1的VIP,正常。在客户端PING VIP,正常。TNSPING VIP,不通。

检查监听配置,正常。

重启监听,故障依旧。

在客户端(WINDOWS系统),用arp -a命令检查发现,结点1的PUBLIC IP和VIP的MAC地址不一致。怀疑是其他机器占用了此IP。

在客户端用nbtstat -A VIP地址,发现是一WINDOWS系统机器占用了此IP,并得到机器名。

客户维护人员解决IP地址冲突,故障排除。

故障解决很快,但此故障引发的问题值得紧记:在管理数据库的同时,别忘网络的管理。特记之。