[20120915]10046事件与执行计划改变.txt

    使用10046事件来跟踪解决oracle的许多问题,是非常常用的手段,但是实际上可能出现跟踪的sql执行计划与原来不同的情况,自己应该引起注意.

测试如下:

1.测试环境建立:

SQL> select * from v$version ;

BANNER

--------------------------------------------------------------------------------

Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production

PL/SQL Release 11.2.0.1.0 - Production

CORE    11.2.0.1.0      Production

TNS for Linux: Version 11.2.0.1.0 - Production

NLSRTL Version 11.2.0.1.0 - Production

SQL> create table t as select rownum id , 'test' name from dual connect by level

Table created.

SQL> insert into t select 1e4+1 ,'book' from dual connect by level

10000 rows created.

SQL> create index i_t_id on t(id);

Index created.

--可以发现id分布不均匀,而且10001占了50%.建立直方图看看.

SQL> exec dbms_stats.gather_table_stats(ownname=>user,tabname=>'T',cascade=>true,method_opt=>'for all columns size 254');

PL/SQL procedure successfully completed.

2.开始测试:

SQL> variable v_id number ;

SQL> exec :v_id := 42;

PL/SQL procedure successfully completed.

SQL> select * from t where id=:v_id;

        ID NAME

---------- ----

        42 test

SQL> @dpc ''

PLAN_TABLE_OUTPUT

-------------------------------------

SQL_ID  d9msgvzah6u4p, child number 0

-------------------------------------

select * from t where id=:v_id

Plan hash value: 4153437776

--------------------------------------------------------------------

| Id  | Operation                   | Name   | E-Rows | Cost (%CPU)|

--------------------------------------------------------------------

|   0 | SELECT STATEMENT            |        |        |     2 (100)|

|   1 |  TABLE ACCESS BY INDEX ROWID| T      |      1 |     2   (0)|

|*  2 |   INDEX RANGE SCAN          | I_T_ID |      1 |     1   (0)|

--------------------------------------------------------------------

Peeked Binds (identified by position):

--------------------------------------

   1 - (NUMBER): 42

Predicate Information (identified by operation id):

---------------------------------------------------

   2 - access("ID"=:V_ID)

Note

-----

   - Warning: basic plan statistics not available. These are only collected when:

       * hint 'gather_plan_statistics' is used for the statement or

       * parameter 'statistics_level' is set to 'ALL', at session or system level

30 rows selected.

将select * from t where id=:v_id;执行多次,避免ACS的影响.(我使用的是11G).

SQL> select sql_text,sql_id,child_number,executions from v$sql where sql_id='d9msgvzah6u4p';

SQL_TEXT                                 SQL_ID        CHILD_NUMBER EXECUTIONS

---------------------------------------- ------------- ------------ ----------

select * from t where id=:v_id           d9msgvzah6u4p            0          9

3.打开10046跟踪看看:

SQL> exec :v_id := 10001;

PL/SQL procedure successfully completed.

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

Session altered.

SQL> select * from t where id=:v_id;

...

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

SQL> select sql_text,sql_id,child_number,executions from v$sql where sql_id='d9msgvzah6u4p';

SQL_TEXT                                 SQL_ID        CHILD_NUMBER EXECUTIONS

---------------------------------------- ------------- ------------ ----------

select * from t where id=:v_id           d9msgvzah6u4p            0          9

select * from t where id=:v_id           d9msgvzah6u4p            1          1

--查看视图V$SQL,发现生成了新的子光标.

SQL> select * from table(dbms_xplan.display_cursor('d9msgvzah6u4p',1,'ALLSTATS LAST PEEKED_BINDS cost'));

PLAN_TABLE_OUTPUT

-----------------------------------------------------------------------------------------------------------

SQL_ID  d9msgvzah6u4p, child number 1

-------------------------------------

select * from t where id=:v_id

Plan hash value: 1601196873

-------------------------------------------------------------------------------------------------

| Id  | Operation         | Name | Starts | E-Rows | Cost (%CPU)| A-Rows |   A-Time   | Buffers |

-------------------------------------------------------------------------------------------------

|   0 | SELECT STATEMENT  |      |      1 |        |    14 (100)|  10000 |00:00:00.01 |      96 |

|*  1 |  TABLE ACCESS FULL| T    |      1 |  10039 |    14   (0)|  10000 |00:00:00.01 |      96 |

-------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):

--------------------------------------

   1 - (NUMBER): 10001

Predicate Information (identified by operation id):

---------------------------------------------------

   1 - filter("ID"=:V_ID)

23 rows selected.

--查看跟踪文件也可以发现,执行计划发生了变化:

SQL ID: d9msgvzah6u4p

Plan Hash: 1601196873

select *

from

 t where id=:v_id

call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse        1      0.00       0.00          0          0          0           0

Execute      1      0.00       0.00          0          0          0           0

Fetch       51      0.00       0.00          0         96          0       10000

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total       53      0.00       0.01          0         96          0       10000

Misses in library cache during parse: 1

Optimizer mode: ALL_ROWS

Parsing user id: 84

Rows     Row Source Operation

-------  ---------------------------------------------------

  10000  TABLE ACCESS FULL T (cr=96 pr=0 pw=0 time=11152 us cost=14 size=90351 card=10039)

4.看看什么导致的光标不能共享:

SQL> @share d9msgvzah6u4p

SQL_TEXT                       = select * from t where id=:v_id

SQL_ID                         = d9msgvzah6u4p

ADDRESS                        = 00000000DE2DC258

CHILD_ADDRESS                  = 00000000DE2DBE58

CHILD_NUMBER                   = 0

--------------------------------------------------

SQL_TEXT                       = select * from t where id=:v_id

SQL_ID                         = d9msgvzah6u4p

ADDRESS                        = 00000000DE2DC258

CHILD_ADDRESS                  = 00000000DE29D1B8

CHILD_NUMBER                   = 1

STATS_ROW_MISMATCH             = Y

--------------------------------------------------

PL/SQL procedure successfully completed.

--可以发现实际上STATS_ROW_MISMATCH=Y.

    也就是将在开启跟踪后,会话执行的SQL将不会重用以前的的执行计划，发生硬解析。由于硬解析时要发生绑定变量窥视，将会使硬解析产生的子游标，而这里由于

ID数据的分布变化,导致其执行计划可能发生了变化。

5.实际上这种情况很多:

比如设置optimizer_capture_sql_plan_baselines=true也会出现类似情况.

设置sql_trace =true等.