insert导致的性能问题大排查(r11笔记第26天)

今天开发的同学小窗口消息给我,向我咨询一个ORA错误的问题。

错误代码是ORA-30036,使用oerr ora 30036查看,由于是undo空间无法扩展导致。

这是一个统计业务的数据库,而且平时的负载其实并不高,确实有一些奇怪。首先排除了大事务导致的原因,查看数据库日志,和开发同学沟通,没有发现相关的错误信息。

所以第一感觉这是一个偶然发生的情况,不过开发的这位同学貌似碰到了问题,他说从应用端抛出了ORA-30036的错误。

java.sql.BatchUpdateException:ORA-30036: unable to extend segment by 8 in undo tablespace 'UNDOTBS1'?
问题刚刚发生,问题确凿,说明插入数据出了问题。但是比较奇怪的是,我在环境中简单模拟了一下,却没有碰到这类问题。把数据量提升到百万还是可以成功。

和开发的同学做了确认,他发过来了执行失败的语句,这是一个看起来很简单的语句,当然我做了简单的脱敏。

insert into user_hh_max(id, stat_time, appkey) select seq_user_hh.nextval id, :1 stat_time, :2 appkey from dual;

 这样一个看似非常简答的INSERT看起来无论如何也不会导致很严重的性能问题,这一点我是深信不疑。除了序列的自增外,其它的地方我是真没看出来有什么性能隐患。

带着疑问,我看了下最近的数据库负载,都在正常的范围之内。查看归档的切换频率,发现问题看起来不是那么简单。

下面的图示,横轴是小时,纵轴是日期,这样就能够看到每个小时的归档切换情况,发现近些天来归档的切换频率比以前有了极大的提高。简单来说,以前基本上是一个小时2~3G的归档量,现在一下子变成了20~30G,而且还有增加的趋势。

insert导致的性能问题大排查(r11笔记第26天)
得到了这样一个报告,让我对原本看起来不痛不痒的问题变得严峻起来,而且应用端确实有些统计出现了问题,希望我帮忙能先修复一下,这种情况下,我先扩容了Undo空间,然后静下心来分析这个奇怪的问题。

带着疑问我得到了一个AWR报告。

查看profile的部分,信息如下:


每秒
每个事务 每次调用
DB Time(s): 1.3 0.1 0.00
DB CPU(s): 1.1 0.1 0.00
Redo size: 8,826,942.0 730,730.2
Logical reads: 77,599.7 6,424.0
Block changes: 56,339.2 4,664.0
Physical reads: 33.6 2.8
Physical writes: 564.9 46.8
User calls: 1,686.8 139.6
Parses: 1.5 0.1
Hard parses: 0.4 0.0
W/A MB processed: 0.7 0.1
Logons: 0.0 0.0
Executes: 1,891.1

Rollbacks: 0.0 0.0
Transactions: 12.1

通过这部分内容,可以很明确看到每秒钟产生了8M左右的redo,在我的经历中,这是一个很频繁的数据变化,但是查看TPS不高,逻辑读很高。所以我的精力就马上集中在了SQL部分,看看有哪些DML的操作会导致如此高的消耗。

查看SQL部分的报告,得到了下面的一个表格。

insert导致的性能问题大排查(r11笔记第26天)
这里的insert执行了500多万次,听起来其实也不高。我就在想单单是500万的insert肯定不会造成每小时20~30G的日志量。那么还有什么地方会导致问题呢。看着下面的语句,有一些update还有一连串的merge语句,自己还一度怀疑是否又是merge导致的性能问题,但是根据数据来分析,影响实在是太小了。

所以面对这样一种情况就很纠结,问题发生但是又很难定位出问题来。

我耐着性子又看了看报告。发现了这样一小段内容。

这部分内容就很奇怪了,完全不大符合逻辑,insert执行了500多万次,但是影响的行数是4000多万行。

insert导致的性能问题大排查(r11笔记第26天)
查看其它的指标也没有找到明显性能问题。

这个问题该怎么继续往下查呢。

我想到了一种方法,既然产生了如此多的归档,那就看看到底redo里面是些什么内容不就一目了然了。使用了多少commit都能看得清清楚楚。

关于Logminer提取redo日志的信息,可以参考

Oracle闪回原理-Logminer解读redo(r11笔记第17天)

使用里面提供的两个脚本,很快就读出了redo的内容,正是insert语句。

我看到了大量的insert,但简单统计insert的数目,看起来这个量级和AWR报告中严重不符。

我查看了这个表的数据量,不到100万,而且对应的数据块也没有爆发式增长,这个现象真是奇怪。

此时我陷入了深思,这个问题该怎么解释,是AWR报告的bug吗?

因为这个表的数据量不大,我做了如下的测试,写了一个脚本,每隔2秒钟统计一下这个表的数据量,然后几分钟后,拿着得到的数据,得到了下面的一张图。

如下是这张表的数据量变化图,可以看到基本上是在1分钟内,会插入100万数据,然后马上清理掉,继续插入,如此反反复复。

insert导致的性能问题大排查(r11笔记第26天)

毫无疑问,这个逻辑如此看来是有明显的问题的,经过反复确认,让开发的同学去看看这个逻辑的实现,是否哪里出了问题,很快就得到了反馈,他们发现了问题根源,及时从逻辑上做了调整。

从下面归档的切换情况可以看出问题有了立竿见影的效果。

insert导致的性能问题大排查(r11笔记第26天)
所以由此一来,AWR的显示的数据有些地方就能够理解了。当然你也可以认为是报告的数据误导在先。


上一篇:消息中间件—RocketMQ的RPC通信(一)


下一篇:常用性能监控指南