Oracle系统SQL消耗大量资源(bsa0wjtftg3uw)

宗9706

Oracle系统SQL消耗大量资源(bsa0wjtftg3uw)
top sql第一条是select file# from file$ where ts#=:1
现象：
客户反馈AWR中TOPSQL第一条为系统SQL：select file# from file$ where ts#=:1。
客户的系统是比较繁忙的系统，该AWR报告取样自业务高峰期。
WORKLOAD REPOSITORY report for
DB Name DB Id Instance Inst num Release RAC Host
EDI 2695423743 EDI 1 10.2.0.2.0 NO dssdb01

Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 32286 20-May-13 07:49:14 205 65.8
End Snap: 32287 20-May-13 08:54:47 210 72.1
Elapsed: 65.55 (mins)
DB Time: 1,375.64 (mins)

Top 5 Timed Events

Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class
PX Deq Credit: send blkd 215,620 24,567 114 29.8 Other
CPU time 14,962 18.1
enq: CF - contention 147,525 10,324 70 12.5 Other
db file sequential read 1,472,843 7,988 5 9.7 User I/O
log file sync 119,120 7,308 61 8.9 Commit

SQL ordered by Gets

Buffer Gets Executions Gets per Exec %Total CPU Time (s) Elapsed Time (s) SQL Id SQL Module SQL Text
123,784,076 143,834 860.60 33.58 988.01 1023.40 bsa0wjtftg3uw select file# from file$ where ... <<<<<<<<<<<<<<<< Here!

bsa0wjtftg3uw ==> select file# from file$ where ts#=:1
该SQL在一个小时时间内执行了1023秒。

分析：
在metalink上发现有几个相关的BUG，但版本对应不上，不过根据BUG的说明信息我们可以窥得Oracle处理文件方面的一些内部机制。
1.Bug 14309390 - High CPU usage / Mutex Contention with Recursive statement on FILE$ (Doc ID 14309390.8)
Range: Versions >= 11.2 but BELOW 12.1
Recursive statement SQLID bsa0wjtftg3uw 'select file# from file$ where ts#=:1'
which is executed during tablespace operations can cause a high mutex contention / high CPU usage

2.Bug 13520452 - Recursive statement on FILE$ causes a huge workload - superseded (Doc ID 13520452.8)
Recursive statement 'select file# from file$ where ts#=:1' which is executed
inside the tbsfnl() function can cause high workload.

Rediscovery Notes:
High workload due to 'select file# from file$ where ts#=:1'
The select shows a FULL scan of FILE$

3.Bug 13520452 : RECURSIVE STATEMENT ON FILE$ CAUSES A HUGE WORKLOAD

INTERNAL PROBLEM DESCRIPTION:
@The statement 'select file# from file$ where ts#=:1' is executed inside tbsfnl
@ function while performing tablespace alter operations, to fetch the file info
@rmation corresponding to the tablespace. tbsfnl is also called while adding ex
@tent where we choose the best file to allocate space for extent, once per each
@ extent allocation. As the number of files inside tablespace increase, executi
@on of the above statement may impact performance.
<===这段说明了该SQL一般在tbsfnl函数中被执行（执行alter tablespace操作时），在为段分配extent时也会执行以选择适合的文件创建extent
@INTERNAL FIX DESCRIPTION:
@File information per tablespace is maintained by Recovery(rcv) layer in SGA. W
@e are fetching file list per tablespace using the cached information.
<===在11.2.0.3，Oracle提供patch包修复这个BUG，修复之后不需要再执行SQL bsa0wjtftg3uw，而是将数据文件信息直接缓存起来，通过直接查看缓存信息获取数据文件信息，此举避免了上述系统SQL的大量执行。

REDISCOVERY INFORMATION:
High workload due to 'select file# from file$ where ts#=:1'


Q:Which program generated below recursive statements and takes lots of buffer gets?
bsa0wjtftg3uw ==> select file# from file$ where ts#=:1

A:
'bsa0wjtftg3uw' is an oracle internal recursive SQL, which is executed during tablespace operations.

