TKPROF in 11.2.0.2 Unexpected Improvement – Rows (1st), Rows (avg), and Rows (max)

12 10 2010

October 12, 2010

One of the greatest features of TKPROF is its ability to quickly summarize very long 10046 extended SQL trace files into easily understood plain text files.  And one of the greatest problems with TKPROF is its default setting that instructs the program to summarize the 10046 extended SQL trace files into easily understood plain text files.  While generating the summary, TKPROF discards a lot of very useful information, and that is why I typically either manually review the raw 10046 trace files or process the files with my Toy Project for Performance Tuning.

In a recent OTN thread a person mentioned seeing columns labeled “Rows (1st)” , “Rows (avg)” , and “Rows (max)” in the Row Source Operation portion of the TKPROF output generated by Oracle Database 11.2.0.2, and wondered what the values in those columns meant.  I could guess the meaning, but why guess when you can search.  A Google search found… the OTN thread and little else.  A documentation search of download.oracle.com found… nothing.  A search of Metalink (MOS) found… nothing.  So, I took a guess as to what the columns mean since I did not have access to Oracle Database 11.2.0.2 in order to perform a direct test.  I built a test case script which constructed two test tables as follows, each with an index (I am still waiting for the OTN thread OP to post his results):

CREATE TABLE T1(
  C1 NUMBER NOT NULL,
  C2 NUMBER NOT NULL,
  C3 VARCHAR2(100));

CREATE TABLE T2(
  C1 NUMBER NOT NULL,
  C2 NUMBER NOT NULL,
  C3 VARCHAR2(100));

INSERT INTO
  T1
SELECT
  ROWNUM C1,
  V2.RN C2,
  RPAD(TO_CHAR(ROWNUM),10,'A') C3
FROM
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=1000) V1,
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=1000) V2
WHERE
  MOD(V1.RN,1000)>=V2.RN;

INSERT INTO
  T2
SELECT
  *
FROM
  T1;

COMMIT;

CREATE INDEX IND_T1_C1_C2 ON T1(C1,C2);
CREATE INDEX IND_T2_C1_C2 ON T2(C1,C2);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE)
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2',CASCADE=>TRUE)

The table data inserted into the two test tables have a variable number of rows for each distinct value in column C2.  For example:

SELECT
  C2,
  COUNT(*)
FROM
  T1
GROUP BY
  C2
ORDER BY
  C2;

  C2   COUNT(*)
---- ----------
   1        999
   2        998
   3        997
   4        996
   5        995
   6        994
   7        993
   8        992
   9        991
  10        990
...
 995          5
 996          4
 997          3
 998          2
 999          1

Column C3 is simply a 10 character padding column to make each table row slightly longer, which may decrease the chances of the optimizer selecting full table scans when accessing the tables, if an index access path is available.  Next, the test script (note that I swapped the order of the first two bind variable values to better illustrate what those columns in the TKPROF output indicate): 

SET LINESIZE 160
SET PAGESIZE 1000
SET TRIMSPOOL ON

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'SQL_10046_ROW_TEST';
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 4';

SPOOL sql_10046_row_test.txt

VARIABLE N1 NUMBER

EXEC :N1:=5

SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N1:=1

SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N1:=95

SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

EXEC :N1:=995

SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';

SPOOL OFF

The excution plans generated by the calls to DBMS_XPLAN in the above script follow:

SQL_ID  6z03777fugw57, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   COUNT(*) FROM   T1,   T2 WHERE
T1.C2=T2.C2   AND T1.C2= :N1

Plan hash value: 765688747

-------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation              | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |              |      1 |        |      1 |00:00:00.15 |    2780 |      2 |       |       |          |
|   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |00:00:00.15 |    2780 |      2 |       |       |          |
|*  2 |   HASH JOIN            |              |      1 |    250K|    990K|00:00:00.26 |    2780 |      2 |  1517K|  1517K|  712K (0)|
|*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |    995 |00:00:00.03 |    1390 |      1 |       |       |          |
|*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |    995 |00:00:00.02 |    1390 |      1 |       |       |          |
-------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("T1"."C2"="T2"."C2")
   3 - filter("T1"."C2"=:N1)
   4 - filter("T2"."C2"=:N1)

