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.

4 Comments

  1. [...] links: Performance Tuning Guide Kerry Osborne – Real time SQL Monitoring Greg Rahn – Real-time SQl Monitoring Using… GA_googleAddAttr("AdOpt", "1"); [...]

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

  3. Shanawaz says:

    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.

  4. osborne says:

    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

Leave a Reply