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

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.