------

SQL_ID  6z03777fugw57, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   COUNT(*) FROM   T1,   T2 WHERE
T1.C2=T2.C2   AND T1.C2= :N1

Plan hash value: 765688747

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation              | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |              |      1 |        |      1 |00:00:00.12 |    2780 |       |       |          |
|   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |00:00:00.12 |    2780 |       |       |          |
|*  2 |   HASH JOIN            |              |      1 |    250K|    998K|00:00:00.21 |    2780 |  1517K|  1517K|  719K (0)|
|*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |    999 |00:00:00.02 |    1390 |       |       |          |
|*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |    999 |00:00:00.02 |    1390 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("T1"."C2"="T2"."C2")
   3 - filter("T1"."C2"=:N1)
   4 - filter("T2"."C2"=:N1)

------

SQL_ID  6z03777fugw57, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   COUNT(*) FROM   T1,   T2 WHERE
T1.C2=T2.C2   AND T1.C2= :N1

Plan hash value: 765688747

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation              | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |              |      1 |        |      1 |00:00:00.10 |    2780 |       |       |          |
|   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |00:00:00.10 |    2780 |       |       |          |
|*  2 |   HASH JOIN            |              |      1 |    250K|    819K|00:00:00.18 |    2780 |  1517K|  1517K|  713K (0)|
|*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |    905 |00:00:00.02 |    1390 |       |       |          |
|*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |    905 |00:00:00.02 |    1390 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("T1"."C2"="T2"."C2")
   3 - filter("T1"."C2"=:N1)
   4 - filter("T2"."C2"=:N1)

------

SQL_ID  6z03777fugw57, child number 0
-------------------------------------
SELECT /*+ GATHER_PLAN_STATISTICS */   COUNT(*) FROM   T1,   T2 WHERE
T1.C2=T2.C2   AND T1.C2= :N1

Plan hash value: 765688747

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation              | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |              |      1 |        |      1 |00:00:00.04 |    2780 |       |       |          |
|   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |00:00:00.04 |    2780 |       |       |          |
|*  2 |   HASH JOIN            |              |      1 |    250K|     25 |00:00:00.04 |    2780 |  1452K|  1452K|  677K (0)|
|*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |      5 |00:00:00.02 |    1390 |       |       |          |
|*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |      5 |00:00:00.02 |    1390 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("T1"."C2"="T2"."C2")
   3 - filter("T1"."C2"=:N1)
   4 - filter("T2"."C2"=:N1)

By looking at the consistent SQL_ID (6z03777fugw57) and child number (0) values displayed with the execution plans, we are able to determine that there was a single hard parse for this SQL statement, even though the number of rows returned by the operation indicated by ID 3 returned anywhere from 25 to 998,000 rows.  It sure would be nice if TKPROF summaries provided some sort of indication about the variable number of rows returned by each operation in the execution plan.  Prior to Oracle Database 11.1, the STAT lines in the raw 10046 trace file, which are transformed by TKPROF into the “Row Source Operation” section in the TKPROF output, were written only when the cursor for the SQL statement closed.  The default behavior in Oracle Database 11.1 changed, with the STAT lines written by default (edit: October 13, 2010) with every after the first execution of a SQL statement (controlled by the PLAN_STAT parameter of DBMS_SESSION.SESSION_TRACE_ENABLE)).  With the introduction of adaptive cursor sharing, each execution with different bind variable values could have a different execution plan written to the raw 10046 trace file.  TKPROF in 11.1.0.6 had a tendency to completely “get it wrong” when the execution plan for a SQL statement changed.  The situation improved with TKPROF in 11.1.0.7, which is able to sense a change in the execution plan and not combine the output statistics for the different execution plans.

The problem still remained through 11.2.0.1 that the “Row Source Operation” section only showed the statistics for the first execution (or the first execution for each new execution plan for a SQL statement).  How would the person reading the TKPROF output recognize that sometimes the operation indicated by ID 3 returned 3 rows, other times returned 998,000 rows, and (assuming the SQL statement was hard parsed during the trace) was originally optimized with the operation returning 990,000 rows.  That could be valuable information – maybe adaptive cursor sharing should have triggered the generation of a different execution plan.  So, what are those columns labeled “Rows (1st)”, “Rows (avg)”, and “Rows (max)” – and what happened to the “Rows” column?  Certainly, the header information in the TKPROF output must explain these three columns (from the 11.2.0.2 TKPROF output):

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

