Bind variable peeking & adaptive cursor sharing

In the previous post we looked at a simple scenario to illustrate SQL Monitoring. In this post I want to extend on that example to illustrate two more features of query optimisation Oracle may employ; bind variable peeking and adaptive cursor sharing.

The query we used last time was simply:

SELECT *
FROM   monitor_test
WHERE  category = :cat

EXPLAIN PLAN showed that Oracle will choose to perform a full table scan when executing the query:

SQL>EXPLAIN PLAN
  2  FOR
  3  SELECT *
  4  FROM   monitor_test
  5  WHERE  category = :cat
  6  /

Explained.

SQL>
SQL>SELECT *
  2  FROM   TABLE(dbms_xplan.display())
  3  /
Plan hash value: 2944410690

----------------------------------------------------------------------------------
| Id  | Operation         | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |              |   200K|  7617K|  1661   (2)| 00:00:20 |
|*  1 |  TABLE ACCESS FULL| MONITOR_TEST |   200K|  7617K|  1661   (2)| 00:00:20 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("CATEGORY"=TO_NUMBER(:CAT))

13 rows selected.

For the previous post we initially used a bind variable value of 5 and then a value of 1. The choice of values and the order used was actually deliberate. If we were to retry the example but use a bind variable value of 1 as the first value we get the following (you may need to flush the shared pool or restart your database first to clear the library cache):

SQL> SET LINESIZE 132
SQL> SET PAGESIZE 9999
SQL> SET ARRAYSIZE 1000
SQL> 
SQL> COLUMN plan_line_id     FORMAT 90
SQL> COLUMN plan_operation   FORMAT A20
SQL> COLUMN plan_options     FORMAT A20
SQL> COLUMN plan_object_name FORMAT A15
SQL> COLUMN plan_object_type FORMAT A10
SQL> COLUMN plan_cost        FORMAT 9999990
SQL> COLUMN plan_cardinality FORMAT 9999990
SQL> COLUMN starts           FORMAT 9999990
SQL> COLUMN output_rows      FORMAT 9999990
SQL> 
SQL> VARIABLE cat NUMBER
SQL> VARIABLE client_id VARCHAR2(30)
SQL> 
SQL> EXEC :cat := 1

PL/SQL procedure successfully completed.

SQL> EXEC :client_id := 'monitor test category 1'

PL/SQL procedure successfully completed.

SQL> 
SQL> EXEC dbms_session.set_identifier (:client_id)

PL/SQL procedure successfully completed.

SQL> 
SQL> SET AUTOTRACE TRACEONLY STATISTICS
SQL> 
SQL> SELECT /*+ MONITOR */
  2  	    *
  3  FROM   monitor_test
  4  WHERE  category = :cat
  5  /

1000 rows selected.


Statistics
----------------------------------------------------------
         83  recursive calls
          0  db block gets
       1092  consistent gets
       2347  physical reads
          0  redo size
      43596  bytes sent via SQL*Net to client
        520  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          7  sorts (memory)
          0  sorts (disk)
       1000  rows processed

SQL> 
SQL> SET AUTOTRACE OFF
SQL> 
SQL> EXEC dbms_session.set_identifier (NULL)

PL/SQL procedure successfully completed.

SQL> 
SQL> SELECT pm.plan_line_id
  2  ,	    pm.plan_operation
  3  ,	    pm.plan_options
  4  ,	    pm.plan_object_name
  5  ,	    pm.plan_object_type
  6  ,	    pm.plan_cost
  7  ,	    pm.plan_cardinality
  8  ,	    pm.starts
  9  ,	    pm.output_rows
 10  FROM   v$sql_monitor      m
 11  ,	    v$sql_plan_monitor pm
 12  WHERE  m.key = pm.key
 13  AND    m.client_identifier = :client_id
 14  ORDER  BY
 15  	    m.sql_exec_start
 16  ,	    pm.key
 17  ,	    pm.sql_id
 18  ,	    pm.plan_line_id
 19  /

PLAN_LINE_ID PLAN_OPERATION       PLAN_OPTIONS         PLAN_OBJECT_NAM PLAN_OBJEC PLAN_COST PLAN_CARDINALITY   STARTS OUTPUT_ROWS
------------ -------------------- -------------------- --------------- ---------- --------- ---------------- -------- -----------
           0 SELECT STATEMENT                                                                                       1        1000
           1 TABLE ACCESS         BY INDEX ROWID       MONITOR_TEST    TABLE             15             1000        1        1000
           2 INDEX                RANGE SCAN           MONITOR_TEST_I1 INDEX              4             1000        1        1000

So, despite what our EXPLAIN PLAN output said, Oracle has not table scanned MONITOR_TEST and instead has selected to look up the rows via the index MONITOR_TEST_I1. To retrieve 1,000 rows out of 1,000,000 this is understandable but there remains the question of why it chose to do so when the EXPLAIN PLAN said otherwise. The reason is that when hard parsing a query, i.e. creating an execution plan for the first time, Oracle will “peek” at the bind variables used and attempt to optimise the query for those values. Bind variable peeking was introduced in Oracle 9i. In our scenario we used a bind variable of 1 when the query was hard parsed. Since we have a histogram on the CATEGORY column Oracle was able to deduce that it will be returning 1,000 rows (note the plan cardinality in the SQL monitor query) and so it selected an index access path instead of a full table scan. We can see the details of the histogram by querying USER_TAB_HISTOGRAMS:

SQL>COLUMN column_name           FORMAT A12
SQL>
SQL>SELECT column_name
  2  ,      endpoint_value
  3  ,      endpoint_number
  4  FROM   user_tab_histograms
  5  WHERE  table_name  = 'MONITOR_TEST'
  6  AND    column_name = 'CATEGORY'
  7  ORDER  BY
  8         endpoint_value
  9  /

COLUMN_NAME  ENDPOINT_VALUE ENDPOINT_NUMBER
------------ -------------- ---------------
CATEGORY                  1            1000
CATEGORY                  2            6000
CATEGORY                  3           56000
CATEGORY                  4          156000
CATEGORY                  5         1000000

So, when Oracle went to parse the query and peeked at the bind variable it was able to determine that it could expect to retrieve 1,000 rows and hence selected the index access path. If we now rerun the same query but with a bind variable of 5 we get:

SQL> EXEC :cat := 5

PL/SQL procedure successfully completed.

SQL> EXEC :client_id := 'monitor test category 5'

PL/SQL procedure successfully completed.

SQL> 
SQL> EXEC dbms_session.set_identifier (:client_id)

PL/SQL procedure successfully completed.

SQL> 
SQL> SET AUTOTRACE TRACEONLY STATISTICS
SQL> 
SQL> SELECT /*+ MONITOR */
  2  	    *
  3  FROM   monitor_test
  4  WHERE  category = :cat
  5  /

844000 rows selected.


Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       9390  consistent gets
       5382  physical reads
          0  redo size
   37277063  bytes sent via SQL*Net to client
       9793  bytes received via SQL*Net from client
        845  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
     844000  rows processed

SQL> 
SQL> SET AUTOTRACE OFF
SQL> 
SQL> EXEC dbms_session.set_identifier (NULL)

PL/SQL procedure successfully completed.

SQL> 
SQL> SELECT pm.plan_line_id
  2  ,	    pm.plan_operation
  3  ,	    pm.plan_options
  4  ,	    pm.plan_object_name
  5  ,	    pm.plan_object_type
  6  ,	    pm.plan_cost
  7  ,	    pm.plan_cardinality
  8  ,	    pm.starts
  9  ,	    pm.output_rows
 10  FROM   v$sql_monitor      m
 11  ,	    v$sql_plan_monitor pm
 12  WHERE  m.key = pm.key
 13  AND    m.client_identifier = :client_id
 14  ORDER  BY
 15  	    m.sql_exec_start
 16  ,	    pm.key
 17  ,	    pm.sql_id
 18  ,	    pm.plan_line_id
 19  /

PLAN_LINE_ID PLAN_OPERATION       PLAN_OPTIONS         PLAN_OBJECT_NAM PLAN_OBJEC PLAN_COST PLAN_CARDINALITY   STARTS OUTPUT_ROWS
------------ -------------------- -------------------- --------------- ---------- --------- ---------------- -------- -----------
           0 SELECT STATEMENT                                                                                       1      844000
           1 TABLE ACCESS         BY INDEX ROWID       MONITOR_TEST    TABLE             15             1000        1      844000
           2 INDEX                RANGE SCAN           MONITOR_TEST_I1 INDEX              4             1000        1      844000

