一、背景

XX系统数据库2013年1月7日归档日志增长异常，导致数据库宕机。

二、故障分析

1、数据库归档目录

归档目录为/arch1和/arch2，每个50G。

2、数据库alert<sid>.log分析

查看相应时间点的数据库运行日志，除了因归档目录满导致归档失败，并未有其他有用信息。

Errors in file /oracle/admin/landingbj/bdump/landingbj1_arc0_856396.trc:

ORA-19502: write error on file "/arch1/landingbj_1_6282_729960074.arc", blockno 350209 (blocksize=512)

ORA-27063: number of bytes read/written is incorrect

IBM AIX RISC System/6000 Error: 28: No space left on device

3、归档日志生成情况

下条语句是检查每天归档日志的生成量，能反映出归档日志生成的总体概况

SELECT TRUNC(COMPLETION_TIME),

       ROUND(SUM(BLOCKS * BLOCK_SIZE) / 1024 / 1024) AS "SIZE(M)"

  FROM V$ARCHIVED_LOG

 GROUP BY TRUNC(COMPLETION_TIME)

 ORDER BY TRUNC(COMPLETION_TIME) Desc

平时每天归档日志产生量在20G以下，从1月7日起归档生成出现异常，达到近60G，8日达到近140G。

下条语句检查每个线程每天每小时的归档日志生成量

SELECT THREAD#,
       A.TTIME,
       SUM(C8) "08",
       SUM(C9) "09",
       SUM(C10) "10",
       SUM(C11) "11",
       SUM(C12) "12",
       SUM(C13) "13",
       SUM(C14) "14",
       SUM(C15) "15",
       SUM(C16) "16",
       SUM(C17) "17",
       SUM(C18) "18",
       SUM(C0) "00",
       SUM(C1) "01",
       SUM(C2) "02",
       SUM(C3) "03",
       SUM(C4) "04",
       SUM(C5) "05",
       SUM(C6) "06" SUM(C7) "07",
       SUM(C19) "19",
       SUM(C20) "20",
       SUM(C21) "21",
       SUM(C22) "22",
       SUM(C23) "23"
  FROM (SELECT THREAD#,
               TTIME,
               DECODE(TTHOUR, '00', 1, 0) C0,
               DECODE(TTHOUR, '01', 1, 0) C1,
               DECODE(TTHOUR, '02', 1, 0) C2,
               DECODE(TTHOUR, '03', 1, 0) C3,
               DECODE(TTHOUR, '04', 1, 0) C4,
               DECODE(TTHOUR, '05', 1, 0) C5,
               DECODE(TTHOUR, '06', 1, 0) C6,
               DECODE(TTHOUR, '07', 1, 0) C7,
               DECODE(TTHOUR, '08', 1, 0) C8,
               DECODE(TTHOUR, '09', 1, 0) C9,
               DECODE(TTHOUR, '10', 1, 0) C10,
               DECODE(TTHOUR, '11', 1, 0) C11,
               DECODE(TTHOUR, '12', 1, 0) C12,
               DECODE(TTHOUR, '13', 1, 0) C13,
               DECODE(TTHOUR, '14', 1, 0) C14,
               DECODE(TTHOUR, '15', 1, 0) C15,
               DECODE(TTHOUR, '16', 1, 0) C16,
               DECODE(TTHOUR, '17', 1, 0) C17,
               DECODE(TTHOUR, '18', 1, 0) C18,
               DECODE(TTHOUR, '19', 1, 0) C19,
               DECODE(TTHOUR, '20', 1, 0) C20,
               DECODE(TTHOUR, '21', 1, 0) C21,
               DECODE(TTHOUR, '22', 1, 0) C22,
               DECODE(TTHOUR, '23', 1, 0) C23
          FROM (SELECT THREAD#,
                       TO_CHAR(FIRST_TIME, 'YYYY-MM-DD') TTIME,
                       TO_CHAR(FIRST_TIME, 'HH24') TTHOUR
                  FROM V$LOG_HISTORY
                 WHERE (SYSDATE - FIRST_TIME < 30))) A
 GROUP BY THREAD#, TTIME
 ORDER BY TTIME DESC

