通过LogMiner分析归档日志异常增长一例

前言：

在解决数据库问题过程中，我们偶尔会遇到数据库归档日志异常增长的情况，这种问题相对都比较棘手，而且其对数据库的影响非常明显，主要表现在：

  数据库性能压力陡增，整体性能下降

  磁盘IO压力增大，形成IO瓶颈

  归档日志生成过快，可能导致磁盘空间占满，引起数据库宕机

由于这类问题对生产业务的影响非常大，用户和渠道都迫切的希望能够立即、彻底的解决，但是往往归档日志的增长原因又多种多样，分析过程中相对比较困难和复杂，今天我们就通过一个案例讲解如何通过对归档日志解析来分析和查找日志异常增长的问题。

案例描述：

不久前一家用户反馈，数据库无法使用，通过远程查看，磁盘空间已经被撑满，数据库无法归档，导致数据库宕机，问题看似很简单，清理下归档日志，然后重新启动下数据库就解决，但是问题显然没有这么简单，为什么磁盘空间为突然被撑满？这时候我们就发现该用户的归档日志增长异常频繁，如下图：

       通过SQL生成归档日志每小时的切换频率，如下：

从截图可以看到，该数据库单个归档日志有50M，从3月12日20点开始，每秒产生5~6个归档日志，一小时产生300个归档日志，也就是说每秒产生250M，一小时产生14GB归档日志，可以用相当惊人来形容，这样的日志产生量，就是再大的剩余空间也会被撑满，相信如果不处理，过不了多久，用户的磁盘会再次撑满，业务会再次宕机，同时医院反馈目前前台应用明显感觉非常慢，问题比较严重，需要立即着手解决。

解决过程：

为什么会产生这么多归档日志，这时候数据库内部到底在做什么操作？只有了解这两点，才能根本上的解决该问题，这里我们就要用到一个处理类似问题非常有效而直接的手段-----日志分析。

Oracle提供了一个日志分析工具LogMiner，通过这个工具可以对归档日志中的内容进行读取和分析，手工执行该工具过程相对比较复杂，这里给大家介绍一个简单的方式，通过toad里面集成的logMiner功能进行分析。大家应该听说过与我们日常使用频繁的PLSQL Developer齐名的另一款Oracle的维护工具Toad（俗称小青蛙），该工具由于没有中文汉化版再加上使用没有PLSQL Developer这么方便简单，因此不被大家所熟知，但是其强大的功能确是PLSQL Developer所无法比拟的，这里我们就使用其集成的logMiner功能来分析和查找归档日志异常增长的原因。

首先打开Toad,在登录界面输入登录用户名和密码，选择连接方式，然后连接指定的数据库实例，如下：

       连接数据库实例后，在Database下面的Diagnose里面，找到我们这次要使用的功能LogMiner，打开它，如下：

       直接点下一步，在File to Mine这里，把我们想要分析的归档日志的完整路径输入到文本框中，这里我们要分析的日志为/u01/archive/1_30673_759001307.dbf,注意到这里的日志路径只需要在服务器上路径就可以，不用拷贝到本地，如下：

       点击Next就开始对日志进行分析，我们来看下分析结果，这里只截取有问题的部分内容进行展示，如下：

       从日志分析的结果来看，应该就是数据库在执行大量的select * from for update语句产生的归档日志，我们找出其中一个语句单独进行分析，如下：

       可以看到该对象是我们ZLHIS业务数据对象，因此肯定同我们的业务操作有直接关系，再在数据库中对该对象进行查询，结果如下：

只是一个过程和公共同义词，为什么这个对象会产生归档日志，数据库会执行大量的select * from for update语句，之前数据库到底做了什么操作?通过询问系统管理员，管理员反馈，之前对生产库部分私有同义词进行了清理，原来是这样!!这就能够清楚的解释为什么会出现大量的针对ZLHIS对象的select * from for update操作。因为之前对私有同义词进行了删除，虽然对象已经删除，但是在数据字典obj$中，该对象的信息还是存在，这部分信息需要数据库后台进程SMON进行更新，这些操作就是更新数据字典导致的,按理说这些更新数据字典应该不会几天都更新不完，肯定这里还有问题，于是查询相关资料，发现如下类似BUG信息，文档的部分内入如下:

Bug 5116414 - Cleanup of non-existence objects by SMON takes a long time (Doc ID 5116414.8)

Symptoms:

Related To:

• Performance Of Certain Operations Affected
• ORA-4030

• (None Specified)

Description

SMON can spend excessive time when processing obj$ rows that have a type# of 10, or SMON might return ORA-4030 during this process. This problem shows most CPU use in kqlclo() or kqlclo1()[depends on database version].Workaround  Set event 10052 to any non-zero value to disable cleanup  until a time when it can be enabled.Note:  This fix changes the behaviour of event 10052 such that it   now controls the cleanup behaviour.

该文档显示，如果遇到BUG5116414,SMON在清理不存在的对象记录的时候，会执行非常长的时间,虽然我们的数据库版本是10.2.0.4，文档上说该问题在这个版本已经修复，但是很不幸，目前这个BUG依然被碰上了，看来Oracle对该BUG的修复还不彻底，找到问题的根本原因，接下来就需要针对问题进行处理，目前有两种处理方式：

  通过设置事件屏蔽进程，不更新OBJ$数据字典

  等待SMON进程把数据字典更新完成

首先看下还有多少数据需要更新，通过下面的SQL语句查询出数据字典和数据对象不一致记录，这些记录的type#=10,如下：

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# = 10 And Not Exists (Select p_Obj# From Dependency$ Where p_Obj# = o.Obj#)
Order By o.Obj#

查询出来的结果还有15W条记录，证明还需要进行更新大量的数据记录，如果任由数据库SMON进程继续执行，可能还会耗时大量的时间，产生大量的日志，如果在业务高峰期执行，肯定会影响业务应用，因此在业务高峰期只有通过文档的提示设置10052内部事件让SMON更新操作禁用，设置命令如下：

alter system set events '10052 trace name context forever, level 65535';

10052诊断事件：用来禁止SMON清理obj$基表，避免SMON因cleanup obj$的相关代码而意外终止或spin从而开展进一步的诊断时可以设置该诊断事件。在Oracle并行服务器或RAC环境中，也可以设置该事件来保证只有特定的某个节点来执行清理工作。

在业务不繁忙的时候，又取消10052诊断，让SMON进程继续进行数据字典清理，但是这个过程中做好磁盘空间的监控和清理，这样即不影响正常的业务应用，同时也保证数据库内部的数据一致，避免可能出现的一些未知错误，通过这个的设置，在经过一段时间的清理后，该数据日志增长量恢复正常，问题彻底解决。

总结

通过本篇文档的介绍，大家今后在处理日志增长这类问题的时候，又多了一种行之有效的方法，本案例我们至少能够总结出以下几点经验：

1.          遇到归档日志异常增长的情况，最好通过LogMiner对归档日志进行分析，找到异常增长的原因。

2.          Toad工具的LogMiner功能非常的简单和直观的进行日志分析。

3.          SMON进程会对数据字典进行更新，通过10052诊断事件可以禁止更新。

当问题出现时，不能只看表象，解决问题一定要找到问题产生的根本原因，再透过该原因去有的放矢，这样才能彻底解决问题。