Oracle 11g Real Time SQL Monitoring
One of the interesting new features of 11gR1 is the automatic tracking of long running SQL statements. Oracle calls this new feature Real-Time SQL Monitoring. There a couple of parameters that must be set to enable this behavior.
- Parameter STATISTICS_LEVEL must be set to ALL or TYPICAL (the default)
- Parameter CONTROL_MANAGEMENT_PACK_ACCESS must be set to DIAGNOSTIC+TUNING (the default)
Not all statements are tracked. Only statements that are consider long running invoke this new facility. The following two conditions qualify a statement for tracking:
- The statement must take more than 5 seconds (or so) to execute
- Or the statement is executed in parallel mode
There are a couple of new views that have been added to expose this feature. They are V$SQL_MONITOR and V$SQL_PLAN_MONITOR. The data appears to be updated once per second and it contains very detailed information including row counts for each step in the plan. These views contain a record of each execution of the qualifying statements. While it is possible to query these views directly, a function (REPORT_SQL_MONITOR) has been provided in the DBMS_SQLTUNE package that produces a nicely formated report in html, xml, or (my favorite) text format . Here is a script that queries the V$SQL_MONITOR view (sql_monitor.sql) and another that executes the afore mentioned function (report_sql_monitor.sql). Here is an example of their usage:
> sqlplus / as sysdba
SQL*Plus: Release 11.1.0.7.0 - Production on Tue Oct 21 08:47:26 2008
Copyright (c) 1982, 2008, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
SQL> connect
Enter user-name: kso
Enter password:
Connected.
SQL> @whoami
USERNAME USER# SID SERIAL# PREV_HASH_VALUE SCHEMANAME OS_PID
--------------- ---------- ---------- ---------- --------------- ------------------------------ ------------------------
KSO 89 146 9626 4128301241 KSO 3596
SQL> @find_sql
Enter value for sql_text: %avg%skew%col1 >%
Enter value for sql_id:
SQL_ID CHILD PLAN_HASH EXECS AVG_ETIME AVG_LIO SQL_TEXT
------------- ------ ---------- ---------- ------------- ------------ -----------------------------------------
ftgja8q5449mb 0 568322376 4 19.29 162,424 select avg(pk_col) from kso.skew where co
SQL> @sql_monitor
Enter value for sid:
Enter value for sql_id: ftgja8q5449mb
Enter value for sql_exec_id:
SID SQL_ID SQL_EXEC_ID SQL_EXEC_START PLAN_HASH_VALUE ETIME BUFFER_GETS DISK_READS
---- ------------- ----------- -------------------- --------------- ------------- ----------- ----------
83 ftgja8q5449mb 16777216 17-Oct-08 13:19:33 568322376 42.87 162297 162295
83 16777217 17-Oct-08 13:21:13 11.65 162297 162294
83 16777218 17-Oct-08 13:21:26 10.58 162297 162294
83 16777219 17-Oct-08 13:24:50 10.69 162297 162294
83 16777220 17-Oct-08 13:26:02 10.63 162297 162294
83 16777221 17-Oct-08 13:26:24 10.54 162297 162294
83 16777222 17-Oct-08 13:36:54 10.91 162297 162294
83 16777223 17-Oct-08 13:37:12 10.05 162297 162294
83 16777224 17-Oct-08 13:45:23 12.22 162297 162294
83 16777225 17-Oct-08 13:46:49 9.88 162297 162294
84 16777226 20-Oct-08 10:03:16 37.12 162297 162294
84 16777227 20-Oct-08 10:45:46 10.47 162297 162294
141 16777228 20-Oct-08 14:51:46 18.84 162297 162294
109 16777229 21-Oct-08 08:52:24 10.68 162297 162294
102 16777230 21-Oct-08 11:47:29 10.72 162297 162294
102 16777231 21-Oct-08 11:50:55 10.80 162297 162294
102 16777232 21-Oct-08 11:51:42 10.56 162297 162294
17 rows selected.
SQL> @avgskew
AVG(PK_COL)
-----------
16093749.3
SQL> @sql_monitor
Enter value for sid:
Enter value for sql_id: ftgja8q5449mb
Enter value for sql_exec_id:
SID SQL_ID SQL_EXEC_ID SQL_EXEC_START PLAN_HASH_VALUE ETIME BUFFER_GETS DISK_READS
---------- ------------- ----------- -------------------- --------------- ---------- ----------- ----------
83 ftgja8q5449mb 16777216 17-Oct-08 13:19:33 568322376 42.867348 162297 162295
83 16777217 17-Oct-08 13:21:13 11.65255 162297 162294
83 16777218 17-Oct-08 13:21:26 10.584698 162297 162294
83 16777219 17-Oct-08 13:24:50 10.692678 162297 162294
83 16777220 17-Oct-08 13:26:02 10.629618 162297 162294
83 16777221 17-Oct-08 13:26:24 10.542389 162297 162294
83 16777222 17-Oct-08 13:36:54 10.908706 162297 162294
83 16777223 17-Oct-08 13:37:12 10.053868 162297 162294
83 16777224 17-Oct-08 13:45:23 12.216788 162297 162294
83 16777225 17-Oct-08 13:46:49 9.877616 162297 162294
84 16777226 20-Oct-08 10:03:16 37.121513 162297 162294
84 16777227 20-Oct-08 10:45:46 10.471579 162297 162294
141 16777228 20-Oct-08 14:51:46 18.838655 162297 162294
109 16777229 21-Oct-08 08:52:24 10.681204 162297 162294
102 16777230 21-Oct-08 11:47:29 10.721737 162297 162294
102 16777231 21-Oct-08 11:50:55 10.801564 162297 162294
102 16777232 21-Oct-08 11:51:42 10.562701 162297 162294
146 16777237 21-Oct-08 12:09:54 10.429318 162297 162294
18 rows selected.
SQL> !date
Tue Oct 21 12:09:59 CDT 2008
SQL> @whoami
USERNAME USER# SID SERIAL# PREV_HASH_VALUE SCHEMANAME OS_PID
--------------- ---------- ---------- ---------- --------------- ------------------------------ ------------------------
KSO 89 146 9629 1029988163 KSO 11421
SQL> -- with no parameters should give me back most recent long running statement by my current session
SQL>
SQL> @report_sql_monitor
Enter value for sid:
Enter value for sql_id:
Enter value for sql_exec_id:
REPORT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
SQL Text
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
select avg(pk_col) from kso.skew where col1 > :"SYS_B_0"
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Global Information
Status : DONE (ALL ROWS)
Instance ID : 1
Session ID : 146
SQL ID : ftgja8q5449mb
SQL Execution ID : 16777237
Plan Hash Value : 568322376
Execution Started : 10/21/2008 12:09:54
First Refresh Time : 10/21/2008 12:09:58
Last Refresh Time : 10/21/2008 12:10:04
---------------------------------------------------------
| Elapsed | Cpu | IO | Fetch | Buffer | Reads |
| Time(s) | Time(s) | Waits(s) | Calls | Gets | |
---------------------------------------------------------
| 14 | 10 | 3.90 | 1 | 162K | 162K |
---------------------------------------------------------
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 | | | 5 | 7 | +4 | 1 | 1 | | |
| 1 | SORT AGGREGATE | | 1 | | 7 | +4 | 1 | 1 | | |
| 2 | TABLE ACCESS FULL | SKEW | 1233 | 5 | 7 | +4 | 1 | 32000K | | |
============================================================================================================================
SQL> -- with the SID I should get the most recent execution by the specified SID
SQL>
SQL> @report_sql_monitor
Enter value for sid: 83
Enter value for sql_id:
Enter value for sql_exec_id:
REPORT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
SQL Text
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
select avg(pk_col) from kso.skew where col1 > :"SYS_B_0"
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Global Information
Status : DONE (ALL ROWS)
Instance ID : 1
Session ID : 83
SQL ID : ftgja8q5449mb
SQL Execution ID : 16777225
Plan Hash Value : 568322376
Execution Started : 10/17/2008 13:46:49
First Refresh Time : 10/17/2008 13:46:53
Last Refresh Time : 10/17/2008 13:46:59
---------------------------------------------------------
| Elapsed | Cpu | IO | Fetch | Buffer | Reads |
| Time(s) | Time(s) | Waits(s) | Calls | Gets | |
---------------------------------------------------------
| 13 | 10 | 3.63 | 1 | 162K | 162K |
---------------------------------------------------------
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 | | | 5 | 7 | +4 | 1 | 1 | | |
| 1 | SORT AGGREGATE | | 1 | | 7 | +4 | 1 | 1 | | |
| 2 | TABLE ACCESS FULL | SKEW | 1233 | 5 | 7 | +4 | 1 | 32000K | | |
============================================================================================================================
Note: The key for the V$SQL_MONITOR view consists of the SESSION_ID, SESSION_SERIAL, SQL_ID, and SQL_EXEC_ID fields. The documentation says that the SQL_EXEC_START field is also part of the key but that doesn’t appear to be the case. It appears that the SQL_EXEC_START field contains a time stamp that is not necessary to identify a unique row.
Greg Rahn has a good post on this feature with examples of the html output of the dbms_sqltune.report_sql_monitor function.
[…] links: Performance Tuning Guide Kerry Osborne – Real time SQL Monitoring Greg Rahn – Real-time SQl Monitoring Using… GA_googleAddAttr("AdOpt", "1"); […]
[…] is the Real Time SQL Monitoring capabilities. I did a post about it a couple of years ago here: Oracle 11g Real Time SQL Monitoring In that post I talked about a procedure (DBMS_SQLTUNE.REPORT_SQL_MONITOR) that provides a very […]
Hello Kerry,
When a procedure/package is run consisting of more than 2 or 3 sql statements is there a way to find the details of it apart from using the EMconsole?I had seen once in grid in the sql monitor section that it shows the package name and the list of sqlid’s associated with it along with the status of each.
Hi Shanawaz,
The only time I’ve seen sql_id show up in the wait event column on SQL Monitor output is when a program opens a cursor, fetches some records, and then does a bunch of other stuff – including running some other SQL statements. If you can send me an example I’d be happy to have a look.
Kerry
Great scripts! Thanks.