Real-Time SQL Monitoring

Posted on , updated on by Yannick Jaquier
Oracle

Table of contents

Preamble

This post is on my number one 11gR2 new functionality i.e. Real-Time SQL Monitoring. I used to see a similar feature a long time back in a pretty expensive product called Precise for Oracle. Now all is available for free in Grid Control, well for free, not exactly as the feature is part of Oracle Database Tuning Pack.

I came back to Oracle documentation and found that possible value for CONTROL_MANAGEMENT_PACK_ACCESS are { NONE | DIAGNOSTIC | DIAGNOSTIC+TUNING } means that you cannot buy Tuning pack alone. Clearly clarified by Oracle in CONTROL_MANAGEMENT_PACK_ACCESS initialization parameter documentation: A license for DIAGNOSTIC is required for enabling the TUNING pack. STATISTICS_LEVEL need to be on TYPICAL minimum but I rate as standard way of working.

Then Real-Time SQL Monitoring will monitor all SQL statements that run in parallel or have consumed more than 5 seconds of CPU or IO Time in a single execution.

Information is graphically available in Grid Control or with command line using V$SQL_MONITOR and V$SQL_PLAN_MONITOR tables and DBMS_SQLTUNE.REPORT_SQL_MONITOR and DBMS_SQLTUNE.REPORT_SQL_MONITOR_LIST functions.

MONITOR and NO_MONITOR hints can be used to respectively force or forbid SQL statement to be monitored.

I have done my testing on Red Hat Enterprise Linux Server release 5.5 (Tikanga) running Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 – 64bit Production.

Grid Control

The Real-Time SQL Monitoring link is available in database performance page. Do not hesitate to righ mouse click to change graph options and left mouse click to order SQL statements. If you hover on rows data you get additional information. A report ordered by elapsed time:

sql_monitoring1
sql_monitoring1

If you click on Oracle account name you move to Top Activity usual page to get more precise information on the session (if still running) and you are even able to submit a SQL Tuning task…

If you click on sql_id you get more precise information on the session activity and wait events. You even have sub panel to see this activity and wait events graphically:

sql_monitoring2
sql_monitoring2

Command line

Let’s see how Oracle is getting all those information. If you wish to list the top 20 SQL having the longest elapsed time you may use something like (you may also order by physical reads):

SQL> SET lines 200
SQL> SET pages 1000
SQL> SELECT *
     FROM
       (SELECT status,
         --username,
         sql_id,
         sql_exec_id,
         TO_CHAR(sql_exec_start,'dd-mon-yyyy hh24:mi:ss') AS sql_exec_start,
         ROUND(elapsed_time/1000000)                      AS "Elapsed (s)",
         ROUND(cpu_time    /1000000)                      AS "CPU (s)",
         buffer_gets,
         ROUND(physical_read_bytes /(1024*1024)) AS "Phys reads (MB)",
         ROUND(physical_write_bytes/(1024*1024)) AS "Phys writes (MB)"
       FROM v$sql_monitor
       ORDER BY elapsed_time DESC
       )
     WHERE rownum<=20;
 
STATUS              SQL_ID        SQL_EXEC_ID SQL_EXEC_START                Elapsed (s)    CPU (s) BUFFER_GETS Phys reads (MB) Phys writes (MB)
------------------- ------------- ----------- ----------------------------- ----------- ---------- ----------- --------------- ----------------
DONE                br73cuz2mqx4c    16777934 10-jan-2012 04:09:08                  271         28      708877            2269                0
DONE                8aukpq4gxcrf9    16777272 10-jan-2012 04:00:54                  261         27      708860            2278                0
DONE                23snaz93bxuk6    16777344 10-jan-2012 04:05:16                  227         27      729883            2269                0
DONE                8aukpq4gxcrf9    16777274 10-jan-2012 04:30:30                  221         27      719018            2234                0
DONE                23snaz93bxuk6    16777352 10-jan-2012 06:02:27                  214         26      695902            2341                0
DONE                23snaz93bxuk6    16777346 10-jan-2012 04:34:12                  210         26      699418            2248                0
DONE                23snaz93bxuk6    16777377 10-jan-2012 12:16:20                  194         24      695011            3307                0
DONE                81c1xvnmsyr64    16777301 10-jan-2012 09:00:57                  192         28      694963            2769                0
DONE                8aukpq4gxcrf9    16777273 10-jan-2012 04:16:50                  187         26      698430            2282                0
DONE                8aukpq4gxcrf9    16777216 10-jan-2012 12:01:22                  186         28      695011            3261                0
DONE                81c1xvnmsyr64    16777282 10-jan-2012 04:13:41                  186         30      696572            2278                0
DONE                81c1xvnmsyr64    16777281 10-jan-2012 03:57:44                  185         30      704999            2268                0
DONE                23snaz93bxuk6    16777345 10-jan-2012 04:19:58                  184         26      699093            2282                0
DONE                8aukpq4gxcrf9    16777216 10-jan-2012 12:30:55                  181         25      695011            3321                0
DONE                br73cuz2mqx4c    16777935 10-jan-2012 04:23:05                  180         27      698720            2279                0
DONE                8aukpq4gxcrf9    16777288 10-jan-2012 08:00:16                  178         24      694947            2625                0
DONE                81c1xvnmsyr64    16777286 10-jan-2012 05:09:27                  176         27      706666            2269                0
DONE                23snaz93bxuk6    16777359 10-jan-2012 07:44:39                  175         25      705790            2594                0
DONE                23snaz93bxuk6    16777373 10-jan-2012 11:15:01                  173         29      695048            3144                0
DONE                2d945y6a1k9xc    16777216 10-jan-2012 16:41:14                  173         23      695085            4342                0
 