Well, there is the “Rows” column that no longer exists in the “Row Source Operation” section.  Maybe the three columns indicate the number of rows on the first execution, the average number of rows for all executions, and the maximum number of rows of all executions.  That information would certainly be helpful when reviewing TKPROF summaries.

If we pass the 10046 extended SQL trace file generated by the test script (executed against Oracle Database 11.2.0.1) through TKPROF provided with either Oracle Database 11.1.0.6 or 11.2.0.1, we see the following for the SQL statement of interest:

SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute      4      0.00       0.01          0          0          0           0
Fetch        8      0.39       0.41          2      11120          0           4
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       16      0.39       0.43          2      11120          0           4

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

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=2780 pr=2 pw=0 time=0 us)
 990025   HASH JOIN  (cr=2780 pr=2 pw=0 time=222451 us cost=759 size=2000000 card=250000)
    995    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=1 pw=0 time=27459 us cost=379 size=2000 card=500)(object id 72576)
    995    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=1 pw=0 time=17395 us cost=379 size=2000 card=500)(object id 72577)

Four executions, yet the Row Source Operation only shows the execution plan for the first execution.  Now, let’s take a look at the output found in the 11.2.0.2 TKPROF file:

SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute      4      0.00       0.01          0          0          0           0
Fetch        8      0.39       0.41          2      11120          0           4
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       16      0.39       0.43          2      11120          0           4

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 68 
Number of plan statistics captured: 3

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=2780 pr=1 pw=0 time=0 us)
    990025     935684     998001   HASH JOIN  (cr=2780 pr=1 pw=0 time=190669 us cost=759 size=2000000 card=250000)
       995        966        999    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=21262 us cost=379 size=2000 card=500)(object id 72576)
       995        966        999    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=17005 us cost=379 size=2000 card=500)(object id 72577)

In the above we can see quite clearly that the number of rows returned by the second line in the execution plan returned a variable number of rows.  If we manually calculate the average number of rows found in the DBMS_XPLAN outputs, we find (990,000 + 998,000 + 819,000 + 25) / 4 = 701,756.25, and that is not the value shown by the “Rows (avg)” column.  The value shown by the “Rows (avg)” column apparently discards the last value from the average, thus it is (990,000 + 998,000 + 819,000) / 3 = 935,666.67 (slightly different from the displayed value due to rounding errors in the DBMS_XPLAN output).  Helpful, but it probably is not a good idea to throw out the value 25 when calculating the average when the rest of the numbers are so large.

Interestingly, the bottom of the 11.1.0.6 TKPROF output shows this:

Trace file: or112_ora_9393_SQL_10046_ROW_TEST.trc
Trace file compatibility: 11.01.00
Sort options: default

       1  session in tracefile.
      33  user  SQL statements in trace file.
     299  internal SQL statements in trace file.
     332  SQL statements in trace file.
      60  unique SQL statements in trace file.
    7857  lines in trace file.
 1286922860  elapsed seconds in trace file.

While the bottom of the 11.2.0.1 and 11.2.0.2 TKPROF outputs shows this:

Trace file: or112_ora_9393_SQL_10046_ROW_TEST.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       1  session in tracefile.
      33  user  SQL statements in trace file.
     299  internal SQL statements in trace file.
     332  SQL statements in trace file.
      60  unique SQL statements in trace file.
    7857  lines in trace file.
      22  elapsed seconds in trace file.

Notice the difference in the elapsed seconds!  I guess that over time some bugs are fixed, while others are introduced.

———————–

Updated (5 minutes after hitting the Publish button in WordPress):

Chris Antognini published, roughly an hour before my article based on the Twitter feed on orana.info, a blog entry on the same subject.  You can read his blog article here – his blog article is probably much more comprehensive than my blog article.


Actions

Information

13 responses

13 10 2010
Narendra

Charles,

