接着上次分享的关于数据库无法登录的原因http://blog.itpub.net/23718752/viewspace-1791089/ 其实最终还是因为在短期内生成了大量的redo,造成了频繁的日志切换，导致归档占用了大量的空间，最后无法登录，从这个层面来说，我们可以做一些工作来尽可能长时间的保留近期的归档，但是我们还可以换一个思路，那就是看看到底是什么操作生成了大量的redo,能不能试着减少redo的生成量。 一般来说，这个问题有点傻，日志肯定是记录尽可能完整的信息，这是做数据恢复的基础，我们还是不要过早下结论，先来分析一下再来做决定。 查看数据库的redo切换频率，在近几天内的redo切换频率极高，对于一个OLTP的系统来说是很非常高的负载，这种频繁的日志切换我也只在数据迁移的一些场景中碰到过。
但是奇怪的是查看数据库的DB time，却发现这个值其实并不高，看起来似乎有些矛盾，从这一点来看数据库内的数据变化频率其实并不是很高。
代码语言：javascript复制 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和IOsh
Top 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,然后查看归档的频率就可以比较出来。 把数据导入到另外一个测试环境中。 然后使用下面的语句进行频繁更新即可，先更新一百万次，中间可以随时中断。
代码语言：javascript复制function test_update
{
sqlplus test/test <<eof
update sync_id set max_id = 38 where sync_id_type = 'SYNC_LOG_ID';
commit;
EOF
}</eof
for i in {1..1000000}
do
test_update
done
在测试开始的时候
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
剩下的就是做进一步的确认和在正式环境部署了。
当然在清楚了冗余数据之后，创建索引的优势就没有那么大了。
