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,而且还有增加的趋势。

得到了这样一个报告，让我对原本看起来不痛不痒的问题变得严峻起来，而且应用端确实有些统计出现了问题，希望我帮忙能先修复一下，这种情况下，我先扩容了Undo空间，然后静下心来分析这个奇怪的问题。

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

查看profile的部分，信息如下：

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

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

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

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

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

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

查看其它的指标也没有找到明显性能问题。

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

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

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

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

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

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

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

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

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

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

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

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

所以由此一来，AWR的显示的数据有些地方就能够理解了。当然你也可以认为是报告的数据误导在先。