TKPROF in 11gR2 – New Rows Columns

In one of OTN thread I asked information about new columns in rowsource operation and Charles Hooper and Tom Kyte give some insight on this. I didn’t got chance to run test case provided by charles.

In my previous post I had mention same thing and here are some more things which i tried today.

I am using 11.2.0.1.0 Version and will update this page if i find something different in 11.2.0.2. Also, using windows 32 bit environment and Charles test case. Let’s get started.

Here is the test setup

drop table t1 purge;
drop table t2 purge;
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);

This is test script


VARIABLE N1 NUMBER
EXEC :N1:=1

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

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:=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:=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';

This is the output

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

  COUNT(*)
----------
    998001

TARAL@taral > SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------
SQL_ID  8ygbsrkt6sqd9, 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 | Use
------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT       |              |      1 |        |      1 |00:00:00.34 |    2780 |      4 |       |       |
|   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |00:00:00.34 |    2780 |      4 |       |       |
|*  2 |   HASH JOIN            |              |      1 |    250K|    998K|00:00:00.66 |    2780 |      4 |  1066K|  1066K|  42
|*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |    999 |00:00:00.04 |    1390 |      2 |       |       |
|*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |    999 |00:00:00.04 |    1390 |      2 |       |       |
------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("T1"."C2"="T2"."C2")
   3 - filter("T1"."C2"=:N1)
   4 - filter("T2"."C2"=:N1)

24 rows selected.

TARAL@taral >
TARAL@taral > EXEC :N1:=5

PL/SQL procedure successfully completed.

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

  COUNT(*)
----------
    990025

TARAL@taral >
TARAL@taral > SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------
SQL_ID  8ygbsrkt6sqd9, 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.30 |    2780 |    |  |          |
|   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |00:00:00.30 |    2780 |    |  |          |
|*  2 |   HASH JOIN            |              |      1 |    250K|    990K|00:00:00.65 |    2780 |  1066K|  1066K|  395K (0)|
|*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |    995 |00:00:00.04 |    1390 |    |  |          |
|*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |    995 |00:00:00.04 |    1390 |    |  |          |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("T1"."C2"="T2"."C2")
   3 - filter("T1"."C2"=:N1)
   4 - filter("T2"."C2"=:N1)

24 rows selected.

TARAL@taral >
TARAL@taral > EXEC :N1:=95

PL/SQL procedure successfully completed.

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

  COUNT(*)
----------
    819025

TARAL@taral > SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------
SQL_ID  8ygbsrkt6sqd9, 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.28 |    2780 |    |  |          |
|   1 |  SORT AGGREGATE        |              |      1 |      1 |      1 |00:00:00.28 |    2780 |    |  |          |
|*  2 |   HASH JOIN            |              |      1 |    250K|    819K|00:00:00.57 |    2780 |  1066K|  1066K|  379K (0)|
|*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |    905 |00:00:00.05 |    1390 |    |  |          |
|*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |    905 |00:00:00.05 |    1390 |    |  |          |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("T1"."C2"="T2"."C2")
   3 - filter("T1"."C2"=:N1)
   4 - filter("T2"."C2"=:N1)

24 rows selected.

TARAL@taral >
TARAL@taral > EXEC :N1:=995

PL/SQL procedure successfully completed.

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

  COUNT(*)
----------
        25

TARAL@taral > SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------
SQL_ID  8ygbsrkt6sqd9, 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|     25 |00:00:00.10 |    2780 |  1036K|  1036K|  351K (0)|
|*  3 |    INDEX FAST FULL SCAN| IND_T1_C1_C2 |      1 |    500 |      5 |00:00:00.05 |    1390 |    |  |          |
|*  4 |    INDEX FAST FULL SCAN| IND_T2_C1_C2 |      1 |    500 |      5 |00:00:00.06 |    1390 |    |  |          |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("T1"."C2"="T2"."C2")
   3 - filter("T1"."C2"=:N1)
   4 - filter("T2"."C2"=:N1)

24 rows selected.

So, from tkprof output here are the results which perfectely shows average rows as it had captured 4 occurences of the statement.

SQL ID: 8ygbsrkt6sqd9
Plan Hash: 765688747
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.98       1.02          4      11120          0           4
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       16      0.98       1.03          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: 89
Number of plan statistics captured: 4

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=2780 pr=1 pw=0 time=0 us)
    998001     701769     998001   HASH JOIN  (cr=2780 pr=1 pw=0 time=429843 us cost=761 size=2000000 card=250000)
       999        726        999    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=1 pw=0 time=33406 us cost=380 size=2000 card=500)(object id 74359)
       999        726        999    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=1 pw=0 time=33505 us cost=380 size=2000 card=500)(object id 74360)

As, default aggregation is turned on if we make it off and then see tkprof output it display all 4 execution

SQL ID: 8ygbsrkt6sqd9
Plan Hash: 765688747
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        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.01          0          0          0           0
Fetch        2      0.31       0.33          4       2780          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.31       0.35          4       2780          0           1

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=2780 pr=4 pw=0 time=0 us)
    998001     998001     998001   HASH JOIN  (cr=2780 pr=4 pw=0 time=596598 us cost=761 size=2000000 card=250000)
       999        999        999    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=2 pw=0 time=42664 us cost=380 size=2000 card=500)(object id 74359)
       999        999        999    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=2 pw=0 time=42415 us cost=380 size=2000 card=500)(object id 74360)

SQL ID: 8ygbsrkt6sqd9
Plan Hash: 765688747
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        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.29       0.30          0       2780          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.29       0.30          0       2780          0           1

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=2780 pr=0 pw=0 time=0 us)
    990025     990025     990025   HASH JOIN  (cr=2780 pr=0 pw=0 time=596958 us cost=761 size=2000000 card=250000)
       995        995        995    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=42866 us cost=380 size=2000 card=500)(object id 74359)
       995        995        995    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=42866 us cost=380 size=2000 card=500)(object id 74360)

SQL ID: 8ygbsrkt6sqd9
Plan Hash: 765688747
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        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.26       0.27          0       2780          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.26       0.27          0       2780          0           1

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=2780 pr=0 pw=0 time=0 us)
    819025     819025     819025   HASH JOIN  (cr=2780 pr=0 pw=0 time=525793 us cost=761 size=2000000 card=250000)
       905        905        905    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=47686 us cost=380 size=2000 card=500)(object id 74359)
       905        905        905    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=48364 us cost=380 size=2000 card=500)(object id 74360)

SQL ID: 8ygbsrkt6sqd9
Plan Hash: 765688747
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        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.10       0.10          0       2780          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.10       0.10          0       2780          0           1

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=2780 pr=0 pw=0 time=0 us)
        25         25         25   HASH JOIN  (cr=2780 pr=0 pw=0 time=24 us cost=761 size=2000000 card=250000)
         5          5          5    INDEX FAST FULL SCAN IND_T1_C1_C2 (cr=1390 pr=0 pw=0 time=408 us cost=380 size=2000 card=500)(object id 74359)
         5          5          5    INDEX FAST FULL SCAN IND_T2_C1_C2 (cr=1390 pr=0 pw=0 time=376 us cost=380 size=2000 card=500)(object id 74360)

About these ads

About Taral
I am Rookie to Oracle Technology so let's see where it goes

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

%d bloggers like this: