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.
Recent Comments