oracle 大量trace,Trace文件过量生成问题解决

随着Oracle技术本身的不断发展，“自动化”和“智能化”的数据库时代已经来临。无论是运维管理、开发调试，传统DBA们的工作内容都已经发生了很大变化。一些诸如内存池划分调整、归档日志管理等功能，都已经被Oracle自动或者半自动的特性所解决。对新一代DBA而言，保持不断学习的精神，接受新问题，发现属于自己的一片新天地，才是当务之急。

今天，和一个朋友解决了一个运维环境问题。笔者感觉很有意思，记录下来，供需要的朋友不时之需。

1、问题说明

今天，一个朋友从QQ上提出问题，说在测试环境的一台10gR2库，近期突然生成很多Trace Dump文件。每个文件大小在4-5M，频率每分钟若干次。几天之内占用了上百G的空间，删除无用文件之后依然产生。

Oracle Trace文件从本质上是Oracle前后台进程在特殊的情景下，例如开启跟踪模式、运行异常，自动向文件系统中输出的诊断文件。Trace文件通常以trc结尾，包含进程环境信息、运行过程和故障点输出。对Oracle官方和管理人员而言，Trace文件是诊断的重要依据。

正常运行情况下，每台数据库都会生成一些trc文件，每个文件大小在几k左右，是不会产生朋友遇到的问题的。

之后，朋友将数据库alert log和一个trace文件样本发给笔者。Trace文件大小在4M左右，明显超过正常大小。之所以还要alert log，是因为Oracle在生成trace文件时候，通常对应alert log中有相应记录。

2、问题分析

朋友的数据库环境是Oracle 10gR2，具体版本是10.2.0.3.0.。从alert log中，可以发现是一个标准的Windows数据库环境。

System parameters with non-default values:

processes= 150

sga_target= 612368384

control_files= D:\ORADATA\ORACLE10\CONTROL01.CTL, D:\ORADATA\ORACLE10\CONTROL02.CTL, D:\ORADATA\ORACLE10\CONTROL03.CTL

db_block_size= 8192

compatible= 10.2.0.3.0

db_file_multiblock_read_count= 16

db_recovery_file_dest= D:\oracle\product\10.2.0\flash_recovery_area

db_recovery_file_dest_size= 2147483648

undo_management= AUTO

undo_tablespace= UNDOTBS1

remote_login_passwordfile= EXCLUSIVE

在alert log中，我们果然发现了很多异常点。从若干天之前，就不断报错异常。

Wed Jan 21 12:49:10 2015

db_recovery_file_dest_size of 2048 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.

Wed Jan 21 12:49:11 2015

Completed: alter database open

Wed Jan 21 12:49:22 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j002_2524.trc:

Wed Jan 21 12:49:28 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j000_2516.trc:

Wed Jan 21 12:49:34 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j003_3752.trc:

Wed Jan 21 12:49:35 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j002_2524.trc:

ORA-12012:自动执行作业26出错

ORA-08102:未找到索引关键字,对象号239,文件1,块1674 (2)

之后，每隔约5秒钟，就生成一个trace文件，对应内容相同。

Mon Mar 23 09:30:52 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j002_4348.trc:

ORA-12012:自动执行作业26出错

ORA-08102:未找到索引关键字,对象号239,文件1,块1674 (2)

Mon Mar 23 09:30:55 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j001_1376.trc:

ORA-12012:自动执行作业4出错

ORA-08102:未找到索引关键字,对象号239,文件1,块1674 (2)

Mon Mar 23 09:30:56 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j001_1376.trc:

ORA-12012:自动执行作业4出错

ORA-08102:未找到索引关键字,对象号239,文件1,块1674 (2)

再打开trace文件，文件名称为：oracle10_j000_5820。Jxxx通常为Oracle的自动作业Job后台进程，自动按照执行的规则后台执行。其中，包括了报错功能点：

*** 2015-03-23 09:30:38.468

ksedmp: internal or fatal error

Current SQL statement for this session:

update sys.job$ set failures=0, this_date=null, flag=:1, last_date=:2,next_date = greatest(:3, sysdate),total=total+(sysdate-nvl(this_date,sysdate)) where job=:4

执行job$修改操作时候，发出的错误信息。

诊断的依据中，“对象239，文件1，块1674(2)”是很好的入手点。从提示信息看，似乎这个对象遇到了坏块情况。文件1是system表空间，应该是Oracle内部对象。

由于笔者不能实际操作问题库，所以找到了类似的环境进行简单检查。

SQL> select * from v$version;

BANNER

----------------------------------------------------------------

Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Prod

PL/SQL Release 10.2.0.3.0 - Production

CORE10.2.0.3.0Production

TNS for 32-bit Windows: Version 10.2.0.3.0 - Production

NLSRTL Version 10.2.0.3.0 – Production

找到object_id=239对象。

SQL> select object_name, object_type, status from dba_objects where object_id=239;

OBJECT_NAMEOBJECT_TYPESTATUS

-------------------- ------------------- -------

I_JOB_NEXTINDEXVALID

报错对象是一个索引对象，对应的段结构。

SQL> select SEGMENT_TYPE, TABLESPACE_NAME, HEADER_FILE, HEADER_BLOCK, BLOCKS, EXTENTS from dba_segments where segment_name='I_JOB_NEXT';

SEGMENT_TYPETABLESPACE_NAMEHEADER_FILE HEADER_BLOCKBLOCKSEXTENTS

------------------ -------------------- ----------- ------------ ---------- ----------

INDEXSYSTEM1167381

对应的索引段结构很小，只有一个extents，合计八个数据块。注意：头块编号为1673。报错块号为1674，是段头块后面第一个数据块。

熟悉Oracle段结构的朋友一定知道，索引段后第一个数据块就是索引树的根节点块。报错信息很可能是出现了索引段损坏的情况。

3、问题修复

在Oracle中，坏块是很难处理的一种故障。从官方角度，坏块的来源有两个：一个是软硬件存储之间的不兼容，另一个是Oracle内部Bug。处理坏块的手段有很多，落实到这个案例中，索引段坏块是比较好处理的一种。

最简单的处理策略是尝试rebuild索引，让数据库重新整理结构。模拟操作：

SQL> alter index I_JOB_NEXT rebuild;

Index altered

让朋友在环境上进行测试，发现执行成功，索引状态也是valid。但是问题依然存在，trace文件还会生成。

索要最新的alert log之后，发现报错信息变化。

Mon Mar 23 10:15:35 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j002_6932.trc:

ORA-00604:递归SQL级别1出现错误

ORA-08102:未找到索引关键字,对象号239,文件1,块65946 (2)

ORA-12012:自动执行作业26出错

ORA-08102:未找到索引关键字,对象号239,文件1,块65946 (2)

Mon Mar 23 10:15:37 2015

Errors in file d:\oracle\product\10.2.0\admin\oracle10\bdump\oracle10_j001_7056.trc:

ORA-00604:递归SQL级别1出现错误

ORA-08102:未找到索引关键字,对象号239,文件1,块65946 (2)

ORA-12012:自动执行作业4出错

ORA-08102:未找到索引关键字,对象号239,文件1,块65946 (2)

注意，报错内容发生了变化。块号变化到了system表空间另一个位置。说明：rebuild操作生效，修改了index的结构，但是错误依然存在。

笔者的一种猜想是：也许rebuild操作并不能直观反映数据表的数据情况，而报错问题是在索引数据和表段数据的不一致。尝试解决方法：drop后重新create索引对象。

SQL> drop index i_job_next;

Index dropped

SQL> create index i_job_next on job$ (next_date);

Index created

之后，问题解决。

4、结论

相对于各种复杂问题，今天这个问题相对比较单纯简单。但是这个问题告诉我们教训。首先，问题处理要从核心线索入手，层层深入，最后定位问题。其次，对于一些想当然的概念，如rebuild，要更加深层次理解含义，更详细的分析。