Oracle 11g: Real-Time SQL Monitoring Using DBMS_SQLTUNE.REPORT_SQL_MONITOR

Many times a DBA wants to know where a SQL statement is in its execution plan and where the time is being spent. There are a few ways to find out this information, but an 11g new feature makes gathering this information extremely easy. Oracle 11g Real-Time SQL Monitoring allows you to monitor the performance of SQL statements while they are executing as well as see the breakdown of time and resources used for recently completed statements. It is on by default when STATISTICS_LEVEL is set to to ALL or TYPICAL (the default value) and monitors statements that consume more than 5 seconds of CPU or IO time, as well as any parallel execution (PQ, PDML, PDDL). One can override the default actions by using the MONITOR or NO_MONITOR hint. The 11g Documentation has a text version of a SQL Monitor Report but the report output can be html, text or xml.

Real-Time SQL Monitoring Report Walkthrough

To demonstrate the Real-Time SQL Monitoring feature, I started a parallel query and every 60 seconds or so I captured a Real-Time SQL Monitoring report in html format using DBMS_SQLTUNE.REPORT_SQL_MONITOR. Reports 1 through 4 are captures while the query is executing, Report 5 is a post execution capture. Each of the below links will open in a new window.

As you browse through the SQL Monitoring Reports you will see which operation(s) of the execution plan is/are active, how long they have been active, as well as wait events and database time. You can mouse over each of the colored bars to get more detail. As the SQL Monitoring Report notes, this query was executed using a DOP of 8, but there were 16 slaves, 2 sets of 8 which act in a producer/consumer pair. In the SQL Plan Monitoring Details section you can see which operations were performed by each slave set, as well as the QC, by the colors of the Id column. This report also makes it very easy to see that there was some skew in the work for the first slave set. Slaves p003 and p004 performed much more IO than the other slaves and it stands out by the length of the colored bars. The “Active Period” column allows one to see which operations were active, for how long, and at what point of the overall execution. I feel this report gives a great visualization of the execution and a visual breakdown of DB Time and Wait Activity. I’m quite certain I will be using this feature frequently when troubleshooting execution plans and as well as db time drill down.

I’m really excited about Real-Time SQL Monitoring’s ability to capture the Estimated and Actual number of rows for each row source. This eliminates the need to run a query with a GATHER_PLAN_STATISTICS hint as I discussed in my post: Troubleshooting Bad Execution Plans.

More Information

There are a few slides on Real-Time SQL Monitoring in the DBAs’ New Best Friend: Advanced SQL Tuning Features of Oracle Database 11g (starting on page 27) presentation from OOW 2007. As the presentation mentions, Real-Time SQL Monitoring will also be a part of 11g Enterprise Manager Grid Control.

Addendum (2008/02/12)

If you want to get a SQL Monitor report for a statement you just ran in your session (similar to dbms_xplan.display_cursor) then use this command:

set pagesize 0 echo off timing off linesize 1000 trimspool on trim on long 2000000 longchunksize 2000000
select DBMS_SQLTUNE.REPORT_SQL_MONITOR(
   session_id=>sys_context('userenv','sid'),
   report_level=>'ALL') as report
from dual;

Or if you want to generate the EM Active SQL Monitor Report (my recommendation) from any SQL_ID you can use:

set pagesize 0 echo off timing off linesize 1000 trimspool on trim on long 2000000 longchunksize 2000000 feedback off
spool sqlmon_4vbqtp97hwqk8.html
select dbms_sqltune.report_sql_monitor(type=>'EM', sql_id=>'4vbqtp97hwqk8') monitor_report from dual;
spool off

