Intermediate SQL Color Coded SQL, UNIX and Database Essays

26Dec/092

SQLPlus might show incorrect explain plan

Be careful when using SQLPlus to investigate performance problems as it might show you incorrect results in certain conditions.

Here is one example:

In the following scenario, we are trying to find out if a simple expression:

WHERE char_column = :bind

will produce different execution plans with NUMBER and CHAR binds.

At the first sight, it looks like there is no difference between CHAR and NUMBER binds – the plans are exactly the same:

SQL> variable vn NUMBER;
SQL> variable vc varchar2(10);
SQL> EXEC :vn := 25;
SQL> EXEC :vc := '25';

SQL> SET autotrace ON

SQL> SELECT * FROM t1 WHERE id=:vc;

ID
----------
25

Execution Plan
----------------------------------------------------------
Plan hash VALUE: 3333592317

----------------------------------------------------------------------------------
| Id  | Operation         | Name         | ROWS  | Bytes | Cost (%CPU)| TIME     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |              |     1 |     6 |     1   (0)| 00:00:52 |
|*  1 |  INDEX UNIQUE SCAN| SYS_C0048600 |     1 |     6 |     1   (0)| 00:00:52 |
----------------------------------------------------------------------------------

Predicate Information (IDENTIFIED BY operation id):
---------------------------------------------------

1 - access("ID"=:VC)

Statistics
----------------------------------------------------------
1  recursive calls
0  db block gets
2  consistent gets
2  physical reads
0  redo SIZE
520  bytes sent via SQL*Net TO client
524  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 * FROM t1 WHERE id=:vn;

ID
----------
25

Execution Plan
----------------------------------------------------------
Plan hash VALUE: 3333592317

----------------------------------------------------------------------------------
| Id  | Operation         | Name         | ROWS  | Bytes | Cost (%CPU)| TIME     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |              |     1 |     6 |     1   (0)| 00:00:52 |
|*  1 |  INDEX UNIQUE SCAN| SYS_C0048600 |     1 |     6 |     1   (0)| 00:00:52 |
----------------------------------------------------------------------------------

Predicate Information (IDENTIFIED BY operation id):
---------------------------------------------------

1 - access("ID"=:VN)

Statistics
----------------------------------------------------------
132  recursive calls
0  db block gets
181  consistent gets
6  physical reads
0  redo SIZE
520  bytes sent via SQL*Net TO client
524  bytes received via SQL*Net FROM client
2  SQL*Net roundtrips TO/FROM client
3  sorts (memory)
0  sorts (disk)
1  ROWS processed

But look closely at the execution statistics. With CHAR variable we have 2 consistent gets while with NUMBER we have 181.

Is it a fluke ? Well, not really, I have run the statements multiple times and they always produce (roughly) the same results.

It is a clue, however, that something is going on and it becomes perfectly clear in TKPROF output:

SELECT *
FROM
t1 WHERE id=:vn

CALL     COUNT       cpu    elapsed       disk      query    CURRENT        ROWS
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
EXECUTE      3      0.00       0.00          0          0          0           0
Fetch        6      0.61       0.73          0        474          0           3
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       12      0.61       0.73          0        474          0           3

Misses IN library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing USER id: 72

ROWS     ROW SOURCE Operation
-------  ---------------------------------------------------
1  TABLE ACCESS FULL T1 (cr=158 pr=0 pw=0 TIME=0 us cost=71 SIZE=6 card=1)

In other words, SQLPlus, while a useful tool, has its own share of problems that you need to be aware of. So,

Be careful while working with SQLPlus and always sanity check your results

Comments (2) Trackbacks (0)
  1. Please note that what you have reported in this blog article is in fact NOT a bug in SQL*Plus. Behind the scenes, SQL*Plus’ AUTOTRACE facility uses an EXPLAIN PLAN FOR call to retrieve the execution plan for a submitted SQL statement. All bind variables for a call to EXPLAIN PLAN, whether called from SQL*Plus or another utility, are interpretted as VARCHAR2 (regardless of the actual bind variable data type) and are not initialized with a value (this also prevents bind variable peeking from affecting the execution plan). The Oracle Database documentation states the following about EXPLAIN PLAN: “Oracle does not support EXPLAIN PLAN for statements performing implicit type conversion of date bind variables. With bind variables in general, the EXPLAIN PLAN output might not represent the real execution plan.”

    Your article states that it is attempting to compare execution plans for NUMBER and CHAR binds, but the VC bind variable is actually defined as a VARCHAR2 and not a CHAR.

    A quick demonstration:
    [code]
    CREATE TABLE T1 (C1 NUMBER, PRIMARY KEY);

    INSERT INTO T1
    SELECT ROWNUM FROM DUAL CONNECT BY LEVELUSER,TABNAME=>’T1′,CASCADE=>TRUE)
    [/code]

    We now have a very simple table with a primary key index, and 100 rows in the table. On to the test:
    [code]
    VARIABLE N1 NUMBER
    EXEC :N1:=1
    ALTER SESSION SET EVENTS ‘10046 TRACE NAME CONTEXT FOREVER, LEVEL 12′;
    SET AUTOTRACE ON

    SELECT
    C1
    FROM
    T1
    WHERE
    C1 = :N1;

    Execution Plan
    ———————————————————-
    Plan hash value: 2546125981

    ———————————————————————————-
    | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
    ———————————————————————————-
    | 0 | SELECT STATEMENT | | 1 | 3 | 0 (0)| 00:00:01 |
    |* 1 | INDEX UNIQUE SCAN| SYS_C0028425 | 1 | 3 | 0 (0)| 00:00:01 |
    ———————————————————————————-

    Predicate Information (identified by operation id):
    —————————————————
    1 – access(“C1″=TO_NUMBER(:N1))

    SET AUTOTRACE OFF
    [/code]

    Notice the Predicate Information section of the execution plan shows that the N1 bind variable is being converted from a VARCHAR2 to a NUMBER for the comparison. That conversion is a direct result of AUTOTRACE using EXPLAIN PLAN to generate the excution plan for the SQL statement. Now, let’s take a look at the way to display the actual execution plan (in Oracle Database 10.1 and greater):
    [code]
    SELECT
    C1
    FROM
    T1
    WHERE
    C1 = :N1;

    SELECT * FROM TABLE);

    PLAN_TABLE_OUTPUT
    ———————————————————————–
    SQL_ID d2fjtd39f9gmd, child number 0
    ————————————-
    SELECT C1 FROM T1 WHERE C1 = :N1

    Plan hash value: 2546125981

    ———————————————————————–
    | Id | Operation | Name | Rows | Bytes | Cost (%CPU)|
    ———————————————————————–
    | 0 | SELECT STATEMENT | | | | 1 (100)|
    |* 1 | INDEX UNIQUE SCAN| SYS_C0028425 | 1 | 3 | 0 (0)|
    ———————————————————————–

    Predicate Information (identified by operation id):
    —————————————————
    1 – access(“C1″=:N1)
    [/code]
    Notice in the above, the Predicate Information section does not show that the N1 bind variable is being converted from a VARCHAR2 to a NUMBER for the comparison.

    Now that we are finished with the 10046 trace, we should disable it:
    [code]
    ALTER SESSION SET EVENTS ‘10046 TRACE NAME CONTEXT OFF’;
    [/code]

    Still not sure that SQL*Plus just calls EXPLAIN PLAN when AUTOTRACE is enabled? Take a look in the 10046 trace file that was generated, below is a small portion of the trace file:
    [code]
    PARSING IN CURSOR #11 len=85 dep=0 uid=286 oct=3 lid=286 tim=178896871268 hv=3595065010 ad=’4697a6750′ sqlid=’gkgsxamb4hppk’
    EXPLAIN PLAN SET STATEMENT_ID=’PLUS702067′ FOR SELECT
    C1
    FROM
    T1
    WHERE
    C1 = :N1
    END OF STMT
    PARSE #11:c=0,e=144,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=178896871268
    BINDS #11:
    Bind#0
    oacdty=01 mxl=32(00) mxlc=00 mal=00 scl=00 pre=00
    oacflg=00 fl2=1010000 frm=01 csi=178 siz=32 off=0
    kxsbbbfp=1f533240 bln=32 avl=00 flg=05
    [/code]

    Notice in the above the call to EXPLAIN PLAN, that the oacdty is set to 01 (VARCHAR2), and that the bind variable’s value was not submitted.

    Of course, it is also possible for TKPROF to show the wrong (Row Source Operation) execution plan for a query, but that is a topic for another discussion.

  2. @Charles Hooper – At what point did the article SAY it was a BUG ??? He’s just pointing out an issue for people to be aware of


Leave a comment

No trackbacks yet.