今天开发的同学小窗口消息给我,向我咨询一个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的部分,信息如下:
每秒 | 每个事务 | 每次调用 | |
---|---|---|---|
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执行了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的显示的数据有些地方就能够理解了。当然你也可以认为是报告的数据误导在先。