大量redo生成的问题原因及改进(r6笔记第50天)

接着上次分享的关于数据库无法登录的原因http://blog.itpub.net/23718752/viewspace-1791089/ 其实最终还是因为在短期内生成了大量的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和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,然后查看归档的频率就可以比较出来。 把数据导入到另外一个测试环境中。 然后使用下面的语句进行频繁更新即可,先更新一百万次,中间可以随时中断。

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
剩下的就是做进一步的确认和在正式环境部署了。
当然在清楚了冗余数据之后,创建索引的优势就没有那么大了。

原文发布于微信公众号 - 杨建荣的学习笔记(jianrong-notes)

原文发表时间:2015-09-05

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏python全栈布道师

python项目简单实现自定义配置覆盖默认配置

47790
来自专栏杨建荣的学习笔记

由报警邮件分析发现的备库oracle bug(r7笔记第12天)

昨天到公司之后,收到两份封报警邮件,可以看到在早晨6:30左右主库的v$dataguard_status检查时发现了一个错误。然后再2分钟后就自动恢复了。 一般...

27160
来自专栏杨建荣的学习笔记

dg broker校验失败的一个奇怪问题(二) (r8笔记第51天)

对昨天提出的问题做了一个简单的分析和排查,也算是有了一个交代,上一篇文章在 dg broker校验失败的一个奇怪问题 我查看了最近的日志,发现在半个月以前有一...

36250
来自专栏码农二狗

php持久化连接数据库

21830
来自专栏乐沙弥的世界

MySQL 自动故障转移工具--mysqlfailover

38060
来自专栏SpringBoot 核心技术

第三十二章:如何获取SpringBoot项目的applicationContext对象

288110
来自专栏一个会写诗的程序员的博客

《Spring Boot极简教程》第8章 Spring Boot集成Groovy,Grails开发第8章 Spring Boot集成Groovy,Grails开发小结参考资料

本章介绍Spring Boot集成Groovy,Grails开发。我们将开发一个极简版的pms(项目管理系统)。

18920
来自专栏pangguoming

简单的Hibernate入门简介

其实Hibernate本身是个独立的框架,它不需要任何web server或application server的支持。然而,大多数的Hibernate入门介绍...

37190
来自专栏沃趣科技

ASM 翻译系列第三十八弹:ASM数据清理

原作者:Bane Radulovic 译者: 魏兴华 审核: 魏兴华 DBGeeK社区联合出品 原文链接:http://asmsupportguy....

287100
来自专栏杨建荣的学习笔记

memory_target设置不当导致数据库无法启动的问题(r3笔记第38天)

今天在做一个问题排查的时候碰到了另外一个有些“奇怪的”问题。 我们在测试库中已经禁用了SGA自动存储管理,结果在spfile文件里丢掉了shared_pool_...

36760

扫码关注云+社区

领取腾讯云代金券