我们经常使用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         

在创建的测试表中,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的执行计划:

Read the rest of this entry

,