限于篇幅，省略部分记录。

实例1从1月7日21点开始就增长异常了，1月8日10:00-21:00增长极快，每小时都有7G以上归档日志产生。

下条语句检查哪些session生成归档异常

select a.INST_ID,b.sid,round((b.VALUE)/1024/1024/1024) "GB" from gv$statname a , gv$sesstat b

where a.INST_ID=b.INST_ID and a.STATISTIC#=b.STATISTIC# and a.NAME='redo size' order by 3 desc

限于篇幅，省略部分记录。

Sid=544是导致归档日志生成频繁的会话。

下条语句检查导致两个实例sid=544的详细信息

Select * From gv$session Where sid=544

导致归档日志生成频繁的进程是SMON。

4、Oracle核心后台进程SMON介绍

System Monitor简称SMON，要完成所有“系统级”任务。它以系统级为出发点，这是一种数据库“垃圾收集器”。SMON所做的工作包括：

a、清理临时空间

b、合并空闲空间

c、执行RAC中失败节点的实例恢复

d、清理OBJ$

e、“离线”回滚段

5、LogMiner分析归档日志

1）添加要分析的归档日志

begin

  dbms_logmnr.add_logfile(LogFileName => 'landingbj_2_5620_729960074.arc',

                          Options     => dbms_logmnr.new);

end;

/

2）使用在线数据字典分析

begin

  dbms_logmnr.start_logmnr(options => dbms_logmnr.DICT_FROM_ONLINE_CATALOG);

end;

/

3）查询分析结果

Select sql_redo From v$logmnr_contents

限于篇幅，省略部分记录。

Select Count(*) From v$logmnr_contents Where sql_redo Like 'select * from "SYS"."OBJ$" where ROWID =% for update;'

类似select * from "SYS"."OBJ$" where ROWID = 'AAAAASAACAAAnU/ABv' for update;

的语句有2230413条，暂且将这样的语句标识为异常语句。

继续分析下面归档日志，按上面1）、2）、3）步执行

landingbj_2_5624_729960074.arc  类似异常语句有2131288条。

/arch1/landingbj_1_6661_729960074.arc  类似异常语句有2099627条。

/arch1/landingbj_1_6656_729960074.arc  类似异常语句有2176965条。

可见，SMON频繁执行类似

select * from "SYS"."OBJ$" where ROWID = 'AAAAASAACAAAnU/ABv' for update;

是导致归档日志频繁生成原因。

5、sys.obj$表for update语句分析

前面提到，SMON的其中一个作用是清理obj$数据字典基表。

OBJ$基表是一张低级数据字典表，该表几乎对库中的每个对象(表、索引、包、视图等)都包含有一行记录。很多情况下，这些条目所代表的对象是不存在的对象(non-existent)，引起这种现象的一种可能的原因是对象本身已经被从数据库中删除了，但是对象条目仍被保留下来以满足消极依赖机制(negative dependency)。因为这些条目的存在会导致OBJ$表不断膨胀，这时就需要由SMON进程来删除这些不再需要的行。

SMON会在实例启动时以及启动后的每12个小时执行一次清理任务。

SMON清理obj$过程中会涉及下面语句：

select o.owner#,o.obj#,decode(o.linkname,null, decode(u.name,null,'SYS',

  u.name),o.remoteowner), o.name,o.linkname,o.namespace,o.subname

from

 user$ u, obj$ o where u.user#(+)=o.owner# and o.type#=:1 and not exists

  (select p_obj# from dependency$ where p_obj# = o.obj#) order by o.obj# for

  update

对obj$基表字段的解释可以从sql.bsq文件中获得，关于type#的解释，我们可以从中得到：

type#=10表示的是non-existant类型的对象，SMON要清理的就是sys.obj$.type#=10的记录。

1月9日23时，执行下面操作

分析landingbj_2_5620_729960074.arc归档日志，产生v$logmnr_contents。

执行下面5条语句

Select count(1) From v$logmnr_contents Where sql_redo Like 'select * from "SYS"."OBJ$" where ROWID =% for update;'  

查询结果：1805063

Select count(a.obj#) From sys.obj$ a,v$logmnr_contents b 

Where b.sql_redo Like 'select * from "SYS"."OBJ$" where ROWID =% for update;'And a.type#<>10 And a.rowid=b.row_id  

查询结果为：0

Select count(b.scn) From sys.obj$ a,v$logmnr_contents b 

Where b.sql_redo Like 'select * from "SYS"."OBJ$" where ROWID =% for update;'And a.type#=10 And a.rowid=b.row_id  

查询结果：1785965

Select count(Distinct a.obj#) From sys.obj$ a,v$logmnr_contents b Where b.sql_redo Like 'select * from "SYS"."OBJ$" 

where ROWID =% for update;'And a.type#=10 And a.rowid=b.row_id 

 查询结果：440646

select count(1) from obj$ where (name,owner#) in ( select o.name,u.user# from user$ u, obj$ o

where u.user# (+)=o.owner# and o.type#=10 and not exists (select p_obj# from

dependency$ where p_obj# = o.obj#) );  

查询结果：440600

通过几个查询后能够判断：在v$logmnr_contents里存在的类似select * from "SYS"."OBJ$" where ROWID = 'AAAAASAACAAAnU/ABv' for update; 都是SMON清理obj$发出的，同时SMON需要清理的记录还有440600条。

1月10日10:00和10:30，分别查询两次下面语句，该语句的作用是SMON还需要清理obj$的记录。

select count(1) from obj$ where (name,owner#) in ( select o.name,u.user# from user$ u, obj$ o

where u.user# (+)=o.owner# and o.type#=10 and not exists (select p_obj# from

dependency$ where p_obj# = o.obj#) );   

得到的查询结果：408958条和407765条，可见，SMON清理obj$的速度是很慢的，结合9日23时查询结果（440646条），obj$在10小时左右时间仅仅清理被4万条左右记录，速度较慢。

三、建议和总结

根据上面分析，1月7日归档日志频繁生成是由于oracle核心后台进程SMON导致，同时SMON清理sys.obj$速度极慢，极有可能触发BUG导致。

建议：

1）、适当增大归档目录空间大小，增加归档目录/arch1和/arch2到100G；

2）、优化备份策略，及时备份归档日志并删除备份前的归档日志；

3）、联系oracle原厂工程师确认：SMON进程清理obj$为何会产生如此大量的归档日志，清理obj$的速度为何如此之慢,，是否触发BUG？

4）、手动清理obj$，参考MOS文档，

SMON Consumes High CPU With Excessive Redo Log Generation [ID 1073704.1]

Smon Cleanup Preventing Job Processes From Executing [ID 340128.1]

这种方式存在一定的风险，因此在执行前，数据库必须做全备。具体步骤如下：

1、在参数文件中设置10052 event,来禁用smon清理obj$表的功能

EVENT="10052 trace name context forever, level 65535"

2、重启数据库到restricted模式。

3、通过下面的语句进行obj$表的清理

SQL> delete from obj$ where (name,owner#) in ( select o.name,u.user# from user$ u, obj$ o where u.user# (+)=o.owner# and o.type#=10 and not exists (select p_obj# from dependency$ where p_obj# = o.obj#) );

SQL> commit;

4、关闭数据库（必须shutdown abort）

5、从参数文件中移除10052 event的相关设置

6、启动数据库，并实时监控数据库alert日志是否出现异常。

7、做个full export操作，验证数据库的稳固性。