set echo on
set long 10000000
set longchunksize 10000000 set linesize 200
set pagesize 1000
exec dbms_lock.sleep(8);
select
dbms_sqltune.report_sql_monitor(sql_id=>'dkz7v96ym42c6',report_level
=>'ALL') from dual;
4) After you are ready in both the sessions, press [Enter] in session 1 to start the
execution of the ep_session_issue.sh script. Note: Do not wait. Proceed with the next step immediately.
Session 1:
---
[oracle@edrsr33p1-orcl Explain_Plan]$ ./ep_session_issue.sh
SQL*Plus: Release 11.1.0.6.0 - Production on Wed Apr 2 20:12:47 2008 Copyright (c) 1982, 2007, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining and Real Application Testing options
SQL>
SQL> set timing on SQL>
SQL> select count(*) from test t1, test t2 where t1.c=t2.c and t1.c=1;
5) In session 2, enter return to start the execution of the ep_monitor.sql script.
After the execution, enter “/” and go back to your SQL*Plus session as many times as necessary until session 1 is done with its execution. What do you observe?
a) You can see that session 1 uses NESTED LOOPS on top of two INDEX RANGE SCANS to execute the query. It takes approximately 47 seconds to execute session 1’s query. The time depends on your environment. The big advantage of SQL Monitoring is that you can clearly see which steps in the execution plan take most of the resources. In this case, you clearly see that you do only one scan of the index, and that for each row returned, you execute another index scan to probe.
This is not really efficient. Also there is no costs information for this monitored plan.
Oracle Internal & Or acle Academy Use Only
Session 2:
---
SQL> @ep_monitor
SQL> set long 10000000
SQL> set longchunksize 10000000 SQL> set linesize 200
SQL> set pagesize 1000 SQL>
SQL> exec dbms_lock.sleep(8);
PL/SQL procedure successfully completed.
SQL>
SQL> select
dbms_sqltune.report_sql_monitor(sql_id=>'dkz7v96ym42c6',report_level
=>'ALL') from dual;
DBMS_SQLTUNE.REPORT_SQL_MONITOR(SQL_ID=>'DKZ7V96YM42C6',SESSION_ID=>
:SESSID,REPORT_LEVEL=>'ALL')
--- SQL Monitoring Report
SQL Text
---
select count(*) from test t1, test t2 where t1.c=t2.c and t1.c=1 ---
Global Information
Status : EXECUTING Instance ID : 1
Session ID : 138
SQL ID : dkz7v96ym42c6 SQL Execution ID : 16777222 Plan Hash Value : 1643938535
Execution Started : 04/02/2008 20:12:46 First Refresh Time : 04/02/2008 20:12:54 Last Refresh Time : 04/02/2008 20:12:56 ---
| Elapsed | Cpu | Other | Buffer |
| Time(s) | Time(s) | Waits(s) | Gets | ---
| 8.10 | 8.09 | 0.01 | 134K | ---
SQL Plan Monitoring Details
====================================================================
=================================================================
Oracle Internal & Or acle Academy Use Only
| Id | Operation | Name | Rows | Cost | Time | Start | Starts | Rows | Activity | Activity Detail |
| | | | (Estim) | |
Active(s) | Active | | (Actual) | (percent) | (sample #)
|
====================================================================
=================================================================
| 0 | SELECT STATEMENT | | | |
| | 1 | | | |
| 1 | SORT AGGREGATE | | | | 1 | +6 | 1 | 0 | 12.50 | Cpu (1) |
| -> 2 | NESTED LOOPS | | | | 3 | +8 | 1 | 79096K | | |
| -> 3 | INDEX RANGE SCAN | TEST_C_INDX | | | 3 | +8 | 1 | 3954 | | |
| -> 4 | INDEX RANGE SCAN | TEST_C_INDX | | | 9 | +2 | 3955 | 79096K | 87.50 | Cpu (7) |
====================================================================
=================================================================
SQL>
SQL> /
DBMS_SQLTUNE.REPORT_SQL_MONITOR(SQL_ID=>'DKZ7V96YM42C6',SESSION_ID=>
:SESSID,REPORT_LEVEL=>'ALL')
--- SQL Monitoring Report
SQL Text
---
select count(*) from test t1, test t2 where t1.c=t2.c and t1.c=1 ---
Global Information
Status : EXECUTING Instance ID : 1
Session ID : 138
SQL ID : dkz7v96ym42c6 SQL Execution ID : 16777222 Plan Hash Value : 1643938535
Execution Started : 04/02/2008 20:12:46 First Refresh Time : 04/02/2008 20:12:54 Last Refresh Time : 04/02/2008 20:12:58 ---
| Elapsed | Cpu | Other | Buffer |
| Time(s) | Time(s) | Waits(s) | Gets | ---
| 10 | 10 | 0.01 | 167K | ---
Oracle Internal & Or acle Academy Use Only
SQL Plan Monitoring Details
====================================================================
=================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Starts | Rows | Activity | Activity Detail |
| | | | (Estim) | |
Active(s) | Active | | (Actual) | (percent) | (sample #)
|
====================================================================
=================================================================
| 0 | SELECT STATEMENT | | | |
| | 1 | | | |
| 1 | SORT AGGREGATE | | | | 1 | +6 | 1 | 0 | 10.00 | Cpu (1) |
| -> 2 | NESTED LOOPS | | | | 5 | +8 | 1 | 96151K | | |
| -> 3 | INDEX RANGE SCAN | TEST_C_INDX | | | 5 | +8 | 1 | 4807 | | |
| -> 4 | INDEX RANGE SCAN | TEST_C_INDX | | | 11 | +2 | 4808 | 96151K | 90.00 | Cpu (9) |
====================================================================
=================================================================
SQL> /
DBMS_SQLTUNE.REPORT_SQL_MONITOR(SQL_ID=>'DKZ7V96YM42C6',SESSION_ID=>
:SESSID,REPORT_LEVEL=>'ALL')
--- SQL Monitoring Report
SQL Text
---
select count(*) from test t1, test t2 where t1.c=t2.c and t1.c=1 ---
Global Information
Status : EXECUTING Instance ID : 1
Session ID : 138
SQL ID : dkz7v96ym42c6 SQL Execution ID : 16777222 Plan Hash Value : 1643938535
Execution Started : 04/02/2008 20:12:46 First Refresh Time : 04/02/2008 20:12:54 Last Refresh Time : 04/02/2008 20:13:00 ---
| Elapsed | Cpu | Other | Buffer |
Oracle Internal & Or acle Academy Use Only
| Time(s) | Time(s) | Waits(s) | Gets | ---
| 12 | 12 | 0.01 | 201K | ---
SQL Plan Monitoring Details
====================================================================
=================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Starts | Rows | Activity | Activity Detail |
| | | | (Estim) | |
Active(s) | Active | | (Actual) | (percent) | (sample #)
|
====================================================================
=================================================================
| 0 | SELECT STATEMENT | | | |
| | 1 | | | |
| 1 | SORT AGGREGATE | | | | 1 | +6 | 1 | 0 | 8.33 | Cpu (1) |
| -> 2 | NESTED LOOPS | | | | 7 | +8 | 1 | 113M | | |
| -> 3 | INDEX RANGE SCAN | TEST_C_INDX | | | 7 | +8 | 1 | 5664 | | |
| -> 4 | INDEX RANGE SCAN | TEST_C_INDX | | | 13 | +2 | 5665 | 113M | 91.67 | Cpu (11) |
====================================================================
=================================================================
SQL> /
DBMS_SQLTUNE.REPORT_SQL_MONITOR(SQL_ID=>'DKZ7V96YM42C6',SESSION_ID=>
:SESSID,REPORT_LEVEL=>'ALL')
--- SQL Monitoring Report
SQL Text
---
select count(*) from test t1, test t2 where t1.c=t2.c and t1.c=1 ---
Global Information
Status : EXECUTING Instance ID : 1
Session ID : 138
SQL ID : dkz7v96ym42c6 SQL Execution ID : 16777222 Plan Hash Value : 1643938535
Execution Started : 04/02/2008 20:12:46 First Refresh Time : 04/02/2008 20:12:54
Oracle Internal & Or acle Academy Use Only
Last Refresh Time : 04/02/2008 20:13:08 ---
| Elapsed | Cpu | Other | Buffer |
| Time(s) | Time(s) | Waits(s) | Gets | ---
| 20 | 20 | 0.04 | 334K | ---
SQL Plan Monitoring Details
====================================================================
=================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Starts | Rows | Activity | Activity Detail |
| | | | (Estim) | |
Active(s) | Active | | (Actual) | (percent) | (sample #)
|
====================================================================
=================================================================
| 0 | SELECT STATEMENT | | | |
| | 1 | | | |
| 1 | SORT AGGREGATE | | | | 1 | +6 | 1 | 0 | 5.00 | Cpu (1) |
| -> 2 | NESTED LOOPS | | | | 15 | +8 | 1 | 182M | | |
| -> 3 | INDEX RANGE SCAN | TEST_C_INDX | | | 15 | +8 | 1 | 9082 | | |
| -> 4 | INDEX RANGE SCAN | TEST_C_INDX | | | 21 | +2 | 9083 | 182M | 95.00 | Cpu (19) |
====================================================================
=================================================================
SQL> /
DBMS_SQLTUNE.REPORT_SQL_MONITOR(SQL_ID=>'DKZ7V96YM42C6',SESSION_ID=>
:SESSID,REPORT_LEVEL=>'ALL')
--- SQL Monitoring Report
SQL Text
---
select count(*) from test t1, test t2 where t1.c=t2.c and t1.c=1 ---
Global Information
Status : EXECUTING Instance ID : 1
Session ID : 138
SQL ID : dkz7v96ym42c6
Oracle Internal & Or acle Academy Use Only
SQL Execution ID : 16777222 Plan Hash Value : 1643938535
Execution Started : 04/02/2008 20:12:46 First Refresh Time : 04/02/2008 20:12:54 Last Refresh Time : 04/02/2008 20:13:17 ---
| Elapsed | Cpu | Other | Buffer |
| Time(s) | Time(s) | Waits(s) | Gets | ---
| 28 | 28 | 0.05 | 468K | ---
SQL Plan Monitoring Details
====================================================================
=================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Starts | Rows | Activity | Activity Detail |
| | | | (Estim) | |
Active(s) | Active | | (Actual) | (percent) | (sample #)
|
====================================================================
=================================================================
| 0 | SELECT STATEMENT | | | |
| | 1 | | | |
| 1 | SORT AGGREGATE | | | | 1 | +6 | 1 | 0 | 3.45 | Cpu (1) |
| -> 2 | NESTED LOOPS | | | | 24 | +8 | 1 | 250M | | |
| -> 3 | INDEX RANGE SCAN | TEST_C_INDX | | | 24 | +8 | 1 | 12518 | | |
| -> 4 | INDEX RANGE SCAN | TEST_C_INDX | | | 30 | +2 | 12519 | 250M | 96.55 | Cpu (28) |
====================================================================
=================================================================
SQL> /
DBMS_SQLTUNE.REPORT_SQL_MONITOR(SQL_ID=>'DKZ7V96YM42C6',SESSION_ID=>
:SESSID,REPORT_LEVEL=>'ALL')
--- SQL Monitoring Report
SQL Text
---
select count(*) from test t1, test t2 where t1.c=t2.c and t1.c=1 ---
Global Information
Oracle Internal & Or acle Academy Use Only
Status : EXECUTING Instance ID : 1
Session ID : 138
SQL ID : dkz7v96ym42c6 SQL Execution ID : 16777222 Plan Hash Value : 1643938535
Execution Started : 04/02/2008 20:12:46 First Refresh Time : 04/02/2008 20:12:54 Last Refresh Time : 04/02/2008 20:13:29 ---
| Elapsed | Cpu | Other | Buffer |
| Time(s) | Time(s) | Waits(s) | Gets | ---
| 40 | 40 | 0.06 | 669K | ---
SQL Plan Monitoring Details
====================================================================
=================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Starts | Rows | Activity | Activity Detail |
| | | | (Estim) | |
Active(s) | Active | | (Actual) | (percent) | (sample #)
|
====================================================================
=================================================================
| 0 | SELECT STATEMENT | | | |
| | 1 | | | |
| 1 | SORT AGGREGATE | | | | 35 | +6 | 1 | 0 | 4.88 | Cpu (2) |
| -> 2 | NESTED LOOPS | | | | 36 | +8 | 1 | 353M | | |
| -> 3 | INDEX RANGE SCAN | TEST_C_INDX | | | 36 | +8 | 1 | 17663 | | |
| -> 4 | INDEX RANGE SCAN | TEST_C_INDX | | | 42 | +2 | 17664 | 353M | 95.12 | Cpu (39) |
====================================================================
=================================================================
SQL> /
DBMS_SQLTUNE.REPORT_SQL_MONITOR(SQL_ID=>'DKZ7V96YM42C6',SESSION_ID=>
:SESSID,REPORT_LEVEL=>'ALL')
--- SQL Monitoring Report
SQL Text
---
select count(*) from test t1, test t2 where t1.c=t2.c and t1.c=1
Oracle Internal & Or acle Academy Use Only
---
Global Information
Status : DONE (ALL ROWS) Instance ID : 1
Session ID : 138
SQL ID : dkz7v96ym42c6 SQL Execution ID : 16777222 Plan Hash Value : 1643938535
Execution Started : 04/02/2008 20:12:46 First Refresh Time : 04/02/2008 20:12:54 Last Refresh Time : 04/02/2008 20:13:34
---
| Elapsed | Cpu | Other | Fetch | Buffer |
| Time(s) | Time(s) | Waits(s) | Calls | Gets | ---
| 46 | 46 | 0.06 | 1 | 760K | ---
SQL Plan Monitoring Details
====================================================================
===============================================================
| Id | Operation | Name | Rows | Cost | Time
| Start | Starts | Rows | Activity | Activity Detail |
| | | | (Estim) | |
Active(s) | Active | | (Actual) | (percent) | (sample #)
|
====================================================================
===============================================================
| 0 | SELECT STATEMENT | | | | 1 | +48 | 1 | 1 | | |
| 1 | SORT AGGREGATE | | | | 43 | +6 | 1 | 1 | 4.35 | Cpu (2) |
| 2 | NESTED LOOPS | | | | 41 | +8 | 1 | 400M | | |
| 3 | INDEX RANGE SCAN | TEST_C_INDX | | | 41 | +8 | 1 | 20000 | | |
| 4 | INDEX RANGE SCAN | TEST_C_INDX | | | 47 | +2 | 20000 | 400M | 95.65 | Cpu (44) |
====================================================================
===============================================================
SQL>
6) After approximately 47 seconds (depending on your environment), you should see the following output in your session 1:
Session 1:
---
Oracle Internal & Or acle Academy Use Only
…
COUNT(*) --- 400000000
Elapsed: 00:00:47.21 SQL>
SQL> exit;
Disconnected from Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining and Real Application Testing options
[oracle@edrsr33p1-orcl Explain_Plan]$
7) From session 1, connect as the EP user in the SQL*Plus session.
Session 1:
---
[oracle@edrsr33p1-orcl Explain_Plan]$ sqlplus ep/ep
SQL*Plus: Release 11.1.0.6.0 - Production on Wed Apr 2 20:14:03 2008 Copyright (c) 1982, 2007, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production
With the Partitioning, Oracle Label Security, OLAP, Data Mining and Real Application Testing options
SQL>
8) Use PLAN_TABLE to determine the execution plan of the query that was executed in step 4. What do you observe?
select count(*) from test t1, test t2 where t1.c=t2.c and t1.c=1;