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:
select
DBMS_SQLTUNE.REPORT_SQL_MONITOR(
session_id=>sys_context('userenv','sid'),
report_level=>'ALL') as report
from dual;
11gR1, Execution Plans, Oracle, Performance, SQL Tuning, Troubleshooting
Trackbacks
Comments
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.
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?
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).
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.
Greg,
I’m a little late in reading it, but thanks very much for this awesome post.
Jerry Cunningham
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’.