大量redo生成的问题原因及改进

接着上次分享的关于数据库无法登录的原因 http://www.linuxidc.com/Linux/2015-09/122728.htm
其实最终还是因为在短期内生成了大量的redo,造成了频繁的日志切换，导致归档占用了大量的空间，最后无法登录，从这个层面来说，我们可以做一些工作来尽可能长时间的保留近期的归档，但是我们还可以换一个思路，那就是看看到底是什么操作生成了大量的redo,能不能试着减少redo的生成量。
一般来说，这个问题有点傻，日志肯定是记录尽可能完整的信息，这是做数据恢复的基础，我们还是不要过早下结论，先来分析一下再来做决定。
查看数据库的redo切换频率，在近几天内的redo切换频率极高，对于一个OLTP的系统来说是很非常高的负载，这种频繁的日志切换我也只在数据迁移的一些场景中碰到过。但是奇怪的是查看数据库的DB time，却发现这个值其实并不高，看起来似乎有些矛盾，从这一点来看数据库内的数据变化频率其实并不是很高。
BEGIN_SNAP END_SNAP SNAPDATE DURATION_MINS DBTIME
---------- ---------- ----------------------- ----------
82560 82561 05 Sep 2015 00:00 30 26
82561 82562 05 Sep 2015 00:30 30 26
82562 82563 05 Sep 2015 01:00 29 29
82563 82564 05 Sep 2015 01:30 30 27
82564 82565 05 Sep 2015 02:00 30 23
82565 82566 05 Sep 2015 02:30 30 23
82566 82567 05 Sep 2015 03:00 30 20
82567 82568 05 Sep 2015 03:30 30 22
82568 82569 05 Sep 2015 04:00 30 20
82569 82570 05 Sep 2015 04:30 30 25
82570 82571 05 Sep 2015 05:00 30 23
82571 82572 05 Sep 2015 05:30 30 27
82572 82573 05 Sep 2015 06:00 30 40
82573 82574 05 Sep 2015 06:30 30 26
82574 82575 05 Sep 2015 07:00 30 28
82575 82576 05 Sep 2015 07:30 30 34
82576 82577 05 Sep 2015 08:00 29 40
82577 82578 05 Sep 2015 08:30 30 37
82578 82579 05 Sep 2015 09:00 30 40
82579 82580 05 Sep 2015 09:30 30 38
82580 82581 05 Sep 2015 10:00 30 41
82581 82582 05 Sep 2015 10:30 30 40
82582 82583 05 Sep 2015 11:00 30 37
82583 82584 05 Sep 2015 11:30 30 39
82584 82585 05 Sep 2015 12:00 30 41
82585 82586 05 Sep 2015 12:30 30 34
82586 82587 05 Sep 2015 13:00 30 53
82587 82588 05 Sep 2015 13:30 30 82
82588 82589 05 Sep 2015 14:00 30 74
82589 82590 05 Sep 2015 14:30 30 45对于这种情况，我们还是抓取一个awr报告来看看。
在awr报告中，可以看到瓶颈还是主要在DB CPU和IOshTop 5 Timed Foreground Events

Event	Waits	Time（s）	Avg wait （ms）	% DB time	Wait Class
DB CPU		2,184		68.89
db file parallel read	6,096	413	68	13.02	User I/O
log file sync	65,199	363	6	11.47	Commit
db file sequential read	46,038	172	4	5.43	User I/O
direct path read	415,685	46	0	1.47	User I/O

查看时间模型，可以看到DB CPU和sql相关的影响各占了主要的比例。
看到这，自己还是有些犯嘀咕，柑橘这个问题还是有些奇怪，能够关注的一个重点就是sql语句了，但是top 1的sql语句还是有些奇怪。

Elapsed Time （s）	Executions	Elapsed Time per Exec （s）	%Total	%CPU	%IO	SQL Id	SQL Module	SQL Text
931.73	14,409	0.06	29.39	99.77	0.00	c95g9rc1hw48j	JDBC Thin Client	update sync_id set ma...

这条语句执行频率极高，语句也很简单，但是CPU消耗却很高，初步怀疑是走了全表扫描。
语句如下：
update sync_id set max_id = :1 where sync_id_type = :2
简单查看执行计划，发现确实是走了全表扫描，如果碰到这个问题，第一感觉是需要走索引，没有索引可以建个索引，但是当我看到sql by Executions这个部分时，自己感觉到问题其实不是那么简单。
可以看到第2个语句其实就是刚刚提到的top 1的sql，对应的指标还是很不寻常的，一次执行处理的行数近5000度行，执行了1万多次，处理的数据行数近8千万。

Executions	Rows Processed	Rows per Exec	Elapsed Time （s）	%CPU	%IO	SQL Id	SQL Module	SQL Text
14,684	14,684	1.00	3.39	94.7	.7	98kzt71wqz5qg	JDBC Thin Client	update sus_log set failed_c...
14,409	78,329,332	5,436.14	931.73	99.8	0	c95g9rc1hw48j	JDBC Thin Client	update sync_id set ma...

但是查看这个表，发现数据其实就1万多条，所以这是一个明显的问题。
我们来进一步分析一下，一个小表1万多的数据，每次更新能够更新5000多行，可以断定数据的分布式是不均匀的。因为这个表结构非常简单，就两个字段，所以分析问题还是很好定位的。
简单查看了一下数据情况，发现数据主要分布在两个type列值上，基本上占用了99.99%以上的数据
SQL> select max_id,count（*）from SYNC_ID where SYNC_ID_TYPE="SYNC_LOG_ID" group by max_id;
MAX_ID COUNT（*）
---------- ----------
38 5558
SQL> select max_id,count（*）from SYNC_ID where SYNC_ID_TYPE=SYNC_TEST2_LOG_ID" group by max_id;
MAX_ID COUNT（*）
---------- ----------
108 5577
从数据的分布情况可以看到，其实表中存在了大量的冗余数据，而且表中没有索引字段和其它约束，在每次更新的时候本来更新一个字段值，结果会修改5000多行数据的值，如果执行频繁，短时间内就会频繁生成大量的redo,从目前的sql运行情况来看，这条语句应该是造成redo频繁切换的主要原因了。
但是这个环境还是需要做一些确认和沟通之后才能够变更的，目前的也只是建议，我们在这个基础上还是可以简单地测试一下的。
测试的思路其实很简单，就是把这个表里的数据给导出来，放到其它测试环境中，做频繁的update，然后查看归档的频率即可。
然后删除冗余的数据，再做频繁的update,然后查看归档的频率就可以比较出来。
把数据导入到另外一个测试环境中。
然后使用下面的语句进行频繁更新即可，先更新一百万次，中间可以随时中断。function test_update
{
sqlplus test/test < update sync_id set max_id = 38 where sync_id_type = "SYNC_LOG_ID";
commit;
EOF
}for i in {1..1000000}
do
test_updatedone在测试开始的时候
Redo Switch times per hour 2015-Sep-05 16:02:55
MON DA 00 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 16 17 18 19 20 21 22 23
--- -- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
09 05 0 0 0 0 0 0 0 1 0 0 1 0 0 0 0 1 0 0 0 0 0 0 0 0
运行了不到3分钟，日志切换就达到了14次，还是很能够说明问题的。
Redo Switch times per hour 2015-Sep-05 16:05:20
MON DA 00 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 16 17 18 19 20 21 22 23
--- -- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
09 05 0 0 0 0 0 0 0 1 0 0 1 0 0 0 0 2 14 0 0 0 0 0 0 0然后我们使用update的方式来验证一下。
Redo Switch times per hour 2015-Sep-05 16:08:04
MON DA 00 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 16 17 18 19 20 21 22 23
--- -- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
09 05 0 0 0 0 0 0 0 1 0 0 1 0 0 0 0 2 14 0 0 0 0 0 0 0
又过了4分钟，日志一次都没有切换，这就足以说明了我们的推论是正确的。
Redo Switch times per hour 2015-Sep-05 16:12:47
MON DA 00 01 02 03 04 05 06 07 08 09 10 11 12 13 14 15 16 17 18 19 20 21 22 23
--- -- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
09 05 0 0 0 0 0 0 0 1 0 0 1 0 0 0 0 2 14 0 0 0 0 0 0 0
剩下的就是做进一步的确认和在正式环境部署了。
当然在清楚了冗余数据之后，创建索引的优势就没有那么大了。更多Oracle相关信息见Oracle 专题页面 http://www.linuxidc.com/topicnews.aspx？tid=12本文永久更新链接地址