Thanks for sharing this excellent information.
I am not really sure how this will make it easier for somebody trying to tune a query.
And the “elapsed time in trace file” bug is…what can I say ?
Unfortunately, that was the only statistic in TkProf that accounted for time spent on “SQL*Net message from client” and “SQL*Net message to client” wait events.

13 10 2010
Charles Hooper

Narendra,

Be sure to take a look at Chris Antognini’s article on the same subject – you will find a link to his article at the bottom of this blog article.

Regarding how this enhancement might be used to tune a query, it might not be too helpful for tuning a single query in isolation. However, assume that you have a program that builds a report. The program starts by retrieving a list of all customers, and then tries to identify the amount of money that each of those customers owes that is 30 days overdue, 60 days overdue, 90 days overdue, and more than 90 days overdue (I believe that this would be called an accounts receivable aging report). Now assume that the first customer in the list retrieved from the database has never actually placed an order. How might that situation affect the query execution plans when the optimizer generates execution plans that are efficient when the optimizer expects 1 or fewer rows to be returned for the initial set of bind variable values, but are terribly inefficient when other customers are processed? Or what if the first customer in the list represents 50% of the orders in the database, how might that affect the execution plans, and what impact will that have when the customer with a single order is encountered? For example, the SQL statement in the above test case generated an execution plan that looked like this:

--------------------------------------------------------------------------
| Id  | Operation              | Name         | Starts | E-Rows | A-Rows |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |              |      1 |        |      1 |
|   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |
|*  2 |   HASH JOIN            |              |      1 |    250K|    998K|
|*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |    999 |
|*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |    999 |
--------------------------------------------------------------------------

Note that in the above, the operation with ID 2 returned 998,000 rows. The same execution plan was later used again:

--------------------------------------------------------------------------
| Id  | Operation              | Name         | Starts | E-Rows | A-Rows |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |              |      1 |        |      1 |
|   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |
|*  2 |   HASH JOIN            |              |      1 |    250K|     25 |
|*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |      5 |
|*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |      5 |
--------------------------------------------------------------------------

Note that in the above, the operation with ID 2 returned 25 rows. Maybe with just 5 rows entering from each row source, rather than 999, it would make sense for the optimizer to select a nested loops join rather than a hash join. What should have appeared in the TKPROF summary

This enhancement to the TKPROF output will hopefully help to highlight cases where a SQL statement was optimized using one set of criteria (the bind variable values), and then substantially different criteria is used for later executions. What should have appeared in the TKPROF summary should at least serve as an indicator that the data volumes were a little variable:

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=2780 pr=1 pw=0 time=0 us)
    990025     701756     998001   HASH JOIN  (cr=2780 pr=1 pw=0 time=190669 us cost=759 size=2000000 card=250000)
       995        726        999    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=21262 us cost=379 size=2000 card=500)(object id 72576)
       995        726        999    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=17005 us cost=379 size=2000 card=500)(object id 72577)

Since the TKPROF output should have showed: “Number of plan statistics captured: 4″, we could perform a little math to get an idea of what the two other values might have been without manually digging through the trace file:
(990,025 + 998,001 + 2n) / 4 = 701,756
(1,988,026 + 2n) / 4 = 701,756
1,988,026 + 2n = 701,756 * 4
1,988,026 + 2n = 2,807,024
2n = 818,998
n = 409,499

So, the average of the two other values on the plan line with ID=2 is 409,499, yet the execution plan was optimized for 990,025. This might tell us that we need to take a closer look at the execution plan to make certain that it is the most appropriate execution plan for the bind variables that will be passed in. Maybe this also means that we should have a histogram on the column, with the expectation that adaptive cursor sharing will eventually generate more efficient execution plans as additional sets of bind variables are introduced.

I still need to determine why the TKPROF row summary output excluded the final execution.

14 10 2010
Egor Starostin

> I still need to determine why the TKPROF row summary output excluded the final execution.

It’s just absent in raw trace. Note that tkprof reports: ‘Number of plan statistics captured: 3′.
Simply add ‘exec dbms_monitor.session_trace_enable(plan_stat=>’ALL_EXECUTIONS’)’ after enabling trace

14 10 2010
Charles Hooper

Egor,

I have not yet manually reviewed the trace file to see if in fact the STAT lines for the fourth execution were not actually written to the trace file. In examining the test script, I included the following after each execution of the test SQL statement, which should have caused the cursor for the test SQL statement to close (the STAT lines are supposed to be written when the cursor is closed in Oracle Database releases prior to 11.1, but (by default) after the first execution starting with 11.1):

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

The catch here with the above reasoning is that after the third execution and attempted close of the cursor, the SQL statement *should* have been added to the session cursor cache, if enabled, and the cursor would not actually be closed (11.1 and above will write a CLOSE entry to the trace file when a cursor is actually closed). That could explain why the fourth execution did not cause the STAT lines to be written to the trace file (with the default value of PLAN_STAT in effect) – because the cursor was still open from the previous (third) execution, the fourth execution was not considered a “new first execution” of the cursor.

It will be at least 10 hours before I will be able to review the raw trace file. I strongly suspect that Egor has correctly answered the riddle of why the “Rows (avg)” column in the TKPROF output excluded the case where the plan line identified by ID 2 returned 25 rows.

If someone would like to try a couple of additional experiments using Oracle Database 11.1.0.6 or higher, see if there is a CLOSE entry in the raw trace file after the first, second, third (there probably will not be one here), and fourth (there probably will not be one here) execution of the test SQL statement, and the STAT lines are written only after the first, second, and third executions. Then, execute:

ALTER SESSION SET SESSION_CACHED_CURSORS=0;

and repeat the test case script. Again process the trace file with TKPROF from Oracle Database 11.2.0.2.

This is a very good example of how a test case script can explain how/why something works as it does.

14 10 2010
Charles Hooper

I have now had a chance to review the raw 10046 trace file – Egor is correct. My prediction that there would be no CLOSE entry after the third and fourth executions is incorrect. Here are the portions of the raw 10046 trace file that apply to the test case:

PARSING IN CURSOR #13 len=100 dep=0 uid=68 oct=3 lid=68 tim=1286922845411268 hv=3718770855 ad='257788a80' sqlid='6z03777fugw57'
SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1
END OF STMT
PARSE #13:c=0,e=422,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1286922845411267
BINDS #13:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2b9f6b961b38  bln=22  avl=02  flg=05
  value=5
EXEC #13:c=0,e=16909,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=765688747,tim=1286922845428289
FETCH #13:c=137979,e=153467,p=2,cr=2780,cu=0,mis=0,r=1,dep=0,og=1,plh=765688747,tim=1286922845581833
STAT #13 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=2780 pr=2 pw=0 time=0 us)'
STAT #13 id=2 cnt=990025 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=2780 pr=2 pw=0 time=222451 us cost=759 size=2000000 card=250000)'
STAT #13 id=3 cnt=995 pid=2 pos=1 obj=72576 op='INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=1 pw=0 time=27459 us cost=379 size=2000 card=500)'
STAT #13 id=4 cnt=995 pid=2 pos=2 obj=72577 op='INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=1 pw=0 time=17395 us cost=379 size=2000 card=500)'
FETCH #13:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=765688747,tim=1286922845594968
=====================
 
*** 2010-10-12 18:34:19.469
CLOSE #13:c=0,e=19,dep=0,type=0,tim=1286922859469005
 
PARSING IN CURSOR #15 len=100 dep=0 uid=68 oct=3 lid=68 tim=1286922860187185 hv=3718770855 ad='257788a80' sqlid='6z03777fugw57'
SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1
END OF STMT
PARSE #15:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=765688747,tim=1286922860187184
BINDS #15:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2b9f6bb525b0  bln=22  avl=02  flg=05
  value=1
EXEC #15:c=999,e=89,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=765688747,tim=1286922860187365
FETCH #15:c=118982,e=119348,p=0,cr=2780,cu=0,mis=0,r=1,dep=0,og=1,plh=765688747,tim=1286922860306760
STAT #15 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=2780 pr=0 pw=0 time=0 us)'
STAT #15 id=2 cnt=998001 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=2780 pr=0 pw=0 time=187133 us cost=759 size=2000000 card=250000)'
STAT #15 id=3 cnt=999 pid=2 pos=1 obj=72576 op='INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=18587 us cost=379 size=2000 card=500)'
STAT #15 id=4 cnt=999 pid=2 pos=2 obj=72577 op='INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=16217 us cost=379 size=2000 card=500)'
FETCH #15:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=765688747,tim=1286922860307080
CLOSE #15:c=0,e=10,dep=0,type=0,tim=1286922860307402
=====================
 