20 ROWS selected.

Remark:
As explained in Oracle documentation the key columns of this table are sql_id, sql_exec_start and sql_exec_id. Yes a column date is part of key columns which will not ease further queries. Sql_id and sql_exec_start columns are not enough because we may imagine having the same SQL statement running at exact same time in two different session so the third column sql_exec_id for uniqueness.

If I take the first SQL statement of this list and I display more interesting columns (please refer to documentation for complete list of columns):

SQL> SELECT ROUND(elapsed_time    /1000000)     AS "Elapsed (s)",
     ROUND(cpu_time             /1000000,3)   AS "CPU (s)",
     ROUND(queuing_time         /1000000,3)   AS "Queuing (s)",
     ROUND(application_wait_time/1000000,3)   AS "Appli wait (s)",
     ROUND(concurrency_wait_time/1000000,3)   AS "Concurrency wait (s)",
     ROUND(cluster_wait_time    /1000000,3)   AS "Cluster wait (s)",
     ROUND(user_io_wait_time    /1000000,3)   AS "User io wait (s)",
     ROUND(physical_read_bytes  /(1024*1024)) AS "Phys reads (MB)",
     ROUND(physical_write_bytes /(1024*1024)) AS "Phys writes (MB)",
     buffer_gets                              AS "Buffer gets",
     ROUND(plsql_exec_time/1000000,3)         AS "Plsql exec (s)",
     ROUND(java_exec_time /1000000,3)         AS "Java exec (s)"
     FROM v$sql_monitor
     WHERE sql_id = '81c1xvnmsyr64'
     AND sql_exec_id = 16777270
     AND sql_exec_start=TO_DATE('11-jan-2012 05:59:27','dd-mon-yyyy hh24:mi:ss');
 
Elapsed (s)    CPU (s) Queuing (s) Appli wait (s) Concurrency wait (s) CLUSTER wait (s) USER io wait (s) Phys reads (MB) Phys writes (MB) Buffer gets Plsql EXEC (s) JAVA EXEC (s)
----------- ---------- ----------- -------------- -------------------- ---------------- ---------------- --------------- ---------------- ----------- -------------- -------------
        394     29.641           0              0                    0                0          374.313            2668                0      711673              0             0

As they say in Oracle documentation we can join V$SQL_MONITOR with V$ACTIVE_SESSION_HISTORY to get more accurate information:

SQL> SELECT NVL(wait_class,'CPU') AS wait_class, NVL(event,'CPU') AS event, COUNT(*)
     FROM v$active_session_history a
     WHERE sql_id = '81c1xvnmsyr64'
     AND sql_exec_id = 16777270
     AND sql_exec_start=TO_DATE('11-jan-2012 05:59:27','dd-mon-yyyy hh24:mi:ss')
     GROUP BY wait_class, event;
 
WAIT_CLASS                                                       EVENT                                                            COUNT(*)
---------------------------------------------------------------- ---------------------------------------------------------------- ----------
CPU                                                              CPU                                                                      19
USER I/O                                                         db FILE scattered read                                                  169
USER I/O                                                         db FILE sequential read                                                 205

CPU information is more accurate in V$SQL_MONITOR while for I/O we are able to re-conciliate information. 169+205 = 374 and the sample time in V$ACTIVE_SESSION_HISTORY is 1 second so 374 (s). We can even say as Grid Control does that I/O waits are made of 45% (169/374*100) on db file scattered read wait event and 55% on db file sequential read wait event.

Anyway some wait events logged in V$ACTIVE_SESSION_HISTORY do not appear in V$SQL_MONITOR. The one I have often seen is Other, but based on your database activity you may see others:

SQL> SELECT DISTINCT NVL(wait_class,'CPU') AS wait_class FROM v$active_session_history ORDER BY 1;
 
WAIT_CLASS
----------------------------------------------------------------
Administrative
Application
CPU
COMMIT
Concurrency
Configuration
Network
Other
SYSTEM I/O
USER I/O
 
10 ROWS selected.

Those wait events that do not appear in V$SQL_MONITOR must be added to total execution time to compute database activity percentage. As it is not the case in our SQL statement example we can say that execution time is 6 minutes and 34 seconds and that SQL statement did 7.34% (29.641/(29.641+374.313)*100) of CPU and 92.66% of I/O. You can also use:

NUMTODSINTERVAL(elapsed_time/1000000,'SECOND') AS "Elapsed",

To display elapsed time in day hour:min:ss.ss.

Same as V$SQL_PLAN you may query V$SQL_PLAN_MONITOR to get additional information on your SQL statement (plan_time column is quite interesting) and even join it with V$ACTIVE_SESSION_HISTORY, add sql_plan_line_id in the join, to even get more accurate information per line of your explain plan:

SQL> col PLAN FOR a150
SQL> SELECT
     RPAD('(' || p.plan_line_ID || ' ' || NVL(p.plan_parent_id,'0') || ')',8) || '|' ||
     RPAD(LPAD (' ', 2*p.plan_DEPTH) || p.plan_operation || ' ' || p.plan_options,60,'.') ||
     NVL2(p.plan_object_owner||p.plan_object_name, '(' || p.plan_object_owner|| '.' || p.plan_object_name || ') ', '') ||
     NVL2(p.plan_COST,'Cost:' || p.plan_COST,'') || ' ' ||
     NVL2(p.plan_bytes||p.plan_CARDINALITY,'(' || p.plan_bytes || ' bytes, ' || p.plan_CARDINALITY || ' rows)','') || ' ' ||
     NVL2(p.plan_partition_start || p.plan_partition_stop,' PStart:' ||  p.plan_partition_start || ' PStop:' || p.plan_partition_stop,'') ||
     NVL2(p.plan_time, p.plan_time || '(s)','') AS PLAN
     FROM v$sql_plan_monitor p
     WHERE sql_id = '81c1xvnmsyr64'
     AND sql_exec_id = 16777270
     AND sql_exec_start=TO_DATE('11-jan-2012 05:59:27','dd-mon-yyyy hh24:mi:ss')
     ORDER BY p.plan_line_id, p.plan_parent_id;
 
PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------
(0 0)   |UPDATE STATEMENT ...........................................
(1 0)   |  UPDATE ...................................................(DATALOAD.MN_HT_CONTRACT_LI_VER)
(2 1)   |    TABLE ACCESS FULL.......................................(DATALOAD.MN_HT_CONTRACT_LI_VER) COST:189008 (24 bytes, 12 ROWS) 2269(s)
SQL> SELECT NVL(wait_class,'CPU') AS wait_class, NVL(event,'CPU') AS event, sql_plan_line_id, COUNT(*)
     FROM v$active_session_history a
     WHERE sql_id = '81c1xvnmsyr64'
     AND sql_exec_id = 16777270
     AND sql_exec_start=TO_DATE('11-jan-2012 05:59:27','dd-mon-yyyy hh24:mi:ss')
     GROUP BY wait_class,event,sql_plan_line_id;
 
WAIT_CLASS                                                       EVENT                                                            SQL_PLAN_LINE_ID   COUNT(*)
---------------------------------------------------------------- ---------------------------------------------------------------- ---------------- ----------
CPU                                                              CPU                                                                             2         19
USER I/O                                                         db FILE scattered read                                                          2        169
USER I/O                                                         db FILE sequential read                                                         2        205

As you see it starts to be complex, and fortunately Oracle is providing DBMS_SQLTUNE.REPORT_SQL_MONITOR function that do for you all those computations:

SQL> SET lines 200
SQL> SET pages 1000
SQL> SET LONG 999999
SQL> SET longchunksize 200
SQL> SELECT dbms_sqltune.report_sql_monitor(sql_id=>'81c1xvnmsyr64',sql_exec_id=>16777270,sql_exec_start=> TO_DATE('11-jan-2012 05:59:27','dd-mon-yyyy hh24:mi:ss'),report_level=>'ALL') AS report FROM dual;
 
REPORT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL Monitoring Report
 
SQL Text
------------------------------
UPDATE mn_ht_contract_li_ver SET program_id = 74745 WHERE program_id = 138956
 
Global Information
------------------------------
 Status              :  DONE
 Instance ID         :  1
 SESSION             :  DATALOAD (1128:57577)
 SQL ID              :  81c1xvnmsyr64
 SQL Execution ID    :  16777270
 Execution Started   :  01/11/2012 05:59:27
 FIRST Refresh TIME  :  01/11/2012 05:59:31
 LAST Refresh TIME   :  01/11/2012 06:06:01
 Duration            :  394s
 Module/Action       :  JDBC Thin Client/-
 Service             :  SYS$USERS
 Program             :  JDBC Thin Client
 
Global Stats
========================================================
| Elapsed |   Cpu   |    IO    | Buffer | Read | Read  |
| TIME(s) | TIME(s) | Waits(s) |  Gets  | Reqs | Bytes |
========================================================
|     404 |      30 |      374 |   712K | 191K |   3GB |
========================================================
 
