【IT168 技术文档】我们经常使用Sql Trace和10046 event来诊断Oracle数据库性能问题。而level超过1的10046事件通常称为extended sql trace，通常用于诊断确定的单个SQL、存储过程或会话的性能问题，具有如下的几个优点：
可以得到SQL执行时实际的执行计划。
可以得到SQL执行时所花时间的具体分布，CPU消耗了多长时间，多块读消耗了多长时间等等。
可以得到SQL执行时的各种与性能相关的统计数据，逻辑读、物理读、fetch次数、parse次数等等。
不仅能够用于性能测试，同时能够用于诊断正在执行的SQL或存储过程的性能。
有很多的工具用于格式化生成的trace文件，除了Oracle自带的TKPROF、Metalink Note 224270.1 Trace Analyzer，以及第三方的免费工具如orasrp，《Troubleshooting Oracle Performance》作者开发的TVD$XTAT，甚至还有商业化的软件Hotsos Profiler等。
不过前段时间在用10046事件诊断一个性能问题的时候，却让生成的结果误导了。后来仔细检查发现，在会话开启sql trace的情况下，SQL语句会重新解析，导致开启sql trace之后与开启之前相比，执行计划可能发生了变化，导致sql trace的结果不能真实地反映会话执行SQL的情况，在分析时容易发生偏差。
下面是一个测试：
测试的环境是Oracle 10.2.0.1 for Windows，不过前面提到的案例，是发生在Oracle 9i下的，所以9i和10g都有这个问题，而11g目前还没有测试过，有兴趣的朋友可以在11g上进行测试。
首先创建一个sql文件，内容为：
select /*+ testsql */ sum(value) from t1 where flag=:v_flag;
创建一个列上数据有倾斜的表：
SQL> create table t1 (value number ,flag number,pad varchar2(2000));
表已创建。
SQL> insert into t1 select rownum,mod(rownum,2000),lpad('x',1000,'x') from dba_objects;
已创建49796行。
SQL> commit;
提交完成。
SQL> insert into t1 select rownum,3000,lpad('x',1000,'x') from dba_objects where rownum<=10000;
已创建10000行。
SQL> commit;
提交完成。
SQL> create index t1_idx on t1(flag);
索引已创建。
SQL> exec dbms_stats.gather_table_stats(ownname=>user,tabname=>'T1',cascade=>true,method_opt=>'for all indexed columns');
PL/SQL 过程已成功完成。
SQL> select column_name,num_distinct,num_buckets from user_tab_columns where table_name='T1';
COLUMN_NAME NUM_DISTINCT NUM_BUCKETS
------------------------------ ------------ -----------
VALUE
FLAG 2030 75
PAD
select /*+ testsql */ sum(value) from t1 where flag=:v_flag;
创建一个列上数据有倾斜的表：
SQL> create table t1 (value number ,flag number,pad varchar2(2000));
表已创建。
SQL> insert into t1 select rownum,mod(rownum,2000),lpad('x',1000,'x') from dba_objects;
已创建49796行。
SQL> commit;
提交完成。
SQL> insert into t1 select rownum,3000,lpad('x',1000,'x') from dba_objects where rownum<=10000;
已创建10000行。
SQL> commit;
提交完成。
SQL> create index t1_idx on t1(flag);
索引已创建。
SQL> exec dbms_stats.gather_table_stats(ownname=>user,tabname=>'T1',cascade=>true,method_opt=>'for all indexed columns');
PL/SQL 过程已成功完成。
SQL> select column_name,num_distinct,num_buckets from user_tab_columns where table_name='T1';
COLUMN_NAME NUM_DISTINCT NUM_BUCKETS
------------------------------ ------------ -----------
VALUE
FLAG 2030 75
PAD
select /*+ testsql */ sum(value) from t1 where flag=:v_flag;
创建一个列上数据有倾斜的表：
SQL> create table t1 (value number ,flag number,pad varchar2(2000));
表已创建。
SQL> insert into t1 select rownum,mod(rownum,2000),lpad('x',1000,'x') from dba_objects;
已创建49796行。
SQL> commit;
提交完成。
SQL> insert into t1 select rownum,3000,lpad('x',1000,'x') from dba_objects where rownum<=10000;
已创建10000行。
SQL> commit;
提交完成。
SQL> create index t1_idx on t1(flag);
索引已创建。
SQL> exec dbms_stats.gather_table_stats(ownname=>user,tabname=>'T1',cascade=>true,method_opt=>'for all indexed columns');
PL/SQL 过程已成功完成。
SQL> select column_name,num_distinct,num_buckets from user_tab_columns where table_name='T1';
COLUMN_NAME NUM_DISTINCT NUM_BUCKETS
------------------------------ ------------ -----------
VALUE
FLAG 2030 75
PAD
select /*+ testsql */ sum(value) from t1 where flag=:v_flag;
创建一个列上数据有倾斜的表：
SQL> create table t1 (value number ,flag number,pad varchar2(2000));
表已创建。
SQL> insert into t1 select rownum,mod(rownum,2000),lpad('x',1000,'x') from dba_objects;
已创建49796行。
SQL> commit;
提交完成。
SQL> insert into t1 select rownum,3000,lpad('x',1000,'x') from dba_objects where rownum<=10000;
已创建10000行。
SQL> commit;
提交完成。
SQL> create index t1_idx on t1(flag);
索引已创建。
SQL> exec dbms_stats.gather_table_stats(ownname=>user,tabname=>'T1',cascade=>true,method_opt=>'for all indexed columns');
PL/SQL 过程已成功完成。
SQL> select column_name,num_distinct,num_buckets from user_tab_columns where table_name='T1';
COLUMN_NAME NUM_DISTINCT NUM_BUCKETS
------------------------------ ------------ -----------
VALUE
FLAG 2030 75
PAD
在创建的测试表中，FLAG列有2001个不同的值，其中，0-1999之间每个值约为25个，而有一个特殊的值3000，有10000个。收集统计信息时，在FLAG列上收集了直方图。
下面运行test.sql：
SQL> var v_flag number;
SQL> exec :v_flag:=3000;
SQL> set autot on stat
SQL> @test
SUM(VALUE)
----------
50005000
统计信息
-------------------------------------------------------
0 recursive calls
0 db block gets
8575 consistent gets
0 physical reads
0 redo size
412 bytes sent via SQL*Net to client
384 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
SQL> var v_flag number;
SQL> exec :v_flag:=3000;
SQL> set autot on stat
SQL> @test
SUM(VALUE)
----------
50005000
统计信息
-------------------------------------------------------
0 recursive calls
0 db block gets
8575 consistent gets
0 physical reads
0 redo size
412 bytes sent via SQL*Net to client
384 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
SQL> exec :v_flag:=3000;
SQL> set autot on stat
SQL> @test
SUM(VALUE)
----------
50005000
统计信息
-------------------------------------------------------
0 recursive calls
0 db block gets
8575 consistent gets
0 physical reads
0 redo size
412 bytes sent via SQL*Net to client
384 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
SQL> var v_flag number;
SQL> exec :v_flag:=3000;
SQL> set autot on stat
SQL> @test
SUM(VALUE)
----------
50005000
统计信息
-------------------------------------------------------
0 recursive calls
0 db block gets
8575 consistent gets
0 physical reads
0 redo size
412 bytes sent via SQL*Net to client
384 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
我们来看看SQL的执行计划：
SQL> select sql_id,hash_value,child_number,executions from v$sql where sql_text like '%testsql%' and sql_text not like '%v$sql%';
SQL_ID HASH_VALUE CHILD_NUMBER EXECUTIONS
------------- ---------- ------------ ----------
8hdvb5nwfqm8r 954944791 0 2
SQL> select * from table(dbms_xplan.display_cursor('8hdvb5nwfqm8r',0));
PLAN_TABLE_OUTPUT
---------------------------------------
SQL_ID 8hdvb5nwfqm8r, child number 0
-------------------------------------
select /*+ testsql */ sum(value) from t1 where flag=:v_flag
Plan hash value: 3724264953
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 765 (100)| |
| 1 | SORT AGGREGATE | | 1 | 17 | | |
|* 2 | TABLE ACCESS FULL| T1 | 9863 | 163K| 765 (1)| 00:00:07 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("FLAG"=:V_FLAG)
SQL> select sql_id,hash_value,child_number,executions from v$sql where sql_text like '%testsql%' and sql_text not like '%v$sql%';
SQL_ID HASH_VALUE CHILD_NUMBER EXECUTIONS
------------- ---------- ------------ ----------
8hdvb5nwfqm8r 954944791 0 2
SQL> select * from table(dbms_xplan.display_cursor('8hdvb5nwfqm8r',0));
PLAN_TABLE_OUTPUT
---------------------------------------
SQL_ID 8hdvb5nwfqm8r, child number 0
-------------------------------------
select /*+ testsql */ sum(value) from t1 where flag=:v_flag
Plan hash value: 3724264953
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 765 (100)| |
| 1 | SORT AGGREGATE | | 1 | 17 | | |
|* 2 | TABLE ACCESS FULL| T1 | 9863 | 163K| 765 (1)| 00:00:07 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("FLAG"=:V_FLAG)
SQL_ID HASH_VALUE CHILD_NUMBER EXECUTIONS
------------- ---------- ------------ ----------
8hdvb5nwfqm8r 954944791 0 2
SQL> select * from table(dbms_xplan.display_cursor('8hdvb5nwfqm8r',0));
PLAN_TABLE_OUTPUT
---------------------------------------
SQL_ID 8hdvb5nwfqm8r, child number 0
-------------------------------------
select /*+ testsql */ sum(value) from t1 where flag=:v_flag
Plan hash value: 3724264953
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 765 (100)| |
| 1 | SORT AGGREGATE | | 1 | 17 | | |
|* 2 | TABLE ACCESS FULL| T1 | 9863 | 163K| 765 (1)| 00:00:07 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("FLAG"=:V_FLAG)
SQL> select sql_id,hash_value,child_number,executions from v$sql where sql_text like '%testsql%' and sql_text not like '%v$sql%';
SQL_ID HASH_VALUE CHILD_NUMBER EXECUTIONS
------------- ---------- ------------ ----------
8hdvb5nwfqm8r 954944791 0 2
SQL> select * from table(dbms_xplan.display_cursor('8hdvb5nwfqm8r',0));
PLAN_TABLE_OUTPUT
---------------------------------------
SQL_ID 8hdvb5nwfqm8r, child number 0
-------------------------------------
select /*+ testsql */ sum(value) from t1 where flag=:v_flag
Plan hash value: 3724264953
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 765 (100)| |
| 1 | SORT AGGREGATE | | 1 | 17 | | |
|* 2 | TABLE ACCESS FULL| T1 | 9863 | 163K| 765 (1)| 00:00:07 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("FLAG"=:V_FLAG)
可以看到，由于绑定变量窥视，SQL语句走了全表扫描，没有使用索引。
SQL> exec :v_flag:=300;
SQL> set autot on stat
SQL> @test
SUM(VALUE)
----------
607500
统计信息
----------------------------------------------------------
0 recursive calls
0 db block gets
8575 consistent gets
0 physical reads
0 redo size
411 bytes sent via SQL*Net to client
384 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
SQL> exec :v_flag:=300;
SQL> set autot on stat
SQL> @test
SUM(VALUE)
----------
607500
统计信息
----------------------------------------------------------
0 recursive calls
0 db block gets
8575 consistent gets
0 physical reads
0 redo size
411 bytes sent via SQL*Net to client
384 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
SQL> set autot on stat
SQL> @test
SUM(VALUE)
----------
607500
统计信息
----------------------------------------------------------
0 recursive calls
0 db block gets
8575 consistent gets
0 physical reads
0 redo size
411 bytes sent via SQL*Net to client
384 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
SQL> exec :v_flag:=300;
SQL> set autot on stat
SQL> @test
SUM(VALUE)
----------
607500
统计信息
----------------------------------------------------------
0 recursive calls
0 db block gets
8575 consistent gets
0 physical reads
0 redo size
411 bytes sent via SQL*Net to client
384 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
从上面的输出可以看到，在变量=300时，仍然走了全表扫描，仍然没有使用索引。