27 comments

  1. Pingback: Back to work links « I’m just a simple DBA on a complex production system
  2. Pingback: 8 Useful Technical Posts … - Sinoptix
  3. Paul

    What a great report. Really amazing. Graphical and numeric/bubble timing information available from the execution plan and for the PQ sessions – stacked graphs for cpu, io, buffer gets, db time. Oracle is making it too easy. It also would be great if they could add buttons to allow you to reveal [+] and hide [-] the filter and access predicates for each step of the plan – it’s great to see the predicates adjacent to the job step. Not so relevant for your example, but for most of the queries I see it would be a useful addition to the report.

  4. Tony

    This looks somewhat like the output of the HOTSOS profiler, at least in concept. It is nice addition and a step in the right direction to more wait event performance analysis.

  5. Pingback: Advanced Oracle Troubleshooting Guide, Part 6: Understanding Oracle execution plans with os_explain « Tanel Poder’s blog: Core IT for geeks and pros
  6. Pingback: AMIS Technology blog » Blog Archive » Real-Time SQL Monitoring (Oracle 11.1.0.7.0) - May I Present The GUI…
  7. Kerry Osborne

    Greg,

    Quick question for you on the report script (it’s really a digression). The REPORT_SQL_MONITOR function accepts a SERIAL# parameter as well as the SID. Do you know of a way to obtain the SERIAL# via SYS_CONTEXT or some other means?

  8. Greg Rahn

    @Kerry

    I do not believe that SYS_CONTEXT will return the SERIAL#. You can join to V$SESSION using SYS_CONTEXT(‘USERENV’,’SID’)=V$SESSION.SID though to get it quite easily. Could you explain what scenario you need SERIAL# as well?

  9. Pingback: Kerry Osborne’s Blog » Blog Archive » Oracle 11g Real Time SQl Monitoring
  10. Kerry Osborne

    Hi Greg,

    Thanks for the quick response. On busy systems, SID’s are frequently reused so it is necessary to specify the serial# as well to ensure that we’re looking at the correct session. Here’s an example (I hope the formatting is OK – if not have a look at a posting I just did on the subject at kerryosborne.oracle-guy.com)

    SQL> @sql_monitor
    SQL> break on sql_id on plan_hash_value
    SQL> col sql_exec_start for a20
    SQL> select sid, session_serial# serial#, sql_id, sql_exec_id, to_char(sql_exec_start,'DD-Mon-YY HH24:MI:SS') sql_exec_start, sql_plan_hash_value plan_hash_value,
      2  elapsed_time/1000000 etime, buffer_gets, disk_reads
      3  from v$sql_monitor
      4  where sid like nvl('&sid',sid)
      5  and sql_id like nvl('&sql_id',sql_id)
      6  and sql_exec_id like nvl('&sql_exec_id',sql_exec_id)
      7  -- order by sql_id, sql_exec_id
      8  order by sql_exec_start
      9  /
    Enter value for sid: 102
    Enter value for sql_id:
    Enter value for sql_exec_id:
    
     SID    SERIAL# SQL_ID        SQL_EXEC_ID SQL_EXEC_START       PLAN_HASH_VALUE         ETIME BUFFER_GETS DISK_READS
    ---- ---------- ------------- ----------- -------------------- --------------- ------------- ----------- ----------
     102          7 0r3nf6rvn31z0    16777217 17-Oct-08 09:40:14        3781965855           .01           0          0
     102         14                  16777218 17-Oct-08 09:42:00                             .02           3          0
     102         16 dbmt8tuqdmhkr    16777218 17-Oct-08 09:42:00        3777092978           .02           3          0
     102         20 8szmwam7fysa3    16777217 17-Oct-08 22:00:10        2976124318         11.17        2608       2167
     102       3189                  16777242 18-Oct-08 10:02:08                            5.07        2157       2080
     102       3189                  16777243 18-Oct-08 10:02:13                            3.96        2291       1876
     102       3818 9hu31jpkxnmcu    16777219 18-Oct-08 14:02:24        2828798618          3.87        1131       4565
     102      12380 bxrvdy7xcx1uz    16777216 20-Oct-08 22:00:20        3965205907          4.14        6420       6275
     102      12380 1gd6hj6au5nn3    16777216 20-Oct-08 22:00:24        3965205907          6.53       12464      11924
     102      12380 chbj552h35n8t    16777216 20-Oct-08 22:00:31        3965205907         12.05       24884      22823
     102      12380 akcnuthdm0nax    16777216 20-Oct-08 22:00:45        4108509612         15.95       55125      52013
     102      12380                  16777217 20-Oct-08 22:01:01        3371650501         16.07       48190          0
     102      12380                  16777218 20-Oct-08 22:01:17        3885211065         16.22       78885      78415
     102      12380                  16777219 20-Oct-08 22:01:33         234802133         16.29       70999          0
     102      12380                  16777220 20-Oct-08 22:01:49        2330810755         15.08       74847        617
     102      12380                  16777221 20-Oct-08 22:02:05        4108509612         31.41      150585     149566
     102      12380                  16777222 20-Oct-08 22:02:36        3371650501         31.39      112369          0
     102      12380                  16777223 20-Oct-08 22:03:07        3885211065         30.36      162304     163522
     102      12380                  16777224 20-Oct-08 22:03:38         234802133         31.39       74847      15682
     102      12380                  16777225 20-Oct-08 22:04:09        2330810755         31.37       74847       9249
     102      12380                  16777226 20-Oct-08 22:04:41        4108509612         61.71      162304     182260
     102      12380                  16777227 20-Oct-08 22:05:42        3371650501         60.71      216863          0
     102      12380                  16777228 20-Oct-08 22:06:43        3885211065         60.69      162304     194318
     102      12380                  16777229 20-Oct-08 22:07:44         234802133         61.76       74847      42521
     102      12380                  16777230 20-Oct-08 22:08:45        2330810755         60.72       74847      26045
     102      12380                  16777231 20-Oct-08 22:09:46        4108509612        120.43      162304     216771
     102      12380                  16777232 20-Oct-08 22:11:47        3371650501        121.48      437847          0
     102      12380                  16777233 20-Oct-08 22:13:48        3885211065        121.46      162304     249492
     102      12380                  16777234 20-Oct-08 22:15:49         234802133        120.45       74847      92853
     102      12380                  16777235 20-Oct-08 22:17:50        2330810755        121.50       74847      60744
     102      12380                  16777236 20-Oct-08 22:19:51        4108509612         22.28      159623     159662
     102      15594 ftgja8q5449mb    16777230 21-Oct-08 11:47:29         568322376         10.72      162297     162294
     102      15594                  16777231 21-Oct-08 11:50:55                           10.80      162297     162294
     102      15594                  16777232 21-Oct-08 11:51:42                           10.56      162297     162294
     102      15596                  16777240 21-Oct-08 13:03:59                           10.78      162297     162294
     102      15596 53sz5gs699tqv    16777217 21-Oct-08 13:39:41         717147039          7.02      162297     162294
    
    36 rows selected.
    
    SQL> @whoami
    
    USERNAME             USER#  SID    SERIAL# PREV_HASH_VALUE SCHEMANAME                     OS_PID
    --------------- ---------- ---- ---------- --------------- ------------------------------ ------------------------
    KSO                     89  102      15598      1029988163 KSO                            6159
    

    So you can see that there have been many sessions with SID 102 over the last several days that executed long running statements. Executing the report_sql_monitor function with session_id=>sys_context(‘userenv’,’sid’) will return data for the most recently monitored statement by any session with the SID 102, but it won’t be my current session because it hasn’t executed a long running statement.

    It would be nice if we could add another where clause that said session_serial=>sys_context(‘userenv’,’serial#’), but unfortunately that option doesn’t seem to exist. I was hoping you might know of an undocumented option. This would be handy in a number of places by the way. For example, when connected as sysdba, the audsid is not unique and so there is no way with sys_context (that I am aware of) to determine which session is actually mine if there are more than one sysdba connections. Anyway, I worked around the issue with the report_sql_monitor function by doing a subquery something like this -

    session_serial=>(select serial# from v$session where audsid=sys_context(‘userenv’,’sessionid’))

    I hope this makes sense (and the formatting isn’t too bad).

  11. Pingback: Doug's Oracle Blog
  12. Gerhard

    Hi Greg,
    maybe I’m little late in this post. So my Question: Is it possible to get the table definition and/or the data you used for this test? I’would reproduce this (especially the parallel query with a long run) to learn more about this new famouse feature from oracle 11g.
    Thank in advance
    Gerhard

  13. Pingback: Oracle Enterprise Manager Grid Control: Scripts Guru shows Database control
  14. Jerry Cunningham

    Greg,

    I’m a little late in reading it, but thanks very much for this awesome post.

    Jerry Cunningham

  15. Pingback: Real-Time SQL Monitoring in SQL Developer - Doug's Oracle Blog
  16. Pingback: AskDba.org Weblog » 11gR2: Monitoring SQL Plan Execution from Oracle Enterprise Manager
  17. Benoit Dageville

    In Oracle database 11.2, we also introduced HTML active reports for SQL monitoring. Active reports are a new type of HTML reports showing more information than the vanilla HTML reports. Also, look and feel is really improved since the content of these reports is displayed using the same interactive UI as the one in Oracle Entreprise Manager.

    For more information on SQL Monitor active reports, see http://www.oracle.com/technology/products/manageability/database/sqlmonitor.html. You will find few examples there like the example below reporting on the execution of a parallel index create:

    http://www.oracle.com/technology/products/manageability/database/active_reports/samples/faq_create_index.html

    Active reports can be directly generated from SQL*Plus command line, like the regular HTML report. Simply use ‘ACTIVE’ instead of ‘HTML’.

  18. Pingback: Real Time SQL Monitoring « OraStory
  19. Pingback: Important Things I’ve Learned at Hotsos 2011 | The Pythian Blog
  20. Pingback: Kerry Osborne’s Oracle Blog » Blog Archive » Realtime SQL Monitoring – Designed with Exadata in Mind – Kerry Osborne’s Oracle Blog
  21. Richard Hobbis

    I’ve built an APEX application that includes the ACTIVE report in an for a selected SQL_ID. This is great and works really well, but there’s one thing I’d like to change – the ‘reveal’ animation it uses when it displays the report. At the moment it reveals the content from the centre and expand outwards, taking about 2 seconds to display the entire report. Can this be reduced or removed altogether?

  22. Greg Rahn

    I believe that is due to the loading of the swf file and the passing of the xml to it. I can check with the developer though to confirm.

  23. Pingback: Crowdsourcing Active SQL Monitor Reports | Structured Data
  24. Pingback: SQL Monitoring in 11g « Shrikant's Blog

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s