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 Reply