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.
Leave a comment