从一个奇怪的ADG同步延时的分析谈起

前两天一个金融客户的核心系统做了一次同城双中心的切换运行，把核心数据库从中心A切换到中心B运行，根据金融两地三中心的要求，这种切换基本上每半年进行一次。客户的同城数据中心是通过存储同步复制的方式建设的，在两个数据中心各部署了一套Oracle 11g rac环境，切换时直接关闭原数据中心的数据库和应用服务器，然后在新中心重新启动应用。因为半年前系统切换到了相对比较老的设备上运行，这回切回来之后，系统的性能应该更好，体现在服务器的CPU主频更高，存储的CACHE更大，SSD盘比例更大。

按理说系统切换到了更好的硬件上，跑的应该更稳定。13号切换后才几天，系统就出现了一次比较严重的ADG复制延时，原本延时接近于0的ADG系统，出现了一次超过1分钟的延时。这个客户采用读写分离的方式，ADG数据库为一些只读业务提供准实时的数据，延时超过1分钟，系统就会告警，延时超过5分钟，某些应用就可能需要暂停等待数据。为了避免ADG复制延时影响业务，客户就针对复制延时展开了分析。当时考虑到硬件环境只会更好，不会有问题，因此重点考虑到ADG服务器的位置问题。因为以前ADG服务器是和数据库服务器在同一数据中心的，这次切换后，ADG服务器和核心数据库服务器分别位于相隔十多公里的两个数据中心里。因此他们重点怀疑了网络问题。经过几天排查，网络上没有发现任何问题。这时候系统在11月22号和24号连续两次出现了延时较高的问题，特别是24号凌晨这次延时，已经接近了5分钟，他们手工执行了一次switch logfile才恢复正常。于是客户希望我们帮助分析一下ADG延时产生的原因。

首先和他们分析了一下数据中心切换是不是会对ADG复制延时产生如此大的影响，对于这种启用内部的城域网，是租用运营商OTN网络线路的，超过一分钟的延时，除非是网络带宽不足，延时达到互联网级别的延时，并且十分不稳定，才有可能出现。而从网络工程师分析的情况来看，这些问题都不存在。因此我建议他们首先排除掉网络的因素。对ADG延时影响比较大的因素主要是几个方面：1）网络带宽不足或者延时过大；2）REDO产生量过大，来不及恢复；3）没有启用实时恢复；4）没有启用并行恢复；5）恢复过程中遇到了HANG的情况；6）备机负载过高，CPU等资源不足。幸运的是客户安装了OSW，根据OSW的数据，基本上排除了资源不足，IO延时过大等因素。

客户给我打电话后就给我发了一个alert log上看到的报错信息，发现延时较大的时候日志出现过报错，同样在2天前的那次延时较大时也存在这个报错。

这实际上是一个具有很大误导性的报错，因为这是日志传输的报错。当PRIMARY的ARCH进程传输日志到STANDBY的时候，如果日志切换的比较快，ARCH发送给对端时对端还在处理前面的归档日志，那么就会拒绝。此时重新传输一遍一般就成功了。如果是孤立的，不是持续不断的报错，那么，基本上是可以忽略的。因为客户说他们启用了实时RECOVERY，那么RECOVERY使用STANDBY REDO LOG，正常情况下不需要使用归档日志进行恢复，只有STANDBY停止恢复了一段时间，部分日志信息在STANDBY REDO LOG中没有了才需要使用归档日志。不过从这个报错信息也可以看出，出问题时的归档频率应该是比较高的。

从数据库中也可以看出，从0:24-0:30这6分钟时间里，两个数据库实例产生了5次日志切换。不管怎么样，我们还是一点点去排除问题吧。首先我们要确认系统当前是否处于实时恢复状态。

上面的语句在主库上跑就可以确认备库的恢复状态。因为主库要根据备库的恢复状态来采取日志传输策略。

可以看出，备库确实是实时恢复状态，第一个疑问排除了。第二步就是确认LAG确实和客户说的那样，有时候客户会做出一些错误的描述，从而导致分析方向的错误，大家分析了半天，最后发现问题的描述不对，最后分析了个寂寞。在Oracle数据库中V$STANDBY_EVENT_HISTOGRAM记录了APPLY LAG相关的所有事件。

可以看出，LAG达到4分钟的现象确实是存在的，从0点28分到32分的时间里，LAG一下子就从一分钟增加到了4分钟了。这种情况下，我们首先就要怀疑这段时间的REDO产生量是不是异常了。这时候可能有朋友会想到做AWR，实际上AWR数据粒度还是太粗了。Oracle数据库分析此类问题的时候，可以使用metric。

SELECT * FROM DBA_HIST_SYSMETRIC_HISTORY

     WHERE metric_name=’Redo Generated Per Sec’ and BEGIN_TIME >=to_date(‘2021-11-24 00:23:00′,’yyyy-mm-dd hh24:mi:ss’)
     and END_TIME<=to_date(‘2021-11-24 00:3
5
:00′,’yyyy-mm-dd hh24:mi:ss’) ORDER BY snap_id,begin_time DESC;

这条命令就可以找出相关的时间段内日志产生量的详细信息。从下面的图上可以看出，这个时间段里REDO量确实很大，最高峰的时候应该超过17M每秒，而这里的统计数据都是按照1分钟平均值的。

从上述的分析中，我们倾向于REDO 产生量过大导致了ADG延时过大。这个问题客户也比较认可，下面要解决的一个问题就是灵魂拷问了。他们自己分析了一下日志产生量较高的时段，发现16号的数据也产生了较大量的REDO，但是16号并没有出现问题。

确实从数据上看，似乎16号的REDO产生量更大，最高都达到20M/秒了。不过这个数据看上去并不一定准确，因为REDO是持续产生的，只看高峰不一定准确，我们选取一些数据，计算一下平均REDO量，才能真正看出每个高峰期的REDO总量。

我们从这些天都选取高峰期的20分钟计算平均值，可以看出，24号和22号出现延时的两天，是REDO量最高的两天，其他的时间段，平均REDO量都没有这两天高。其中11/12号是系统切换前的REDO量，比现在要低得多。

既然是灵魂拷问，就免不了提出为什么切换到更好的系统中，反而延时更大了的问题。这个问题有时候比较难想明白。我不经意间听到用户说他们切换了数据中心后，系统肯定是更快了，晚上跑批以前要做近一个小时，现在不到半小时就完成了。如果真的是这样，那么在一个相对集中的时间段里，产生的REDO量就更集中了，ADG要RECOVER这些数据所需的时间就更长了。业务所需要的时间并不是这些跑批的数据，而是参杂在这些跑批数据中被写到redo log中，被传输到ADG上。因为recover的延时，就导致这些业务数据滞后了。这样可以比较明确的解释清楚切换后才出现延时过大的原因。至于说执行了一次SWITCH LOGFILE就恢复了，那正好是一个巧合，执行SWITCH LOGFILE的时候正好是跑批结束后，REDO量下降的时刻，不执行这条命令，延时也会变正常的。

找到问题后，下一步就是如何解决问题了。如果说是临时性的解决方案，那就是让跑批做的慢一点，比如两个人物之间增加几十秒到1分钟的延时，让REDO量产生的更为均衡一些。不过这个只是临时应急的方案。最根本的解决方案是如何提高ADG RECOVER的吞吐量。目前看连续20-30分钟的每秒5M+的REDO流量让ADG复制延时增加到了风险临界点，放慢跑批会让REDO量更均衡，但是随着企业业务的发展，有可能5M每秒的REDO量会成为常态，这时候该怎么办呢？

客户心里也有一个疑问，我这个配置下，难道每秒RECOVER的REDO量就不能超过4M吗？不产生大延时的REDO量的临界值是多少？我当前的RECOVERY相关参数是最优的吗？因此后续还有很多优化的工作要做。按照Oracle ADG REAL TIME APPLY最佳实践的建议。对于REDO产生量下延时问题的解决，首先要调整REDO LOG/STANDBY REDO LOG的大小，从而减少日志切换的频率。

按照上述表格的要求，客户的REDO LOG文件的大小目前还是偏小的，需要加大。同时并行recovery的并行度也是影响高峰期APPLY LAG的重要因素，这个并行度并不是越高越好，通过监控等待事件，可以找到这方面可能存在的问题，并加以优化，这些问题属于后续优化的问题了。