处理归档日志增加过快一例

摘要

       本文介绍了不久前作者是如何彻底解决一家医院数据库由于归档日志增长过快,导致磁盘剩余空间占满，引起宕机全过程。通过本案例的描述,我们可以了解到当遇到数据库宕机问题时，应该如何分析现象、找到问题关键、最终彻底解决该问题的一个总体思路，最后还应该深入思考该问题产生的原因，总结出避免以后再出现该问题的建议。

关键字: ORACLE、归档日志、宕机、DML语句

初步了解

       早上一来到公司，XZH就告诉我接到CQ公司的有一个技术申请，大致情况为一家三甲医院，采用Rac+Linux环境，启用了归档模式，但是由于日志增长过快，我们的技术人员虽然设置自动删除归档的任务，但是还是没有避免磁盘空间被占满，已经引起医院2次全院无法使用，虽然CQ公司也安排多名技术人员去现场处理，但是医院认为一直没有解决彻底，因此信息主管对此意见较大，希望公司安排技术支持部现场彻底解决该问题。

       通过申请描述，我大致了解到以下几个关键点：

       1.医院启用了归档，也做了定期自动删除归档日志的任务。

       2.由于归档日志增加过快，已经导致医院2号节点宕机。

       3.我们的技术人员去了几次，都未彻底解决，用户已经意见很大了。

       这只是个初步情况，往往只能了解问题的大概，具体的问题产生的原因还是得到用户那里去才能真正了解，于是立即出发，前往用户处处理问题。

现场分析问题

       到达医院，同系统管理员互相寒暄了几句，了解大体情况是医院昨天凌晨部分科室反映不能登录导航台，于是系统管理员深夜被叫到医院，查看服务器发现数据库已经宕机，检查磁盘空间，发现其中一个节点的剩余空间为0，于是立即删除部分过去的归档日志，重新启动服务器，下面科室才能够正常登录，谈话间 不断听见系统管理员抱怨深夜到医院是如何如何不情愿，看来意见是比较大。而且同样的问题不久前才出现过一次，只是当时是中午，未引起足够重视。询问同去的同事，了解到确实不久前也出现过一次同样的情况，当时认为是归档日志的定期删除保留的日志时间太长，保留的是30天的日志，后来改为保留5天的日志，心想不会再出现该问题，没想到日志增长这么快，5天时间的日志就把硬盘撑满了。

       接下来，该我们自己着手分析问题了，因为毕竟用户描述的只是他的主观判断，而真正要想了解到当时数据库发生的真实情况，我们还是应该自己检查下Oracle的日志才能确认，这也是我们处理问题必须遵守的原则，首先看下该节点的alter.ora在出现问题时间段的错误记录，部分记录情况如下：

Fri Jul 18 22:10:18 2010

Errors in file /u01/app/oracle/admin/orcl/bdump/orcl2_arc1_13762.trc:

ORA-19502: Message 19502 not found; No message file for product=RDBMS, facility=ORA; arguments: [/u01/app/oracle/archive/2_24046_698868487.dbf] [22529] [512]

ORA-27072: Message 27072 not found; No message file for product=RDBMS, facility=ORA

Linux-x86_64 Error: 9: Bad file descriptor

Additional information: 4

Additional information: 22529

Additional information: 507392

ORA-19502: Message 19502 not found; No message file for product=RDBMS, facility=ORA; arguments: [/u01/app/oracle/archive/2_24046_698868487.dbf] [22529] [512]

Fri Jul 18 22:10:18 2010

ARCH: Archival stopped, error occurred. Will continue retrying

Fri Jul 18 22:10:18 2010

ORACLE Instance orcl2 - Archival Error

       从日志记录的时间可以看出，真正出问题应该是在22点多钟，只是系统管理员凌晨才得到问题反馈，可以看出自己查看日志是多么的重要，不过从来错误的记录看，确实是由于无法归档，导致该节点出现问题，这个判断到是准确的。首先检查了下日志的增长速度，发现每个节点平均每1~3分钟就产生一个50M的归档日志，一天的归档日志就接近30G，而医院的日志放在本地磁盘，磁盘剩余空间也就100多G，按照这种日志的增长速度，空间被日志撑爆也就理所当然了。但是以该院的规模和业务量来看，产生这么多的日志肯定是不正常的，所以找到日志增长过快的原因，是解决问题的根本。

       首先观察下归档日志产生的频率，我们取当天24小时产生日志的频率数，如下图：

       发现除了在上午业务高峰期（8~9点），其他时间段没有明显的曲线变化，而且凌晨时分（0~7点）的日志也切换频繁，这就肯定有问题，于是我生成今天2点~3点的AWR报告进行分析，分析情况如下：

       首先看该时间段的会话不多，只有60多个会话，除去系统自带的几个会话，真正应用ZLHIS的会话肯定不多，证明当时医院的业务肯定不繁忙。

       但是每秒钟的处理事务却有23.82,比很多三甲医院业务高峰期的事务都要大，肯定有问题，进一步分析执行sql：

       发现即使在凌晨时分，居然也会如此频繁的执行大量的sql语句，其中涉及到update等DML语句，势必会产生大量归档日志，从表名看，应该是与体检系统有直接关系，通过分析，发现是zl_体检任务结果_Transation过程中的语句。 该过程是实现把体检病人的检验结果更新到体检系统里面，我们程序有2种方式进行更新：

       1.后台每天晚上定时对全院未完成体检的病人集中更新一次，通过调用zl_体检任务结果_TransationAll实现，其中zl_体检任务结果_TransationAll过程里面，又循环调用了zl_体检任务结果_Transation过程。

       2.是由操作人员在程序上操作，单独更新某一指定病人，只调用zl_体检任务结果_Transation过程。

       后一种情况肯定不会频繁执行该过程，目标锁定在第一种，后台作业方式，于是查看系统后台作业，发现问题作业，如下：

       该后台作业中该过程的执行频率被调整3分钟，通过对zl_体检任务结果_TransationAll过程分析我们知道，只要体检病人没有完成体检，都会对其检验结果进行更新，而该医院当时正好进行大量体检，有上千病人没有完成体检，每次执行该过程，都会对这些病人进行更新，可想而知肯定会产生大量日志，所以如此频繁的执行该过程，肯定是不现实的，定位了问题，接下来就该处理该问题。

现场处理问题

       询问相关人员，了解到由于该院体检科想实时得到体检病人的检验结果，所以我们的同事按医院的要求对作业执行频率进行了调整所致，说明了问题的严重性，经过和医院协商，阐述利弊，得到医院的同意，按医院要求最后把该后台作业修改为每天执行2次，中午一次，晚上一次。处理方法如下：

1.        删除原来的job

由于知道job号为107，所以调用dbms_job包删除

              exec dbms_job.remove(107);

2.        创建2个的job,一个是中午13点执行，一个晚上执行1点

------1点的job

variable job number;

begin
  sys.dbms_job.submit(job => :job,
                      what => 'zl_体检任务结果_TransationAll;',
                      next_date => to_date('20-07-2010 01:00:00', 'dd-mm-yyyy hh24:mi:ss'),
                      interval => 'trunc(Sysdate)+1+01/24+00/(24*60)+00/(24*60*60)');
  commit;
end;
/

------13点的job

variable job number;

begin
  sys.dbms_job.submit(job => :job,
                      what => 'zl_体检任务结果_TransationAll;',
                      next_date => to_date('20-07-2010 13:00:00', 'dd-mm-yyyy hh24:mi:ss'),
                      interval => 'trunc(Sysdate)+1+13/24+00/(24*60)+00/(24*60*60)');
  commit;
end;
/

3.        后续处理

       经过上面的处理，马上可以观察到2个节点的日志产生速度明显下降了，观察了1个小时，才产生了1个归档日志，由于是在下午时分，本身医院业务不是太忙，这种归档日志的产生速度应该是正常的。

       然后，再对每个节点的备份和归档日志的删除策略进行下检查，1，2号机都改为每天晚上12点定时删除30天前的归档日志，standby的机器由于空间比较大，调整为每天12点定时删除60天前的归档日志，最后要求医院近期观察下日志的生成速度，经过医院的确认，得到医院的认可。

（另：第二天，要求医院提供日志切换的次数统计，如下图，可以看到确实归档日志切换已经恢复正常，看到问题得到解决，医院的管理员也相当高兴。）

总结

       可以看出，本次问题的解决其实并不困难，但是我们前面去的技术人员都无法真正的处理，以致于认为是个高级技术问题，需要申请技术支持才能彻底解决，我们可以得到两点总结：

1.        在满足医院要求的情况下，调整ZLHIS原有设计时，没有充分考虑可能会带来的隐患。

       如本次案例中，为满足医院体检科想即时得到体检结果的要求，而手工修改提取体检结果job的间隔时间，表面上看是满足了医院的要求，但是其后带来的隐患却是比较大的，我们在处理这些事的时候，应该想想他的后续可能引起的问题，再做操作。

2.        解决问题时，没有从问题产生的根本去分析问题

       我们前面的同事在处理过程中，发现了是由于日志增长过快导致医院宕机，但是当时处理的方式是调整日志的删除计划，把删除30天的以前的归档日志，该为删除5天前的归档日志，当时看好像是解决了问题，但是问题的根本隐患并没有排除，我前面用了大量篇幅介绍了分析问题的过程，就是想说明分析问题的重要性。

       通过本次处理问题过程的描述，希望给以后有处理该类似问题的同事予以借鉴，一起共勉。