SQL PLAN Monitoring Details (PLAN Hash VALUE=2222756215)
========================================================================================================================================================================
| Id |      Operation       |         Name          |  ROWS   | COST |   TIME    | START  | Execs |   ROWS   | Read | Read  | Activity |        Activity Detail        |
|    |                      |                       | (Estim) |      | Active(s) | Active |       | (Actual) | Reqs | Bytes |   (%)    |          (# samples)          |
========================================================================================================================================================================
|  0 | UPDATE STATEMENT     |                       |         |      |           |        |     1 |          |      |       |          |                               |
|  1 |   UPDATE             | MN_HT_CONTRACT_LI_VER |         |      |           |        |     1 |          |      |       |          |                               |
|  2 |    TABLE ACCESS FULL | MN_HT_CONTRACT_LI_VER |      12 | 189K |       394 |     +1 |     1 |        0 | 189K |   3GB |   100.00 | Cpu (19)                      |
|    |                      |                       |         |      |           |        |       |          |      |       |          | db FILE scattered read (169)  |
|    |                      |                       |         |      |           |        |       |          |      |       |          | db FILE sequential read (205) |
========================================================================================================================================================================

Remark:
The type parameter of this function may produce an HTML report and when set to ACTIVE produce a Grid Control like page, needed resources will be downloaded from Internet.

While the ACTIVE format has poor interest versus Grid Control (when you have it of course) the HTML report has a pretty good looking:

sql_monitor_html1

The second Real-Time SQL Monitoring function of DBMS_SQLTUNE package is pretty interesting as giving a history list of the sql_id execution over time:

SQL> SET lines 180
SQL> SET pages 1000
SQL> SET LONG 999999
SQL> SET longchunksize 200
SQL> SELECT dbms_sqltune.report_sql_monitor_list(sql_id=>'81c1xvnmsyr64',report_level=>'ALL') AS report FROM dual;
 
REPORT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 
 
                                                                                SQL Monitoring List
                                                                               =====================
 
 
===================================================================================================================================================================================
| Status | Duration |    SQL Id     | EXEC Id  |        START        |   USER   |   Module/Action   | Dop | DB TIME | IOs  |                       SQL Text                       |
===================================================================================================================================================================================
| DONE   |     146s | 81c1xvnmsyr64 | 16777296 | 01/11/2012 12:29:46 | DATALOAD | JDBC Thin Clien/- |     |    155s | 215K | UPDATE mn_ht_contract_li_ver SET program_id = 74745  |
|        |          |               |          |                     |          |                   |     |         |      | WHERE program_id = 138956                            |
| DONE   |     145s | 81c1xvnmsyr64 | 16777295 | 01/11/2012 12:11:19 | DATALOAD | JDBC Thin Clien/- |     |    155s | 215K | UPDATE mn_ht_contract_li_ver SET program_id = 74745  |
|        |          |               |          |                     |          |                   |     |         |      | WHERE program_id = 138956                            |
| DONE   |     158s | 81c1xvnmsyr64 | 16777294 | 01/11/2012 11:59:47 | DATALOAD | JDBC Thin Clien/- |     |    167s | 214K | UPDATE mn_ht_contract_li_ver SET program_id = 74745  |
|        |          |               |          |                     |          |                   |     |         |      | WHERE program_id = 138956                            |
| DONE   |     172s | 81c1xvnmsyr64 | 16777293 | 01/11/2012 11:43:03 | DATALOAD | JDBC Thin Clien/- |     |    182s | 212K | UPDATE mn_ht_contract_li_ver SET program_id = 74745  |
|        |          |               |          |                     |          |                   |     |         |      | WHERE program_id = 138956                            |
| DONE   |     238s | 81c1xvnmsyr64 | 16777292 | 01/11/2012 11:29:44 | DATALOAD | JDBC Thin Clien/- |     |    247s | 211K | UPDATE mn_ht_contract_li_ver SET program_id = 74745  |
|        |          |               |          |                     |          |                   |     |         |      | WHERE program_id = 138956                            |
| DONE   |     192s | 81c1xvnmsyr64 | 16777291 | 01/11/2012 11:11:19 | DATALOAD | JDBC Thin Clien/- |     |    202s | 211K | UPDATE mn_ht_contract_li_ver SET program_id = 74745  |
|        |          |               |          |                     |          |                   |     |         |      | WHERE program_id = 138956                            |
| DONE   |     206s | 81c1xvnmsyr64 | 16777290 | 01/11/2012 10:59:41 | DATALOAD | JDBC Thin Clien/- |     |    215s | 210K | UPDATE mn_ht_contract_li_ver SET program_id = 74745  |
|        |          |               |          |                     |          |                   |     |         |      | WHERE program_id = 138956                            |
| DONE   |     125s | 81c1xvnmsyr64 | 16777289 | 01/11/2012 10:41:11 | DATALOAD | JDBC Thin Clien/- |     |    134s | 209K | UPDATE mn_ht_contract_li_ver SET program_id = 74745  |
|        |          |               |          |                     |          |                   |     |         |      | WHERE program_id = 138956                            |
| DONE   |     122s | 81c1xvnmsyr64 | 16777288 | 01/11/2012 10:29:36 | DATALOAD | JDBC Thin Clien/- |     |    132s | 208K | UPDATE mn_ht_contract_li_ver SET program_id = 74745  |
|        |          |               |          |                     |          |                   |     |         |      | WHERE program_id = 138956                            |
.
.
.
| DONE   |     240s | 81c1xvnmsyr64 | 16777253 | 01/11/2012 01:40:31 | DATALOAD | JDBC Thin Clien/- |     |    250s | 173K | UPDATE mn_ht_contract_li_ver SET program_id = 74745  |
|        |          |               |          |                     |          |                   |     |         |      | WHERE program_id = 138956                            |
===================================================================================================================================================================================

Conclusion

With the trivial example I have given we easily see that this SQL statement is just killing database performance. When looking at global list we can even see that our top 20 by elapsed time is 100% made of two updates on same table and are both performing a FTS. We also see that their database activity percentage is almost on User I/O (and so a bit of CPU to handle them). Here the remedy is quite simple: one or two indexes creation(s).

While looking on Internet I have also seen that SQL Developer (3.1 beta in my case) has also a SQL Monitor interface (Tool -> Monitor SQL …). Then you get a select on V$SQL_MONITOR that you can order on any column. And when you right mouse click you can choose Show SQL Details and have more fine details of the selected statement.

As mentioned by Tanel Poder you do not need to go back to DBA_HIST_SQLBIND to have bind variables values and you can directly query V$SQL_MONITOR.BINDS_XML column.

About Post Author

Yannick Jaquier

administrator

Find more about me on social media.

See author's posts

Share the knowledge!

Related Posts:

5 thoughts on “Real-Time SQL Monitoring”

  2. vadim says:

    How about RAC databases with multiple instances? SCAN gets us connected to one particular instance of the clustered database. If session is running on another instance, how do you leverage SQL Developer for SQL Monitoring?
    THank you,
    vr

    • Yannick Jaquier says:

      Hi Vr,

      Thanks for stopping by… I’m not 100% sure to get your point, in case of RAC you have multiple instances but still one database. So if you use SQL*Developer to access figures whatever the instance you will be connected through SCAN the content of V$SQL_PLAN or V$SQL_PLAN_MONITOR, for example, will be the same… In parallelism information you may as well see number of instances used in parallel queries…

      Thanks, Yannick.

  3. Abel Floor says:

    Some codes on the provided images are quite difficult to understand. Nonetheless, it helps a lot in acquiring knowledge about SQL monitoring.

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes:

<a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>