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 [...]