PARSING IN CURSOR #15 len=100 dep=0 uid=68 oct=3 lid=68 tim=1286922860320484 hv=3718770855 ad='257788a80' sqlid='6z03777fugw57'
SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1
END OF STMT
PARSE #15:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=765688747,tim=1286922860320483
BINDS #15:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2b9f6b8b54b0  bln=22  avl=02  flg=05
  value=95
EXEC #15:c=0,e=42,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=765688747,tim=1286922860320573
FETCH #15:c=102984,e=103706,p=0,cr=2780,cu=0,mis=0,r=1,dep=0,og=1,plh=765688747,tim=1286922860424305
STAT #15 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=2780 pr=0 pw=0 time=0 us)'
STAT #15 id=2 cnt=819025 pid=1 pos=1 obj=0 op='HASH JOIN  (cr=2780 pr=0 pw=0 time=162422 us cost=759 size=2000000 card=250000)'
STAT #15 id=3 cnt=905 pid=2 pos=1 obj=72576 op='INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=17741 us cost=379 size=2000 card=500)'
STAT #15 id=4 cnt=905 pid=2 pos=2 obj=72577 op='INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=17402 us cost=379 size=2000 card=500)'
FETCH #15:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=765688747,tim=1286922860424554
CLOSE #15:c=0,e=15,dep=0,type=1,tim=1286922860424806
=====================
 
PARSING IN CURSOR #13 len=100 dep=0 uid=68 oct=3 lid=68 tim=1286922860434659 hv=3718770855 ad='257788a80' sqlid='6z03777fugw57'
SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1
END OF STMT
PARSE #13:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=765688747,tim=1286922860434658
BINDS #13:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2b9f6b92efe8  bln=22  avl=03  flg=05
  value=995
EXEC #13:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=765688747,tim=1286922860434773
FETCH #13:c=37994,e=38483,p=0,cr=2780,cu=0,mis=0,r=1,dep=0,og=1,plh=765688747,tim=1286922860473285
FETCH #13:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=765688747,tim=1286922860473496
CLOSE #13:c=0,e=5,dep=0,type=3,tim=1286922860473722
=====================

There is a CLOSE entry after every execution, however the type= value differs. The first two executions have a type=0 entry, the third has a type=1 entry, and the fourth that does not have a set of STAT lines has a type=3 entry.

TYPE=0: cursor is actually closed.
TYPE=1: cursor is added to the session cursor cache without pushing an existing cursor out of the session cursor cache.
TYPE=2: cursor is added to the session cursor cache, in the process pushing an existing cursor out of the session cursor cache.
TYPE=3: cursor was already in the session cursor cache
(See Metalink/MOS Doc ID 39817.1 or page 284 of “Secrets of the Oracle Database”)

So, in summary, the average number of rows in the execution plan produced by TKPROF did not include the N1:=995 execution because the cursor was already in the session cursor cache, and the default behavior does not write the STAT lines on future executions when the cursor is held open.

One small mystery solved.

14 10 2010
Centinul

Charles –

I see these additional columns on an 11.2.0.1 database as well:

TKPROF: Release 11.2.0.1.0 - Development on Thu Oct 14 08:22:25 2010

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

Trace file: test_ora_3896.trc
Sort options: default

SQL ID: d6vwqbw6r2ffk
Plan Hash: 1388734953
SELECT USER 
FROM
 DUAL


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          0          0           1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 72  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.00          0.00
********************************************************************************
14 10 2010
Charles Hooper

Centinul,

Interesting output, what were the parameters specified for TKPROF? I wonder if I made a mistake somewhere? I used TKPROF from the base release of Oracle Database 11.2.0.1 on 64 bit Linux during my testing and did not see the “Rows (1st)”, “Rows (avg)”, and “Rows (max)” columns in the TKPROF output. Thanks for giving me another item to check in about 9 hours.