Hmmm, our subsequent run with a bind variable of 5 still used the same index access path. Note again that the plan cardinality is 1,000 but the actual output rows is 844,000. Clearly the 1,000 estimate is rather amiss and as such the index access path probably isn’t the best choice. This illustrates the key failing of bind variable peeking; the variables are peeked at when the query is hard parsed only and subsequent executions of the query will reuse the same plan regardless of the bind variable values. This in turn may lead to inefficient query execution as our example illustrates.

To rectify the problem with bind variable peeking Oracle introduced adaptive cursor sharing in version 11g. To demonstrate this feature, well simply rerun our previous query with a bind variable value of 5 again:

SQL>VARIABLE cat NUMBER
SQL>VARIABLE client_id VARCHAR2(30)
SQL>
SQL>EXEC :cat := 5

PL/SQL procedure successfully completed.

SQL>EXEC :client_id := 'monitor test category 5a'

PL/SQL procedure successfully completed.

SQL>
SQL>EXEC dbms_session.set_identifier (:client_id)

PL/SQL procedure successfully completed.

SQL>
SQL>SET AUTOTRACE TRACEONLY STATISTICS
SQL>
SQL>SELECT /*+ MONITOR */
  2  	    *
  3  FROM   monitor_test
  4  WHERE  category = :cat
  5  /

844000 rows selected.


Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
       6909  consistent gets
          1  physical reads
          0  redo size
    8578594  bytes sent via SQL*Net to client
       9793  bytes received via SQL*Net from client
        845  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
     844000  rows processed

SQL>
SQL>SET AUTOTRACE OFF
SQL>
SQL>EXEC dbms_session.set_identifier (NULL)

PL/SQL procedure successfully completed.

SQL>
SQL>SELECT pm.plan_line_id
  2  ,	    pm.plan_operation
  3  ,	    pm.plan_options
  4  ,	    pm.plan_object_name
  5  ,	    pm.plan_object_type
  6  ,	    pm.plan_cost
  7  ,	    pm.plan_cardinality
  8  ,	    pm.starts
  9  ,	    pm.output_rows
 10  FROM   v$sql_monitor      m
 11  ,	    v$sql_plan_monitor pm
 12  WHERE  m.key = pm.key
 13  AND    m.client_identifier = :client_id
 14  ORDER  BY
 15  	    m.sql_exec_start
 16  ,	    pm.key
 17  ,	    pm.sql_id
 18  ,	    pm.plan_line_id
 19  /

PLAN_LINE_ID PLAN_OPERATION       PLAN_OPTIONS         PLAN_OBJECT_NAM PLAN_OBJEC PLAN_COST PLAN_CARDINALITY   STARTS OUTPUT_ROWS
------------ -------------------- -------------------- --------------- ---------- --------- ---------------- -------- -----------
           0 SELECT STATEMENT                                                                                       1      844000
           1 TABLE ACCESS         FULL                 MONITOR_TEST    TABLE           1657           844000        1      844000

SQL>

You’ll note that without making any changes whatsoever Oracle has changed the execution plan. The SQL Monitor query not only tells us that Oracle performed a full table scan for the query but it also correctly estimated the number of rows that the query would return. This is adaptive cursor sharing in operation. Essentially, if Oracle encounters a query that is sensitive to the specific bind variable values it will flag it as such. On execution of the query if there is a difference between the estimated cardinality and the actual output rows then, on subsequent execution, Oracle will reparse the query in an attempt to generate a better execution plan.

One downside to adaptive cursor sharing is that Oracle will only do the subsequent optimisation after it has encountered a poor execution of query. In our example, the initial run of the query with a bind variable value of 5 used an index access path, which was clearly suboptimal and Oracle flagged it as such. When the query was rerun Oracle optimised the second exeuction for the bind variable used.

We can see that adaptive cursor sharing has kicked in by looking into the query cursor in the SGA. Oracle will set the IS_BIND_SENSITIVE attribute in V$SQL for queries that it’s noted are sensitive to the values of the bind variables presented and the attribute IS_BIND_AWARE attribute for queries that are subject to adaptive cursor sharing optimisation:

SQL>SET ECHO ON
SQL>SET LINESIZE 132
SQL>SET PAGESIZE 9999
SQL>
SQL>COLUMN is_bind_sensitive FORMAT A17
SQL>COLUMN is_bind_aware     FORMAT A13
SQL>
SQL>VARIABLE client_id VARCHAR2(30)
SQL>VARIABLE sql_id    VARCHAR2(30)
SQL>
SQL>EXEC :client_id := 'monitor test category 5a'

PL/SQL procedure successfully completed.

SQL>
SQL>EXEC dbms_session.set_identifier (:client_id)

PL/SQL procedure successfully completed.

SQL>
SQL>BEGIN
  2     SELECT sql_id
  3     INTO   :sql_id
  4     FROM   v$sql_monitor
  5     WHERE  client_identifier = :client_id
  6     AND    ROWNUM = 1;
  7  END;
  8  /

PL/SQL procedure successfully completed.

SQL>
SQL>SELECT *
  2  FROM   TABLE(dbms_xplan.display_cursor(:sql_id,NULL))
  3  /

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  9a8ttf3bd0sk6, child number 0
-------------------------------------
SELECT /*+ MONITOR */        * FROM   monitor_test WHERE  category =
:cat

Plan hash value: 1473390912

-----------------------------------------------------------------------------------------------
| Id  | Operation                   | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                 |       |       |    15 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| MONITOR_TEST    |  1000 | 39000 |    15   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | MONITOR_TEST_I1 |  1000 |       |     4   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("CATEGORY"=:CAT)

SQL_ID  9a8ttf3bd0sk6, child number 1
-------------------------------------
SELECT /*+ MONITOR */        * FROM   monitor_test WHERE  category =
:cat

Plan hash value: 2944410690

----------------------------------------------------------------------------------
| Id  | Operation         | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |              |       |       |  1657 (100)|          |
|*  1 |  TABLE ACCESS FULL| MONITOR_TEST |   844K|    31M|  1657   (1)| 00:00:20 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("CATEGORY"=:CAT)


39 rows selected.

SQL>
SQL>SELECT sql_id
  2  ,      plan_hash_value
  3  ,      executions
  4  ,      is_bind_sensitive
  5  ,      is_bind_aware
  6  FROM   v$sql
  7  WHERE  sql_id = :sql_id
  8  /

SQL_ID        PLAN_HASH_VALUE EXECUTIONS IS_BIND_SENSITIVE IS_BIND_AWARE
------------- --------------- ---------- ----------------- -------------
9a8ttf3bd0sk6      1473390912          2 Y                 N
9a8ttf3bd0sk6      2944410690          1 Y                 Y

From the above we can see that the index access path query was SQL_ID 9a8ttf3bd0sk6, child number 0 and had a plan hash value of 1473390912. The full table scan query was SQL_ID 9a8ttf3bd0sk6, child number 1 and had a plan hash value of 2944410690. We can see that we’ve had two executions of our index access path query and it’s flagged as bind sensitive. We can also see that we’ve had one execution of the table scan query and that this is set to bind aware.

Adaptive cursor sharing is a new feature of Oracle 11g but isn’t documented in the standard database documentation and has a series of restrictions. Oracle will need to be aware of skewed data via histograms in order to determine bind value cardinalities. Furthermore, Oracle will only optimise the query for certain types of simple predicates, such as equality, less/greater than and LIKE (from version 11.2). It will also be disabled if the query runs in parallel or contains more than 14 bind variables. Oracle Support document 740052.1 provides a better listing of the restrictions (you will need an Oracle Support account to access the document).

Both bind variable peeking and adaptive cursor sharing are designed to allow Oracle to execute queries more efficiently by altering “normal” behaviour for details picked up at run time. However, they also complicate matters when it comes to diagnosing performance problems as the execution plan obtained via EXPLAIN PLAN may not actually be the plan Oracle uses when it runs the query. The details presented in V$SQL help determining if adaptve cursor sharing is in effect (as well as some data dictionary views not discussed in this post). However, there’s no similar flag to determine if bind variable peeking influenced the creation of the execution plan. SQL monitoring permits us to look into actual query executions and can be useful diagnosing the impact that these features are having.

---

Download scripts shown in this post.

SQL Monitor

When faced with a particularly slow running query it can be difficult to figure out the cause of the problem. Obtaining the relevant execution plan is a significan step in diagnosing where the problem lies but at times this is not enough. Skewed data distributions and the use of bind variables means that a plan that is suitable for one set of variables may be totally inappropriate for other variables. To help us with this type of problem Oracle introduced SQL monitoring in 11g that tells us specifically what a query is up to and where plan calculations may have gone astray.

