ORACLE RAC环境REDO日志量突然增加的分析
服务概述
CRM系统在7/11日出现REDO日志产生量突增，达到平时产生量的20倍以上，对数据同步已经造成了较大的影响。工程师接到故障申报后，及时进行响应，通过对相关日志等信息的深入分析，整理汇总此文档。
二、数据库REDO产生量突境问题分析
-
- 数据库运行状态检查
-
STATUS INSTANCE_NAME START_TIME
------------ ---------------- --------------------
OPEN crm1 2019/06/02 15:07:43
OPEN crm2 2019/03/08 16:34:47
SQL>
OPEN_MODE NAME DB_UNIQUE_NA FOR LOG_MODE DATABASE_ROLE DBID LANG CURRT_TIME
-------------------- --------- ------------ --- ------------ ---------------- ---------- -------------------------- --------------------
READ WRITE CRM crm YES ARCHIVELOG PRIMARY 3793602241 AMERICAN_AMERICA.ZHS16GBK 2019/07/11 21:34:10
-
- 数据库redo log配置
STATUS GROUP# MEMBER MB SEQUENCE# THREAD#
---------------- ---------- ------------------------------------------------------------ ---------- ---------- ----------
INACTIVE 1 +REDO/crm/onlinelog/group_1.275.985305107 2048 10388 1
INACTIVE 2 +REDO/crm/onlinelog/group_2.274.985305095 2048 10389 1
INACTIVE 3 +REDO/crm/onlinelog/group_3.273.985305083 2048 10390 1
INACTIVE 4 +REDO/crm/onlinelog/group_4.272.985305069 2048 10391 1
INACTIVE 5 +REDO/crm/onlinelog/group_5.256.985304057 2048 10385 1
INACTIVE 6 +REDO/crm/onlinelog/group_6.257.985304079 2048 10386 1
CURRENT 7 +REDO/crm/onlinelog/group_7.268.985304723 2048 10394 1
INACTIVE 8 +REDO/crm/onlinelog/group_8.269.985304815 2048 10387 1
INACTIVE 9 +REDO/crm/onlinelog/group_9.270.985304847 2048 10392 1
INACTIVE 10 +REDO/crm/onlinelog/group_10.271.985304917 2048 10393 1
INACTIVE 21 +REDO/crm/onlinelog/group_21.258.985304107 2048 9390 2
INACTIVE 22 +REDO/crm/onlinelog/group_22.260.985304293 2048 9391 2
CURRENT 23 +REDO/crm/onlinelog/group_23.259.985304475 2048 9392 2
INACTIVE 24 +REDO/crm/onlinelog/group_24.261.985304165 2048 9383 2
INACTIVE 25 +REDO/crm/onlinelog/group_25.262.985304493 2048 9384 2
INACTIVE 26 +REDO/crm/onlinelog/group_26.263.985304511 2048 9385 2
INACTIVE 27 +REDO/crm/onlinelog/group_27.264.985304525 2048 9386 2
INACTIVE 28 +REDO/crm/onlinelog/group_28.265.985304549 2048 9387 2
INACTIVE 29 +REDO/crm/onlinelog/group_29.266.985304607 2048 9388 2
INACTIVE 30 +REDO/crm/onlinelog/group_30.267.985304619 2048 9389 2
20 rows selected.
-
- 数据库REDO产生量及切换频率信息
分析最近三天的REDO日志切换频率，可以发现7/11日上午10点-13点时REDO切换频率最高
Date THREAD Archives_in_last_3_days/hour
-------------------- ---------- ----------------------------
2019/07/09:00 1 2
2019/07/09:00 2 2
2019/07/09:04 2 1
2019/07/09:08 1 1
2019/07/09:08 2 3
2019/07/09:09 1 1
2019/07/09:09 2 3
2019/07/09:10 1 2
2019/07/09:10 2 3
2019/07/09:11 1 1
2019/07/09:11 2 4
2019/07/09:12 1 3
2019/07/09:12 2 4
2019/07/09:13 1 1
2019/07/09:13 2 2
2019/07/09:14 1 1
2019/07/09:14 2 2
2019/07/09:15 1 2
2019/07/09:15 2 4
2019/07/09:16 1 1
2019/07/09:16 2 2
2019/07/09:17 1 1
2019/07/09:17 2 1
2019/07/09:19 2 1
2019/07/09:20 1 1
2019/07/09:20 2 2
2019/07/09:21 2 1
2019/07/09:22 1 2
2019/07/09:22 2 3
2019/07/09:23 2 2
2019/07/10:00 1 1
2019/07/10:00 2 1
2019/07/10:01 1 2
2019/07/10:01 2 2
2019/07/10:03 2 1
2019/07/10:05 1 1
2019/07/10:05 2 1
2019/07/10:08 1 1
2019/07/10:08 2 3
2019/07/10:09 1 2
2019/07/10:09 2 4
2019/07/10:10 1 1
2019/07/10:10 2 3
2019/07/10:11 1 1
2019/07/10:11 2 3
2019/07/10:12 1 3
2019/07/10:12 2 4
2019/07/10:13 2 1
2019/07/10:14 1 2
2019/07/10:14 2 3
2019/07/10:15 1 1
2019/07/10:15 2 3
2019/07/10:16 1 1
2019/07/10:16 2 2
2019/07/10:17 2 1
2019/07/10:18 2 1
2019/07/10:19 1 1
2019/07/10:20 2 2
2019/07/10:21 1 1
2019/07/10:21 2 1
2019/07/10:22 2 2
2019/07/10:23 1 1
2019/07/10:23 2 1
2019/07/11:00 1 1
2019/07/11:01 2 1
2019/07/11:08 1 1
2019/07/11:08 2 3
2019/07/11:09 1 2
2019/07/11:09 2 4
2019/07/11:10 1 14
2019/07/11:10 2 7
2019/07/11:11 1 61
2019/07/11:11 2 20
2019/07/11:12 1 53
2019/07/11:12 2 18
2019/07/11:13 1 23
2019/07/11:13 2 8
2019/07/11:14 1 8
2019/07/11:14 2 4
2019/07/11:15 1 4
2019/07/11:15 2 3
2019/07/11:16 1 10
2019/07/11:16 2 4
2019/07/11:17 1 13
2019/07/11:17 2 5
2019/07/11:18 1 9
2019/07/11:18 2 3
2019/07/11:19 1 9
2019/07/11:19 2 3
2019/07/11:20 1 12
2019/07/11:20 2 4
2019/07/11:21 1 3
-
- 数据库AWR报告分析
1.7/11日 10-13点数据
2.7/11日 13-18点数据
3.7/10日11-13点与7/11日 11-13点数据对
三、总结与后续处理建议
3.1 问题总结
问题排查思路：
1.找出REDO产生量大的时间段
首先查询出数据库每小时的REDO产生量，根据最近三天的REDO产生量的统计值可以发现11-13点产生量最大。
2.查找产生REDO量大的SQL或表
首先明确数据库的REDO在数据发生变化时会对应产生，可以简单认为是表中数据段有写入动作(SQL的增删改对应的数据变化都需要通过对表中数据段的写入来实现)；查询不会产生REDO。因此着重排查涉及增删改的SQL语句及写入量排在前面的表。
3.问题排查过程
通过查询10-13点数据库数据变动量最大的表（通过写入量来判断，写入即对应数据的变更，变更会产生REDO LOG，查询不会产生REDO LOG）；
同时通过对比正常时段(2019/7/10 11-13点)与问题时段(2019/7/11 11-13点)的数据库AWR性能报告,通过对比数据写入量及相应的数据写入量大的表信息，可以与问题时段10-13点查出的变化量最大的表进行互相验证。
SQL部分的查询未有发现，原因可能是SQL执行速度较快并且未使用绑定变量，这种情况下AWR报告是获取的相同SQL的汇总数据排序靠前的，单个SQL执行快是抓不到的。
4.排查结果
通过上述排查思路和排查方法有如下信息：
用查询出的REDO产生量最大的时段11-13点为例：两张表TZBOSS.BP_ACC_BILLITEM_DTL TZBOSS.CS_PROD_SUBSCRIPTION_HIS的数据写入占整个数据库在此期间写入量的62.5%。
从2019/7/10 11-13点与2019/7/11 11-13点的数据库AWR性能报告对比来看，2019/7/10 11-13点没有发现对这两张表的写入。
7/11日 13-18点数据来看REDO产生量已经减少，此时从只有表TZBOSS.BP_ACC_BILLITEM_DTL的写入较大，占总的25%。
3.2 后续处理建议
建议与应用程序开发部门沟通两张表TZBOSS.BP_ACC_BILLITEM_DTL TZBOSS.CS_PROD_SUBSCRIPTION_HIS.涉及的业务逻辑是否发生了相应变化或新增。