While writing a post about the TKPROF new features in 11.2.0.2 I noticed that I didn’t write one about an important change introduced in 11.2.0.1. So, before finishing the other one, let’s have a look to what changed in 11.2.0.1.

One problem with TKPROF up to 11gR1 is that when the AGGREGATE parameter is set to YES (which is the default), all information belonging to cursors having the same text is aggregated in a single SQL statement. This is fine when all cursors were executed with the same execution plan. However, this is also done when a cursor was executed with several execution plans. As a result, only one execution plan is visible in the output. The others are lost.

As of 11gR2 this problem is solved. In fact, every SQL statement in the output is only related to a single execution plan.

To illustrate this enhancement let’s have a look to the TKPROF output for the trace file generated by the following commands (the test table is the one of the SH sample schema):

VARIABLE channel_id NUMBER
EXECUTE dbms_monitor.session_trace_enable(plan_stat=>'all_executions', waits=>false)
EXECUTE :channel_id := 2;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE :channel_id := 3;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE :channel_id := 4;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE :channel_id := 5;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE :channel_id := 9;
SELECT * FROM sh.sales WHERE channel_id = :channel_id;
EXECUTE dbms_monitor.session_trace_disable
SELECT value FROM v$diag_info WHERE name = 'Default Trace File';

The essential thing to know about the query used in this test is that the selectivity strongly depends on the value of the CHANNEL_ID variable. The following query shows the actual distribution:

SQL> SELECT channel_id, count(*)
  2  FROM sh.sales
  3  GROUP BY channel_id
  4  ORDER BY channel_id;

CHANNEL_ID   COUNT(*)
---------- ----------
         2     258025
         3     540328
         4     118416
         9       2074

Hence, when running the commands shown above, two execution plans are expected.

  • When the selectivity is weak (high), the execution plan should be based on a full table scan.
  • When the selectivity is strong (low), the execution plan should be based on an index range scan.

After generating the trace file with 11gR2, let’s have a look to the output provided by TKPROF.

  • 11.1.0.7
SELECT *
FROM
 sh.sales WHERE channel_id = :channel_id

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.04       0.03          0          0          0           0
Execute      5      0.00       0.00          0          0          0           0
Fetch    61263      2.95       2.99          0      66150          0      918843
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    61273      3.01       3.03          0      66150          0      918843

Misses in library cache during parse: 1
Misses in library cache during execute: 3
Optimizer mode: ALL_ROWS
Parsing user id: 34

Rows     Row Source Operation
-------  ---------------------------------------------------
 540328  PARTITION RANGE ALL PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=1127079 us cost=531 size=7495485 card=258465)
 540328   TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=705028 us cost=531 size=7495485 card=258465)
  • 11.2.0.1
SQL ID: 94mzsr37n3vz0
Plan Hash: 1550251865
SELECT *
FROM
 sh.sales WHERE channel_id = :channel_id

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.04       0.03          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch    61122      2.94       2.98          0      65918          0      916769
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    61128      2.99       3.02          0      65918          0      916769

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 34

Rows     Row Source Operation
-------  ---------------------------------------------------
 540328  PARTITION RANGE ALL PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=1127079 us cost=531 size=7495485 card=258465)
 540328   TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=705028 us cost=531 size=7495485 card=258465)
SQL ID: 94mzsr37n3vz0
Plan Hash: 3721375305
SELECT *
FROM
 sh.sales WHERE channel_id = :channel_id

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      141      0.00       0.00          0        232          0        2074
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      145      0.01       0.01          0        232          0        2074

Misses in library cache during parse: 0
Misses in library cache during execute: 2
Optimizer mode: ALL_ROWS
Parsing user id: 34

Rows     Row Source Operation
-------  ---------------------------------------------------
   2074  PARTITION RANGE ALL PARTITION: 1 28 (cr=200 pr=0 pw=0 time=4602 us cost=325 size=78184 card=2696)
   2074   TABLE ACCESS BY LOCAL INDEX ROWID SALES PARTITION: 1 28 (cr=200 pr=0 pw=0 time=3979 us cost=325 size=78184 card=2696)
   2074    BITMAP CONVERSION TO ROWIDS (cr=32 pr=0 pw=0 time=993 us)
      3     BITMAP INDEX SINGLE VALUE SALES_CHANNEL_BIX PARTITION: 1 28 (cr=32 pr=0 pw=0 time=189 us)(object id 13980)

As you can see, in the 11.1.0.7 output the 5 executions are associated to a single SQL statement. So, according to it, it is sensible to say that all 5 executions used the same execution plan based on a full table scan. However, as described above, this is not true. The 11.2.0.1 output doesn’t exhibit the same problem. In fact, the information is separated in two SQL statements. For that reason the section providing the information about a SQL statement begins with the information not only about the SQL ID, but also about the hash value of the execution plan. Note that the SQL ID is missing from the 11.1.0.7 output. No idea why… In fact, in 11.1.0.6, it is present. The hash value, however, was added in 11gR2.