You’ll find details about SQL monitoring in the Performance Tuning Guide but essentially Oracle will automatically start monitoring a query if it’s run in parallel or if the CPU or I/O time exceeds 5 seconds. Alternately, Oracle will monitor a query if it’s hinted with the monitoring hint:

SELECT /*+ monitor */
...

Once Oracle is monitoring a query then it populates two internal views, v$sql_monitor and v$sql_plan_monitor, with details of the execution. Note, the details pertain to a specific execution of a query and are not aggregate figures across multiple executions so we get can get the actual details of what Oracle was doing for our query execution. Of course, in a busy system Oracle may be monitoring many statement executions. Oracle will retain the details in the views for at least 1 minute after execution finishes so it’s important to grab the details as soon as possible. Keep in mind that once monitoring starts then the views are being populated in real time (well, every second) and not only at the end of the execution. This is what makes the monitoring capability so appropriate to diagnosing a currently executing slow query.

The v$sql_monitor view contains one row for each statement that is being monitored. Identifying the specific query that you are interested in is generally a matter of locating the session executing your query from v$session, obtaining details such as the SID and SQL_ID and querying v$sql_monitor with these details. Of course, if your application is properly instrumented with things like CLIENT_IDENTIFIER, MODULE and ACTION then tracking down your query in v$sql_monitor will be even easier. v$sql_monitor contains a number of time-based statistics such as elapsed time, CPU time, application wait time, concurrency wait time, IO wait time and more. These statistics should help you figure out the type of activity your query is spending its time on. It also contains logical and physical I/O details that can help point to whether you have a query plan issue.

In my opinion, the real attraction in SQL monitoring comes from v$sql_plan_monitor. Once you’ve identified your query within v$sql_monitor, you can use the KEY column to query the v$sql_plan_monitor view. For the statement being monitored, this view contains one entry for each line of the execution plan. The view contains details you will find from v$sql_plan, such as the plan operation, object owner, object name and position. It also contains the plan cost and cardinality. These details you will normally obtain the from execution plan but what v$sql_plan_monitor gives you as well is the actual execution details for each step; the number of times the operation was executed, the rows output, the first and last time a row was generated, the physical I/O details and the workarea memory consumption.

Using v$sql_plan_monitor, a simple comparison of the plan cardinality to the actual rows output will tell you if Oracle has made reasonable assumptions about the plan it generated and subsequently whether the join operations it selected are appropriate. Let’s take a look at an example, using a table of 1,000,000 rows with a category column containing 5 distinct values with the following distribution:

• value 1: 1,000 rows
• value 2: 5,000 rows
• value 3: 50,000 rows
• value 4: 100,000 rows
• value 5: 844,000 rows

First we create and populate out table, making sure that our values are distributed throughout the table:

CREATE TABLE monitor_test
  (id       NUMBER (10) NOT NULL
  ,category NUMBER(1)   NOT NULL
  ,padding  CHAR(30)    NOT NULL
  ,CONSTRAINT monitor_test_pk PRIMARY KEY (id))
/

INSERT INTO monitor_test
SELECT rownum
,      CASE 
          WHEN MOD(rownum,1000)  = 0                 THEN 1
          WHEN MOD(rownum,1000)  BETWEEN 1  AND 5    THEN 2
          WHEN MOD(rownum,1000)  BETWEEN 6  AND 55   THEN 3
          WHEN MOD(rownum,1000)  BETWEEN 56 AND 155  THEN 4
          ELSE 5
       END
,      'X'
FROM   dual
CONNECT BY level <= 1000000
/

COMMIT
/

CREATE INDEX monitor_test_i1
ON monitor_test (category)
/

EXEC dbms_stats.gather_table_stats ('','monitor_test',estimate_percent=>NULL,method_opt=>'FOR ALL INDEXED COLUMNS SIZE AUTO')

-- check the distribution of CATEOGRY values
SELECT category
,      count(*) AS no_entries
FROM   monitor_test
GROUP  BY
       category
ORDER  BY
       category
/

When we run an EXPLAIN PLAN for queries that select from the table and filter on the CATEGORY column using values of:

• 1
• 5
• bind variable

we get:

SQL>EXPLAIN PLAN
  2  FOR
  3  SELECT *
  4  FROM   monitor_test
  5  WHERE  category = 1
  6  /

Explained.

SQL>
SQL>SELECT *
  2  FROM   TABLE(dbms_xplan.display())
  3  /
Plan hash value: 1473390912