Anyone else have a comment about the Centinul’s output? Anyone else able to reproduce Centinul’s output?

14 10 2010
Centinul

I did not specify anything additional, just the input *.trc and output file names.

14 10 2010
Charles Hooper

I can’t explain how you received those extra columns. I processed the trace file with the 64 bit Windows version of 11.2.0.1:

C:\>tkprof or112_ora_9393_SQL_10046_ROW_TEST.trc or112_ora_9393_SQL_10046_ROW_TEST.txt
 
TKPROF: Release 11.2.0.1.0 - Development on Thu Oct 14 20:26:27 2010
 
Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

Inside the file:

SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1
 
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute      4      0.00       0.01          0          0          0           0
Fetch        8      0.39       0.41          2      11120          0           4
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       16      0.39       0.43          2      11120          0           4
 
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 68  
 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=2780 pr=2 pw=0 time=0 us)
 990025   HASH JOIN  (cr=2780 pr=2 pw=0 time=222451 us cost=759 size=2000000 card=250000)
    995    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=1 pw=0 time=27459 us cost=379 size=2000 card=500)(object id 72576)
    995    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=1 pw=0 time=17395 us cost=379 size=2000 card=500)(object id 72577)

One mystery still remaining.

15 10 2010
Taral

Hello Sir,

We can achieve this by getting level 16 trace dump in 11gr2 also. Here is the test case that you provided

http://desaitaral.wordpress.com/2010/10/15/tkprof-in-11gr2-%e2%80%93-new-rows-columns/

15 10 2010
Charles Hooper

Taral and Centinul,

I am officially stumped – I cannot reproduce your TKPROF output using the 11.2.0.1 TKPROF on 64 bit Linux, 64 bit Windows, nor 32 bit Windows. I tried enabling a 10046 at level 4 (bind variables) and level 16 (this is an invalid level, as far as I am aware, and appears to be the same as a level 1 trace). I also tried setting the STATISTICS_LEVEL to ALL at the session level, just to see if it had any impact.

This is the output that I received on 32 bit Windows with the 11.2.0.1 version of TKPROF from the 10046 trace at level 4:

SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute      4      0.00       0.00          0          0          0           0
Fetch        8      3.51       3.62          4      11120          0           4
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       16      3.51       3.63          4      11120          0           4

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

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=2780 pr=4 pw=0 time=0 us)
 990025   HASH JOIN  (cr=2780 pr=4 pw=0 time=2956504 us cost=789 size=2000000 card=250000)
    995    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=2 pw=0 time=199048 us cost=392 size=2000 card=500)(object id 70891)
    995    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=2 pw=0 time=172086 us cost=392 size=2000 card=500)(object id 70892)

********************************************************************************

This is the output that I received on 32 bit Windows with the 11.2.0.1 version of TKPROF from the 10046 trace at level 16:

SELECT /*+ GATHER_PLAN_STATISTICS */
  COUNT(*)
FROM
  T1,
  T2
WHERE
  T1.C2=T2.C2
  AND T1.C2= :N1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        4      0.00       0.00          0          0          0           0
Execute      4      0.00       0.00          0          0          0           0
Fetch        8      2.90       2.94          0      11120          0           4
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       16      2.90       2.94          0      11120          0           4

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

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=2780 pr=0 pw=0 time=0 us)
 990025   HASH JOIN  (cr=2780 pr=0 pw=0 time=2547184 us cost=789 size=2000000 card=250000)
    995    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=144005 us cost=392 size=2000 card=500)(object id 70891)
    995    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=153821 us cost=392 size=2000 card=500)(object id 70892)

********************************************************************************
15 10 2010
Taral

Bug 8328200 – Misleading or excessive STAT# lines for SQL_TRACE / 10046 [ID 8328200.8]

16 10 2010
Charles Hooper

Taral,

Thank you for the Metalink note. Interesting, so a session level 10046 trace at level 16 is equivalent to PLAN_STAT=>’ALL_EXECUTIONS’ with bind variables NOT captured and wait events NOT captured, although the Metalink note suggests that bind variables and wait events will be captured (I will have to double-check my trace file).

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s




Follow

Get every new post delivered to your Inbox.

Join 148 other followers

%d bloggers like this: