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.
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)
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.