-----------------------------------------------------------------------------------------------
| Id  | Operation                   | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                 |  1000 | 39000 |    15   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| MONITOR_TEST    |  1000 | 39000 |    15   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | MONITOR_TEST_I1 |  1000 |       |     4   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("CATEGORY"=1)

14 rows selected.

SQL>
SQL>EXPLAIN PLAN
  2  FOR
  3  SELECT *
  4  FROM   monitor_test
  5  WHERE  category = 5
  6  /

Explained.

SQL>
SQL>SELECT *
  2  FROM   TABLE(dbms_xplan.display())
  3  /
Plan hash value: 2944410690

----------------------------------------------------------------------------------
| Id  | Operation         | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |              |   844K|    31M|  1657   (1)| 00:00:20 |
|*  1 |  TABLE ACCESS FULL| MONITOR_TEST |   844K|    31M|  1657   (1)| 00:00:20 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("CATEGORY"=5)

13 rows selected.

SQL>
SQL>EXPLAIN PLAN
  2  FOR
  3  SELECT *
  4  FROM   monitor_test
  5  WHERE  category = :cat
  6  /

Explained.

SQL>
SQL>SELECT *
  2  FROM   TABLE(dbms_xplan.display())
  3  /
Plan hash value: 2944410690

----------------------------------------------------------------------------------
| Id  | Operation         | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |              |   200K|  7617K|  1661   (2)| 00:00:20 |
|*  1 |  TABLE ACCESS FULL| MONITOR_TEST |   200K|  7617K|  1661   (2)| 00:00:20 |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("CATEGORY"=TO_NUMBER(:CAT))

13 rows selected.

We can see that Oracle will choose to do an index lookup into the table when we select a CATEGORY value of 1 and choose to do a full table scan when we select a CATEGORY value of 5. When we provide a bind variable instead of a hard coded literal for the CATEGORY filter Oracle calculates it will return 200,000 rows and chooses to do a full table scan. Obviously no CATEGORY value would actually return this number of rows but it’s the best Oracle can do with the data it has available to it.

So, without knowing the value of the bind variable, Oracle shown that it will choose to scan the table. In a proper system this kind of assumption by the optimiser may manifest as a query that takes far too long to execute. It may be picked up through an examination of the execution plan but monitoring allows us to look into the query execution itself to see exactly where Oracle has made its optimisation error.

Let’s see what SQL monitoring tells us if we actually run the query, providing bind variable values of 5 and then again with a value of 1 (using AUTOTRACE to suppress the actual output):

SQL>SET LINESIZE 132
SQL>SET PAGESIZE 9999
SQL>SET ARRAYSIZE 1000
SQL>
SQL>COLUMN plan_line_id     FORMAT 90
SQL>COLUMN plan_operation   FORMAT A20
SQL>COLUMN plan_options     FORMAT A20
SQL>COLUMN plan_object_name FORMAT A15
SQL>COLUMN plan_object_type FORMAT A10
SQL>COLUMN plan_cost        FORMAT 9999990
SQL>COLUMN plan_cardinality FORMAT 9999990
SQL>COLUMN starts           FORMAT 9999990
SQL>COLUMN output_rows      FORMAT 9999990
SQL>
SQL>VARIABLE cat NUMBER
SQL>VARIABLE client_id VARCHAR2(30)
SQL>
SQL>EXEC :cat := 5

PL/SQL procedure successfully completed.

SQL>EXEC :client_id := 'monitor test cat 5'

PL/SQL procedure successfully completed.

SQL>
SQL>EXEC dbms_session.set_identifier (:client_id)

PL/SQL procedure successfully completed.

SQL>
SQL>SET AUTOTRACE TRACEONLY STATISTICS
SQL>
SQL>SELECT /*+ MONITOR */
  2  	    *
  3  FROM   monitor_test
  4  WHERE  category = :cat
  5  /

844000 rows selected.

Statistics
----------------------------------------------------------
         79  recursive calls
          0  db block gets
       6988  consistent gets
       6066  physical reads
          0  redo size
    8578594  bytes sent via SQL*Net to client
       9792  bytes received via SQL*Net from client
        845  SQL*Net roundtrips to/from client
          6  sorts (memory)
          0  sorts (disk)
     844000  rows processed

SQL>
SQL>SET AUTOTRACE OFF
SQL>
SQL>EXEC dbms_session.set_identifier (NULL)

PL/SQL procedure successfully completed.

