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.
- SQL Monitoring Report 1
- SQL Monitoring Report 2
- SQL Monitoring Report 3
- SQL Monitoring Report 4
- SQL Monitoring Report 5
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
[...] Structured Data post about a terrific SQL tuning monitor in 11g. [...]
[...] believe me, he’s more than capable of that if you want!). Next, Greg Rahn showed an example of Oracle 11g: Real-Time SQL Monitoring Using DBMS_SQLTUNE.REPORT_SQL_MONITOR. Very nice, indeed, although I suppose it requires the Tuning Pack. I’ll definitely be including [...]
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.
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.
[...] REPORT_SQL_MONITOR function to get this info nicely formatted. Greg Rahn has written a good blog entry about [...]
[...] nice post on from Greg Rahn from the Real-World Performance group at Oracle Corporation in his post Oracle 11g: Real-Time SQL Monitoring Using DBMS_SQLTUNE.REPORT_SQL_MONITOR you need in some parameters set to some values to enable this feature + you have to use a hint to [...]
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?
@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?
[...] Greg Rahn has a good post on this feature with examples of the html output of the dbms_sqltune.report_sql_monitor function. Tags: 11g, Oracle, Tuning Category: Uncategorized | Comment (RSS) | Trackback [...]
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 6159So 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).
Kerry,
you can use dbms_debug_jdwp.current_session_serial to get serial#
[...] Other9 rows selected.Just a bit of fun, but nowhere near as much fun as Real Time SQL Monitoring. Now *that’s* a feature worth upgrading for! Posted by Doug Burns Comments: (0) Trackbacks: [...]
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
@Gerhard
I do not have the tables/data any more. I would suggest downloading the TPC-DS kit. It includes tables, data generator and 99 queries to play with.
[...] This requires the license of the Diagnostic and Tuning Packs. For more detail, have a look at this blog entry. Blogged by Porus Homi Havewala (પોરસ હોમી [...]
Greg,
I’m a little late in reading it, but thanks very much for this awesome post.
Jerry Cunningham
[...] tools I've seen since I started working with Oracle too long ago. I was first aware of it via Greg Rahn's blog post.To date I've used it via DB Control for demos and it's sweet, but one of the problems with any demo [...]
[...] could use DBMS_SQLTUNE.REPORT_SQL_MONITOR to generate html/text reports . Greg Rahn has written a post describing it in [...]
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’.
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?
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.
[...] links: Performance Tuning Guide Kerry Osborne – Real time SQL Monitoring Greg Rahn – Real-time SQl Monitoring Using… GA_googleAddAttr("AdOpt", "1"); GA_googleAddAttr("Origin", "other"); [...]
slowly but surely. :)
[...] learned that using a graphical tool like SQL Monitor is nothing to be ashamed of. I discovered SQL Monitor few month back when the customer wanted periodic updates about progress of a long running rebuild [...]
[...] for some time and has been blogging about it for several years. Here’s one from Jan of 2008: Oracle 11g: Real-Time SQL Monitoring Using DBMS_SQLTUNE.REPORT_SQL_MONITOR Category: Exadata, Oracle | Comment (RSS) [...]
[...] 9, 2011By Greg RahnAs my loyal readers will know, I have been a big (maybe BIG) fan of the SQL Monitor Report since it’s introduction in 11g. It would not surprise me if I have looked at over 1000 SQL [...]
[...] Ref: Nicely portrayed in graphical manner by Greg Rahn, Oracle 11g: Real-Time SQL Monitoring Using DBMS_SQLTUNE.REPORT_SQL_MONITOR [...]