我們經常使用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
在創建的測試表中，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的執行計劃：
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語句走了全表掃描，沒有使用索引。
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
從上面的輸出可以看到，在變量=300時，仍然走了全表掃描，仍然沒有使用索引。
使用sqlplus創建一個新的到Oracle的連接，並執行測試SQL:
開啟另一個會話，
SQL> select sid,serial# from v$session where sid=(select sid from v$mystat where rownum=1);
SID SERIAL#
---------- ---------- 22 153 SQL> var v_flag number;
SQL> exec :v_flag:=500;
SQL> set autot on stat
SQL> @test SUM(VALUE)
---------- 612500 統計信息
---------------------------------------------------------- 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> select sid,serial# from v$session where sid=(select sid from v$mystat where rownum=1);
SID SERIAL#
---------- ---------- 22 153 SQL> var v_flag number;
SQL> exec :v_flag:=500;
SQL> set autot on stat
SQL> @test SUM(VALUE)
---------- 612500 統計信息
---------------------------------------------------------- 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執行得到的邏輯讀來看，仍然是走的全表掃描。這裡很明顯使用索引更為合適，這就是使用綁定變量引起的副作用。
然而，如果我們打這個這個會話的10046 事件，則結果如何呢?
SQL> exec sys.dbms_system.set_ev(22,153,10046,12,'');
SQL> exec :v_flag:=410;
SQL> @test SUM(VALUE)
---------- 610250 SQL> exec sys.dbms_system.set_ev(22,153,10046,12,'');
SQL> exec :v_flag:=410;
SQL> @test SUM(VALUE)
---------- 610250
下面是trace文件的內容：
PARSING IN CURSOR #1 len=59 dep=0 uid=55 oct=3 lid=55 tim=7703132042 hv=954944791 ad='27cf5884' select /*+ testsql */ sum(value) from t1 where flag=:v_flag
END OF STMT
PARSE #1:c=0,e=309,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=7703132037 BINDS #1:
kkscoacd
Bind#0 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0 kxsbbbfp=0819ca94 bln=22 avl=03 flg=05 value=410 EXEC #1:c=15625,e=8864,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=7703164320 WAIT #1: nam='SQL*Net message to clIEnt' ela= 5 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=7703165526 FETCH #1:c=0,e=237,p=0,cr=27,cu=0,mis=0,r=1,dep=0,og=1,tim=7703166929 WAIT #1: nam='SQL*Net message from clIEnt' ela= 187 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=7703168520 FETCH #1:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=7703169851 WAIT #1: nam='SQL*Net message to clIEnt' ela= 5 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=7703171170 WAIT #1: nam='SQL*Net message from clIEnt' ela= 421 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=7703172845 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=27 pr=0 pw=0 time=260 us)' STAT #1 id=2 cnt=25 pid=1 pos=1 obj=51606 op='TABLE Access BY INDEX ROWID T1 (cr=27 pr=0 pw=0 time=439 us)' STAT #1 id=3 cnt=25 pid=2 pos=1 obj=51607 op='INDEX RANGE SCAN T1_IDX (cr=2 pr=0 pw=0 time=36 us)' PARSING IN CURSOR #1 len=59 dep=0 uid=55 oct=3 lid=55 tim=7703132042 hv=954944791 ad='27cf5884' select /*+ testsql */ sum(value) from t1 where flag=:v_flag
END OF STMT
PARSE #1:c=0,e=309,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=7703132037 BINDS #1:
kkscoacd
Bind#0 oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0 kxsbbbfp=0819ca94 bln=22 avl=03 flg=05 value=410 EXEC #1:c=15625,e=8864,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=7703164320 WAIT #1: nam='SQL*Net message to clIEnt' ela= 5 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=7703165526 FETCH #1:c=0,e=237,p=0,cr=27,cu=0,mis=0,r=1,dep=0,og=1,tim=7703166929 WAIT #1: nam='SQL*Net message from clIEnt' ela= 187 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=7703168520 FETCH #1:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=7703169851 WAIT #1: nam='SQL*Net message to clIEnt' ela= 5 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=7703171170 WAIT #1: nam='SQL*Net message from clIEnt' ela= 421 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=7703172845 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=27 pr=0 pw=0 time=260 us)' STAT #1 id=2 cnt=25 pid=1 pos=1 obj=51606 op='TABLE Access BY INDEX ROWID T1 (cr=27 pr=0 pw=0 time=439 us)' STAT #1 id=3 cnt=25 pid=2 pos=1 obj=51607 op='INDEX RANGE SCAN T1_IDX (cr=2 pr=0 pw=0 time=36 us)'
可以看，mis=1，表明發生了硬解析，op=’INDEX RANGE SCAN T1_IDX 表明使用使用了索引，而op=’SORT AGGREGATE (cr=27 表明邏輯讀只有27，邏輯讀幅下降，的確是使用了索引。
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 7 8hdvb5nwfqm8r 954944791 1 1 SQL> select * from table(dbms_xplan.display_cursor('8hdvb5nwfqm8r',1));
PLAN_TABLE_OUTPUT
------------------------------------- SQL_ID 8hdvb5nwfqm8r, child number 1 ------------------------------------- select /*+ testsql */ sum(value) from t1 where flag=:v_flag
Plan hash value: 1563165360 --------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | --------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | | | 30 (100)| | | 1 | SORT AGGREGATE | | 1 | 17 | | | | 2 | TABLE Access BY INDEX ROWID| T1 | 33 | 561 | 30 (0)| 00:00:01 | |* 3 | INDEX RANGE SCAN | T1_IDX | 33 | | 1 (0)| 00:00:01 | --------------------------------------------------------------------------------------- Predicate Information (identifIEd by Operation id):
--------------------------------------------------- 3 - Access("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 7 8hdvb5nwfqm8r 954944791 1 1 SQL> select * from table(dbms_xplan.display_cursor('8hdvb5nwfqm8r',1));
PLAN_TABLE_OUTPUT
------------------------------------- SQL_ID 8hdvb5nwfqm8r, child number 1 ------------------------------------- select /*+ testsql */ sum(value) from t1 where flag=:v_flag
Plan hash value: 1563165360 --------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | --------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | | | 30 (100)| | | 1 | SORT AGGREGATE | | 1 | 17 | | | | 2 | TABLE Access BY INDEX ROWID| T1 | 33 | 561 | 30 (0)| 00:00:01 | |* 3 | INDEX RANGE SCAN | T1_IDX | 33 | | 1 (0)| 00:00:01 | --------------------------------------------------------------------------------------- Predicate Information (identifIEd by Operation id):
--------------------------------------------------- 3 - Access("FLAG"=:V_FLAG)
從上面的輸出可以看到，這條SQL已經產生了另外一個子游標(child cursor)。而查看新的子游標的執行計劃，已經使用了索引。
由此，可以看出，開啟sql trace之後，會話執行的SQL將不會重用未開啟sql trace時生成的執行計劃，而發生硬解析。由於硬解析時綁定變量窺視，將會使硬解析產生的子游標，其執行計劃可能發生了變化。
在最後，我們來看看引起游標不能共享的原因是什麼?
SQL> select * from v$sql_shared_cursor where sql_id='8hdvb5nwfqm8r';
SQL_ID ADDRESS CHILD_AD CHILD_NUMBER U S O O S L S E B P I S T A B D L T R I I R L I O S M U T N F A I T D L D B P C S R P T M B M R O P M F L
------------- -------- -------- ------------ - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - 8hdvb5nwfqm8r 27CF5884 27CF57A0 0 N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N
8hdvb5nwfqm8r 27CF5884 27CCC968 1 N N N N Y N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N
SQL> select * from v$sql_shared_cursor where sql_id='8hdvb5nwfqm8r';
SQL_ID ADDRESS CHILD_AD CHILD_NUMBER U S O O S L S E B P I S T A B D L T R I I R L I O S M U T N F A I T D L D B P C S R P T M B M R O P M F L
------------- -------- -------- ------------ - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - 8hdvb5nwfqm8r 27CF5884 27CF57A0 0 N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N
8hdvb5nwfqm8r 27CF5884 27CCC968 1 N N N N Y N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N N
從結果可以看到，STATS_ROW_MISMATCH導致了游標不能共享，Oracle文檔這個列的解釋是：The existing statistics do not match the existing child cursor。
在最後，使用10g的dbms_monitor包來打開會話的sql trace，測試結果完全相同。