SQL>
SQL>SELECT pm.plan_line_id
  2  ,	    pm.plan_operation
  3  ,	    pm.plan_options
  4  ,	    pm.plan_object_name
  5  ,	    pm.plan_object_type
  6  ,	    pm.plan_cost
  7  ,	    pm.plan_cardinality
  8  ,	    pm.starts
  9  ,	    pm.output_rows
 10  FROM   v$sql_monitor      m
 11  ,	    v$sql_plan_monitor pm
 12  WHERE  m.key = pm.key
 13  AND    m.client_identifier = :client_id
 14  ORDER  BY
 15  	    m.sql_exec_start
 16  ,	    pm.key
 17  ,	    pm.sql_id
 18  ,	    pm.plan_line_id
 19  /

PLAN_LINE_ID PLAN_OPERATION       PLAN_OPTIONS         PLAN_OBJECT_NAM PLAN_OBJEC PLAN_COST PLAN_CARDINALITY   STARTS OUTPUT_ROWS
------------ -------------------- -------------------- --------------- ---------- --------- ---------------- -------- -----------
           0 SELECT STATEMENT                                                                                       1      844000
           1 TABLE ACCESS         FULL                 MONITOR_TEST    TABLE           1656           200000        1      844000

SQL>
SQL>EXEC :cat := 1

PL/SQL procedure successfully completed.

SQL>EXEC :client_id := 'monitor test cat 1'

PL/SQL procedure successfully completed.

SQL>
SQL>EXEC dbms_session.set_identifier (:client_id)

PL/SQL procedure successfully completed.

SQL>
SQL>SET AUTOTRACE TRACEONLY STATISTICS
SQL>
SQL>SELECT /*+ MONITOR */
  2  	    *
  3  FROM   monitor_test
  4  WHERE  category = :cat
  5  /

1000 rows selected.

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       6064  consistent gets
       6060  physical reads
          0  redo size
       9656  bytes sent via SQL*Net to client
        519  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
       1000  rows processed

SQL>
SQL>SET AUTOTRACE OFF
SQL>
SQL>EXEC dbms_session.set_identifier (NULL)

PL/SQL procedure successfully completed.

SQL>
SQL>SELECT pm.plan_line_id
  2  ,	    pm.plan_operation
  3  ,	    pm.plan_options
  4  ,	    pm.plan_object_name
  5  ,	    pm.plan_object_type
  6  ,	    pm.plan_cost
  7  ,	    pm.plan_cardinality
  8  ,	    pm.starts
  9  ,	    pm.output_rows
 10  FROM   v$sql_monitor      m
 11  ,	    v$sql_plan_monitor pm
 12  WHERE  m.key = pm.key
 13  AND    m.client_identifier = :client_id
 14  ORDER  BY
 15  	    m.sql_exec_start
 16  ,	    pm.key
 17  ,	    pm.sql_id
 18  ,	    pm.plan_line_id
 19  /

PLAN_LINE_ID PLAN_OPERATION       PLAN_OPTIONS         PLAN_OBJECT_NAM PLAN_OBJEC PLAN_COST PLAN_CARDINALITY   STARTS OUTPUT_ROWS
------------ -------------------- -------------------- --------------- ---------- --------- ---------------- -------- -----------
           0 SELECT STATEMENT                                                                                       1        1000
           1 TABLE ACCESS         FULL                 MONITOR_TEST    TABLE           1656           200000        1        1000

SQL>
SQL>SPOOL OFF

It can easily be seen from the last column of the queries against v$sql_monitor and v$sql_plan_monitor exactly what went on with our queries. The first query, with a bind variable value of 5, returned 844,000 rows from the full table scan of the table and the second query returned 1,000 rows. In both scenarios, Oracle’s calculated cardinality was 200,000.

Obviously the example used here is quite trivial. In a more complex query the above technique can be used to detect differences in particular steps of the overall execution plan, which helps pinpoint where a query may be “going wrong”. The difference between the FIRST_CHANGE_TIME and LAST_CHANGE_TIME is another metric for gauging which activities are taking a long time within the query execution since this helps pinpoint where the time is spent.

One point to bear in mind when using v$sql_plan_monitor is that if you are relying on SQL monitoring kicking in after 5 seconds of CPU or I/O activity then some details of those first 5 seconds are lost and don’t get reported. It may be best to explicitly use the MONITOR hint for queries that you believe will be problematic.

---

Download scripts shown in this post.