玉面飞龙的BLOG

很早以前碰到过一个例子。应用执行SQL抱怨很慢，然后我用10046去跟踪应用的查询。却没有从跟踪文件中找到什么不好的Plan，反而被抱怨的SQL执行效果很好。

原因是10046sql_trace 在trace session的时候，默认session执行的每个SQL都将从新进行hard parse,产生一个新的child cursor,自然，这个被traced的cursor和原本应用的cursor就有可能因为dbms_auto_invalidations等原因使用不同的plan.

也就是说，10046 event并不能保证得到的执行计划就是当前应用程序SQL正在使用的执行计划。

SQL example:

SQL> select count(*) from t;
COUNT(*)
———-
613

SQL> /
COUNT(*)
———-
613

SQL> /
COUNT(*)
———-
613

SQL> /
COUNT(*)
———-
613

SQL> alter session set sql_trace=true;
Session altered.

SQL> select count(*) from t;
COUNT(*)
———-
613

SQL> select count(*) from t;
COUNT(*)
———-
613

SQL> alter session set sql_trace=false;
Session altered.

SQL> select count(*) from t;
COUNT(*)
———-
613

SQL> /
COUNT(*)
———-
613
SQL> /
COUNT(*)
———-
613

From SQL trace, we can see 2 parse. 1 hard , 1 soft.
Hard parse is caused by sql_trace.

——-  —————————————————
select count(*) from t
——-  —————————————————
call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        4      0.00       0.00          0         22          0           2
——- ——  ——– ———- ———- ———- ———-  ———-
total        8      0.00       0.00          0         22          0           2

Misses in library cache during parse: 1
Optimizer goal: RULE
Parsing user id: 43

2 child cursor in V$SQL.

SQL> select sql_id,hash_value,sql_text,executions,INVALIDATIONS,parse_calls,loads from v$sql
where sql_text=’select count(*) from t’;

SQL_TEXT                EXECUTIONS INVALIDATIONS PARSE_CALLS      LOADS
————- ———– ———— ———– ———— ————
select count(*) from t           7             0           7          1
select count(*) from t           2             0           2          1

In 9i, the difference column is on OPTIMIZER_MISMATCH of v$sql_shared_cursor.

SQL> select * from v$sql_shared_cursor where address in (child_address1,child_address2);

ADDRESS          KGLHDPAR         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
—————- —————- - - - - - - - - - - - - - - - - - - - - - - — - - - - - - -
0000000DF3A66758 0000000E0BAB5210 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
0000000DF3D8ADF0 0000000E0BAB5210 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

/* OPTIMIZER_MISMATCH */

In 10g, the difference column is on STATS_ROW_MISMATCH of v$sql_shared_cursor.

SQL_ID        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
————- ———— - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
cyzznbykb509s            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
cyzznbykb509s            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 */

Since they’re different child cursor, they could have different plan. So some times, 10046 don’t always tell us the truth.