在查看一个客户11.2.0.2的AWR报告时,发现了这个问题。
在SQL ORDER
BY ELASPED TIME表中,前两项的结果如下:
Elapsed |
Executions |
%Total |
%CPU |
%IO |
SQL |
SQL |
SQL |
10,752.79 |
0 |
25.86 |
98.20 |
7.49 |
SQL*Plus |
BEGIN |
|
10,752.75 |
13 |
25.86 |
98.20 |
7.49 |
delete |
可以看到,这2两个语句在花费时间,占用CPU以及IO的百分比上惊人的一致,这绝对不是一个偶然的事件。
第一个SQL是收集表的统计信息,显然这是在SQLPLUS里面执行的操作,其执行次数是0,说明在采样时间内,这个操作还没有完成。根据Elspsed Time估算,这个SQL已经运行了3个小时。
而第二个SQL是在删除wri$_optstat_histhead_history表,从表名上看,应该和awr的历史统计信息有关,其执行次数是13次。一个合理的推断就是收集统计信息会导致wri$_optstat_histhead_history表的删除操作,而这个删除操作可能异常缓慢,从而引发了这个问题。
查询MOS,果然发现是一个bug:Bug 10279045 – Slow Statistics purging
(SYSAUX grows) [ID 10279045.8],导致问题的原因是在进行统计信息的PURGE操作时,删除wri$_optstat_histhead_history表产生了长时间的全表扫描操作。
确认影响的版本包括11.1.0.7、11.2.0.1和11.2.0.2,这个问题在11.2.0.3中被fixed。