The statement 'select file# from file$ where ts#=:1' is executed inside tbsfnl function while performing tablespace alter operations, to fetch the file information corresponding to the tablespace. tbsfnl is also called while adding extent where we choose thebest file to allocate space for extent, once per each extent allocation. As the number of files inside tablespace increase, execution of the above statement may impact performance.
Disable autoexetend can do some help to reduce the SQL, but operation like creating table also need to query the tablespace information.
现在我们大致了解了这条系统SQL产生的几个原因，排除了BUG因素，我们需要检查：
1.alert日志，对应时间段是否有alter tablespace操作，例如add datafile。 <== NO
2.查看AWR，是否存在许多insert，造成需要扩充段空间（add extent）。 <== yes
3.检查是否有数据文件为autoextend。 <== no

TOPSQL中确实有几条INSERT，并且据客户介绍这个系统是OLAP系统，在繁忙时间段有很多抽数操作，需要将其他系统的数据抽进来，插入到数据库中，
因此比较符合第2点推测，如下：

SQL ordered by Gets
Buffer Gets Executions Gets per Exec %Total CPU Time (s) Elapsed Time (s) SQL Id SQL Module SQL Text
...
13,996,731 109,095 128.30 3.80 586.11 1708.30 b2cfm5jm9888j GP4MSOX3DWK74QT9KQ0S2LNJLU0 INSERT INTO "/BIC/AMM00_O2900"...
10,222,371 126,034 81.11 2.77 494.23 1396.76 fqwvuf7w3kk7d GP4NBPK14Z49C1BR3I63Q5TQY4O INSERT INTO "/BIC/B0003586000"...
9,017,859 471 19,146.20 2.45 33.79 178.54 5xxbw9gqqugr7 CL_RSBC_FILTER_CMD============CP INSERT INTO "D010TAB" ( "MASTE...
...

以上平均每条insert的逻辑读在100次以上，推测是在执行insert的时候需要为表段分配新的分区（extent），导致了SQL bsa0wjtftg3uw的执行，带来了额外的逻辑读。
口说无凭，实验说明一切，做了个简单测试：
1. Create a new table t2 and try insert some data. Note: there are any extents allocation occurs in the session
====================
SQL> create table t2 as select * from dba_objects where 1=2;

SQL> select count(*) from dba_extents where owner='EDISON' and segment_name='T2';

COUNT(*)
----------
1

SQL> alter session set timed_statistics = true;

Session altered.

SQL> alter session set statistics_level=all;

Session altered.

SQL> alter session set max_dump_file_size = unlimited;

Session altered.

SQL> alter session set events '10046 trace name context forever, level 12';

Session altered.

SQL> insert into t2 select * from dba_objects;

51268 rows created.

SQL> insert into t2 select * from t2;

51268 rows created.

SQL> /

102536 rows created.

SQL> alter session set events '10046 trace name context off';

Session altered.

SQL> select count(*) from dba_extents where owner='EDISON' and segment_name='T2'; <===分配了38个extent

COUNT(*)
----------
38

检查trc文件:

select file# from file$ where ts#=:1 <===执行了72次

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 72 0.00 0.01 0 0 0 0
Execute 72 0.00 0.00 0 0 0 0
Fetch 144 0.00 0.00 0 288 0 72
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 288 0.00 0.01 0 288 0 72


2. 删除所有数据，但不回收EXTENT
====================
SQL> delete from t2;

205072 rows deleted.

SQL> commit;

Commit complete.

SQL> select count(*) from dba_extents where owner='EDISON' and segment_name='T2';

COUNT(*)
----------
38

SQL> alter session set timed_statistics = true;

Session altered.

SQL> alter session set statistics_level=all;

Session altered.

SQL> alter session set max_dump_file_size = unlimited;

Session altered.

SQL> alter session set events '10046 trace name context forever, level 12';

Session altered.

SQL> insert into t2 select * from dba_objects;

51268 rows created.

SQL> insert into t2 select * from t2;

51268 rows created.

SQL> commit;

Commit complete.

SQL> alter session set events '10046 trace name context off';

Session altered.

SQL> select count(*) from dba_extents where owner='EDISON' and segment_name='T2';

COUNT(*)
----------
38

检查trc文件，未发现有select file# from file$ where ts#=:1 执行。

解决方法：
1.将表的NEXT属性调大避免多次分配extent。
ALTER TABLE T2 STORAGE(NEXT NM);
2.手动为表分配extent
ALTER TABLE T2 ALLOCATE EXTENT ALLOCATE EXTENT (SIZE NM);