从天而降的Trace文件--技术人生系列第三十五期-我和数据中心的故事

/oracle 文件系统（ $ORACLE_BASE 所在文件系统）满了，会导致 oracle 数据库不可用。那到底是什么文件占了大量的空间呢？我们简单的使用 du –sh 逐步看一下，发现 bdump 占用了大量空间，进到 bdump 目录 ls –l 查看，发现大量 trace 文件的大小似乎有些超乎寻常 ；

那么，这些 trace 文件是怎么产生的呢？难道是因为发生了什么报错导致的吗？

进一步查看 alert 日志，发现生成 trace 文件的时间段， alert 日志并没有看到明显的异常；

再看 trace 文件输出的内容 ：

从内 容上看，全部都是dump的buffer cache中的数据，所有的数据都是带有buffer_dirty的flag;那么这里是主动dump的dirty buffer呢还是因为所有的buffer 都是dirty的？其实想一想，这是10g的dataguard的备库（只应用redo 日志来修改数据块，不会有其他访问数据的请求），也就不难理解了。  

我们知道，这是一套 oracle dataguard 环境的物理备库，文件系统满了之后 MRP 进程也就终止了，还需要手工启动 MRP 进程 。

老 K 首先选择远程连接分析这个问题。但是由于问题已成历史，出问题的环境是 DATAGUARD 的备库环境，无法生成问题时段的 AWR 报告，客户也没有在操作系统层部署系统监控软件，对于这个问题，暂时没有太多的信息来帮助我们；

虽然根本原因暂时没法找出，临时性的解决方案我们还是可以先给出来的： altersystem set  max_dump_file_size ='4096M'；

通过限定 dump 的大小，避免出现单个 trace 文件过大导致的文件系统满的情况   。 进一步分析问题，老 K 暂时只能先对文件系统增加监控，当系统再次出现文件系统使用率快速增长时，可以通过实时监控分析，了解其 trace 产生的根本原因。

很快，客户再次联系到我们，系统再次产生大量 trace ，我们立即通过远程登录操作进行分析，终于看到了问题时刻系统的一系列状态；

首先，我们来看看这些并行进程都是怎么起来的？

如图所示，产生 trace 的这些并行进程（ pnnn ）的父进程都是 MRP 进程！

然后，从操作系统层面看，CPU和内存均显示正常，唯有IO层面似乎有些异常，可以看到 iostat –x 的输出结果显示如下 ：

这里可以看到 cciss/c0d1 盘正是数据库数据文件所在磁盘，其磁盘使用率达到了 100% ，表面看起来很繁忙，但是我们知道这个磁盘除了数据库（数据库软件和数据文件等）在使用外，并没有其他程序再使用；

嗯，看起来，这是个疑点：难道磁盘慢会导致 DATAGUARD 备库 mrp 的子进程出现异常？

先不管，继续看吧，看看还有什么其他信息可以尽快收集的，避免 trace 文件到达上限后出现新的异常。

OK ，下一步我们看看数据库这个时候性能有没有异常。作为 dataguard 的备库，虽然数据库不是 open 的，但是我们依然可以通过 v$ 性能视图来查看这些 pnnn 进程在做什么 ：

很明显 pxxx 进程似乎又不少进程在等待 free buffer waits ， 联想到 trace 文件中打印出来的正是 buffer cache 中的数据，不得不怀疑 pnnn 进程输出 trace 文件正是与这个问题有关；那么， pnnn 进程为什么会出现 free buffer waits 等待呢？这里出现这个等待的原因在哪呢 ？

看似完美的推断，其他部分都可以理解，关键点依然在第三点，当MRP的子进程（Pnnn）出现等待free buffer waits时，它真的就会开始写trace吗？写多少内容呢？

于是，老K开始了MOS搜索，并未找到相关答案，很失望。。。。。。

问题分析到这一步，如果是你，你接下来会怎么做呢？停下来，想一想？

对于一个未知问题，在应急处理的过程中我们可以充分利用自己的猜测、推断能力；然而，在问题的根因分析阶段，我们就需要逐步查证、验证我们的猜测和推断；对于上面的推断，我们没有找到对应的官方说法，但是我们完全可以通过不同的环境重现问题来进行验证 。

我们的目的是验证 MRP 子进程出现了 free buffer waits 等待时，会不会生成 dump buffer cache 的 trace 文件。至于 free buffer waits 产生的原因，我们在测试环境并不关心，因此我们把 db_cache_size 设置为一个很小的值，主库生产大量的日志，备库启动 RMP 进程，开始应用日志，很容易就产生 free buffer waits 等待 。

通过测试验证了之前的推断是合理的，那么我们需要再次给出解决方案时就更从容了；

首先，对于 MRP 子进程等待 “free buffer waits” 就写 trace 这一问题各方面并没有具体的规避方案，我们可以继续沿用前期的方案，设置 max_dump_file_size 限制其大小是不错的选择；

其次，为什么会有free buffer waits的等待而且出现超时呢，说白了还是IO缓慢造成的， 系统磁盘的 IO 缓慢，并且多个 MRP 子进程等待 free buffer waits 超时后，会同时写 trace 文件，进一步加大了磁盘的 IO 压力，最后恶性循环。我们再回头来重新看磁盘的 IO 性能信息 ：

磁盘的服务时间（ svctm ）约 1.4 毫秒， IO 的响应时间却达到了 644 毫秒（ await ）， r/s+w/s （也就是 IOPS ）为将近 700 ，而平均请求队列的长度 avgqu-sz 达到了（ 529 ）；磁盘的使用率到达100% ！跟客户进行沟通，希望调整存储的分配，然而，客户环境限制，无法及时对此进行进一步的调整；

秉着负责任的态度，我们还需要在此基础上进一步优化调整，那么我们这里能做什么呢？看看系统的异步 IO 使用情况 ：

可以看到，系统并没没有使用异步 IO ；

数据库中的 filesystemio_options 参数设置为 none ，看来 oracle 中也没有配置异步 IO ，这里可以将数据库中的 filesystemio_options 参数调整为 ASYNCH ；   

大家跟上思路继续想！为什么会有那么大的 IO 请求呢？我们是不是可以将 IO 请求量进一步减小呢？

前面提到，数据库的所有文件都放在 /oracle 文件系统中，虽然这只是 dataguard 备库，但是当 RFS/MRP 、 ARC 、 DBW 同时工作的时候，对于磁盘的 IO 请求量还是挺多的；再出现 MRP多个 子进程等待 free buffer waits 超时开始写 trace 文件，系统的 IO 压力更是不言而喻；这里减小总 IO 请求量并不容易，但是我们可以做的是将各种文件分离到不同的磁盘上，减少单个磁盘的 IO 请求 ；

注：其中在上述建议1、2实施后，客户系统未再发生p***进程大量写trace的情况；