Oracle Scratchpad

April 6, 2018

SQL Monitor

Filed under: Execution plans,Oracle,Troubleshooting — Jonathan Lewis @ 7:50 am BST Apr 6,2018

I’ve mentioned the SQL Monitor report from time to time as a very useful way of reviewing execution plans – the feature is automatically enabled by parallel execution and by queries that are expected to take more than a few seconds to complete, and the inherent overheads of monitoring are less than the impact of enabling the rowsource execution statistics that allow you to use the ‘allstats’ format of dbms_xplan.display_cursor() to get detailed execution information for a query. The drawback to the SQL Monitor feature is that it doesn’t report predicate information. It’s also important to note that it falls under the performance and diagnostic licences: some of the available performance informtion comes from v$active_session_history, and the report is generated by a call to the dbms_sqltune package.

There are two basic calls – report_sql_monitor_list(), which appeared in 11.2, produces a summary of the statements and their individual executions (from the information that is still in memory, of course) and report_sql_monitor() shows detailed execution plans. Here’s a simple bit of SQL*Plus code showing basic use – it lists a summary of all the statements monitored in the last half hour, then (as it stands at present) the full monitoring details of the most recently completed monitored statement:


set long 250000
set longchunksize 65536

set linesize 254
set pagesize 100
set trimspool on

set heading off

column text_line format a254

spool report_sql_monitor

select 
        dbms_sqltune.report_sql_monitor_list(
                active_since_date       => sysdate - 30 / (24*60),
                type                    => 'TEXT'
        ) text_line 
from    dual
;

select 
        dbms_sqltune.report_sql_monitor(
--              sql_id                  => '&m_sql_id',
--              start_time_filter       => sysdate - 30/(24 * 60),
--              sql_exec_id             => &m_exec_id,
                type                    =>'TEXT'
        ) text_line 
from    dual
;

spool off




Here’s a variation that reports the details of the most recently completed execution of a query with the specified SQL_ID:

set linesize 255
set pagesize 200
set trimspool on
set long 200000

column text_line format a254
set heading off

define m_sql_id = 'fssk2xabr717j'

spool rep_mon

SELECT  dbms_sqltune.report_sql_monitor(
                sql_id=> v.sql_id,
                sql_exec_id => v.max_sql_exec_id
        ) text_line
from     (
        select
                sql_id,
                max(sql_exec_id)        max_sql_exec_id
        from
                v$sql_monitor
        where
                sql_id = '&m_sql_id'
        and     status like 'DONE%'
        group by
                sql_id
        )       v
;

spool off

set heading on
set linesize 132
set pagesize 60

And a sample of the text output, which is the result of monitoring the query “select * from dba_objects” (with an arraysize of 1,000 set in SQL*Plus):


SQL Monitoring Report

SQL Text
------------------------------
select /*+ monitor */ * from dba_objects

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)
 Instance ID         :  1
 Session             :  SYS (262:54671)
 SQL ID              :  7nqa1nnbav642
 SQL Execution ID    :  16777216
 Execution Started   :  04/05/2018 19:43:42
 First Refresh Time  :  04/05/2018 19:43:42
 Last Refresh Time   :  04/05/2018 19:45:04
 Duration            :  82s
 Module/Action       :  sqlplus@linux12 (TNS V1-V3)/-
 Service             :  SYS$USERS
 Program             :  sqlplus@linux12 (TNS V1-V3)
 Fetch Calls         :  93

Global Stats
===========================================================================
| Elapsed |   Cpu   |    IO    |  Other   | Fetch | Buffer | Read | Read  |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes |
===========================================================================
|    0.31 |    0.29 |     0.00 |     0.02 |    93 |   6802 |   18 |   9MB |
===========================================================================

SQL Plan Monitoring Details (Plan Hash Value=2733869014)
=================================================================================================================================================================================
| Id |                Operation                 |       Name       |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Read | Read  |  Mem  | Activity | Activity Detail |
|    |                                          |                  | (Estim) |      | Active(s) | Active |       | (Actual) | Reqs | Bytes | (Max) |   (%)    |   (# samples)   |
=================================================================================================================================================================================
|  0 | SELECT STATEMENT                         |                  |         |      |        83 |     +0 |     1 |    91314 |      |       |       |          |                 |
|  1 |   VIEW                                   | DBA_OBJECTS      |   91084 | 2743 |        83 |     +0 |     1 |    91314 |      |       |       |          |                 |
|  2 |    UNION-ALL                             |                  |         |      |        83 |     +0 |     1 |    91314 |      |       |       |          |                 |
|  3 |     TABLE ACCESS BY INDEX ROWID          | SUM$             |       1 |      |           |        |       |          |      |       |       |          |                 |
|  4 |      INDEX UNIQUE SCAN                   | I_SUM$_1         |       1 |      |           |        |       |          |      |       |       |          |                 |
|  5 |     TABLE ACCESS FULL                    | USER_EDITIONING$ |       1 |    2 |         1 |     +0 |   872 |        1 |      |       |       |          |                 |
|  6 |      TABLE ACCESS BY INDEX ROWID BATCHED | OBJ$             |       1 |    3 |           |        |       |          |      |       |       |          |                 |
|  7 |       INDEX RANGE SCAN                   | I_OBJ1           |       1 |    2 |           |        |       |          |      |       |       |          |                 |
|  8 |     FILTER                               |                  |         |      |        83 |     +0 |     1 |    91312 |      |       |       |          |                 |
|  9 |      HASH JOIN                           |                  |   91394 |  211 |        83 |     +0 |     1 |    91312 |      |       |    2M |          |                 |
| 10 |       TABLE ACCESS FULL                  | USER$            |     125 |    2 |         1 |     +0 |     1 |      125 |      |       |       |          |                 |
| 11 |       HASH JOIN                          |                  |   91394 |  207 |        83 |     +0 |     1 |    91312 |      |       |    1M |   100.00 | Cpu (1)         |
| 12 |        INDEX FULL SCAN                   | I_USER2          |     125 |    1 |         1 |     +0 |     1 |      125 |      |       |       |          |                 |
| 13 |        TABLE ACCESS FULL                 | OBJ$             |   91394 |  204 |        83 |     +0 |     1 |    91312 |   13 |   9MB |       |          |                 |
| 14 |      TABLE ACCESS FULL                   | USER_EDITIONING$ |       1 |    2 |         1 |     +0 |   872 |        1 |    2 | 16384 |       |          |                 |
| 15 |      NESTED LOOPS SEMI                   |                  |       1 |    2 |           |        |       |          |      |       |       |          |                 |
| 16 |       INDEX SKIP SCAN                    | I_USER2          |       1 |    1 |           |        |       |          |      |       |       |          |                 |
| 17 |       INDEX RANGE SCAN                   | I_OBJ4           |       1 |    1 |           |        |       |          |      |       |       |          |                 |
| 18 |      TABLE ACCESS FULL                   | USER_EDITIONING$ |       1 |    2 |           |        |       |          |      |       |       |          |                 |
| 19 |     HASH JOIN                            |                  |       2 |    4 |         1 |    +82 |     1 |        1 |      |       |       |          |                 |
| 20 |      NESTED LOOPS                        |                  |       2 |    4 |         1 |    +82 |     1 |        2 |      |       |       |          |                 |
| 21 |       STATISTICS COLLECTOR               |                  |         |      |         1 |    +82 |     1 |        2 |      |       |       |          |                 |
| 22 |        TABLE ACCESS FULL                 | LINK$            |       2 |    2 |         1 |    +82 |     1 |        2 |    2 | 16384 |       |          |                 |
| 23 |       TABLE ACCESS CLUSTER               | USER$            |       1 |    1 |         1 |    +82 |     2 |        2 |      |       |       |          |                 |
| 24 |        INDEX UNIQUE SCAN                 | I_USER#          |       1 |      |         1 |    +82 |     2 |        2 |    1 |  8192 |       |          |                 |
| 25 |      TABLE ACCESS FULL                   | USER$            |       1 |    1 |           |        |       |          |      |       |       |          |                 |
=================================================================================================================================================================================


1 row selected.


In a future note I’ll show an example of using one of these reports to identify the critical performance issue with an SQL statement that was raised recently on the ODC (OTN) database forum, but I’ll just point out one detail from this report. The “Time active (s)” says the query ran for about 83 seconds, but the Global Stats section tells us the elapsed time was 0.31 seconds. In this case the difference between these two is the time spent passing the data to the client.

Footnote

It is possible to force monitoring for an SQL statement with the /*+ monitor */ hint. Do be careful with this in production systems; each time the statement is executed the session will try to get the “Real-time descriptor latch” which is a latch with no latch children so if you monitor a lightweight statement that is called many times from many sessions you may find you lose a lot of time to latch contention and the attendant CPU spinning.

 

8 Comments »

  1. Hi Jonathan,
    thank you for this post and pointing out how to interpret the difference between “Time active” and “Elapsed Time”. Very interesting!
    You write, that we take this information from memory. A while ago I spoke and wrote about a history of these reports which is retained in the database even longer.
    Have a look at
    http://blog.trivadis.com/b/mathiaszarick/archive/2017/03/17/real-time-sql-monitoring-report-history-in-12c.aspx
    and
    https://www.doag.org/formes/pubfiles/9106217/2017-NN-Mathias_Zarick-Performance_analysis_with_12c_SQL_Monitoring_report_history-Praesentation.pdf
    Have a nice day
    Mathias

    Comment by Mathias Zarick — April 6, 2018 @ 11:26 am BST Apr 6,2018 | Reply

    • Mathias,

      Thanks for the comment and for the links.
      Comments that collate related information like this are one of the best bits of the blog mechanism.

      I tweeted another link about the historic version a couple of months ago – it’s surprising how long the option has been available without getting much attention.

      Comment by Jonathan Lewis — April 6, 2018 @ 1:08 pm BST Apr 6,2018 | Reply

  2. Sometimes predicates can be extracted, tested on 12.1.0.2

    insert into plan_table
    (statement_id, plan_id, timestamp, remarks, operation, options,
    object_node, object_name, object_alias, id, depth, position,
    cost, cardinality, bytes, partition_start, partition_stop,
    partition_id, distribution, cpu_cost, io_cost, temp_space,
    access_predicates, filter_predicates, qblock_name)
    select
    r.key1 statement_id, 1 plan_id, sysdate timestamp,
    ‘sql monitor history report’ remarks,
    OPERATION, OPTIONS, OBJECT_NODE, OBJECT_NAME, OBJECT_ALIAS,
    ID, DEPTH, POSITION, COST, CARDINALITY, BYTES, PARTITION_START,
    PARTITION_STOP, PARTITION_ID, DISTRIBUTION, CPU_COST, IO_COST,
    TEMP_SPACE, ACCESS_PREDICATES, FILTER_PREDICATES, QBLOCK_NAME
    from dba_hist_reports r,
    dba_hist_reports_details d,
    xmltable(‘/report/sql_monitor_report/plan/operation’
    PASSING xmlparse(document d.report) COLUMNS
    OPERATION path ‘@name’
    ,options path ‘@options’
    ,OBJECT_NODE path ‘node’
    ,OBJECT_NAME path ‘object’
    ,object_alias path ‘object_alias’
    ,id path ‘@id’
    ,depth path ‘@depth’
    ,POSITION path ‘@pos’
    ,cost path ‘cost’
    ,CARDINALITY path ‘card’
    ,bytes path ‘bytes’
    ,PARTITION_START PATH ‘partition/@start’
    ,PARTITION_STOP path ‘partition/@stop’
    ,PARTITION_ID path ‘partition/@id’
    ,DISTRIBUTION path ‘distrib’
    ,cpu_cost path ‘cpu_cost’
    ,io_cost path ‘io_cost’
    ,TEMP_SPACE path ‘TEMP_SPACE’
    ,ACCESS_PREDICATES path ‘predicates[@type=”access”]’
    ,FILTER_PREDICATES path ‘predicates[@type=”filter”]’
    ,QBLOCK_NAME path ‘qblock’
    ) x1
    WHERE r.component_name = ‘sqlmonitor’
    and r.REPORT_ID = d.REPORT_ID
    and r.key1 = ‘dhpn35zupm8ck’
    and r.report_id = 70954;
    select * from table(dbms_xplan.display());

    Just put relevant SQL_ID and REPORT_ID.

    Comment by Yuri — April 6, 2018 @ 11:02 pm BST Apr 6,2018 | Reply

    • Yuri,

      Thanks for the suggestion – sorry the formatting went so wrong that it will take too long for me to do a quick fix.

      I am curious about the “sometimes”. Have you got any ideas about why the predicates are sometimes available and how oracle captures them, since I’ve never noticed them in the v$sql_monitor or v$sql_plan_monitor – even in 12.2 ?

      Comment by Jonathan Lewis — April 8, 2018 @ 11:09 am BST Apr 8,2018 | Reply

      • Jonathan, unfortunately, I did not manage to get understanding of what prevented me from getting predicates in some cases, it was prod database and I did not have enough permissions to dig dipper. It was 12.1.0.2 on Exadata.

        Comment by Yuri — April 9, 2018 @ 8:31 pm BST Apr 9,2018 | Reply

  3. Jonathan,

    may I just add the comment that the incomplete execution plan information in the SQL Monitor text reports (missing predicates etc.) resp. the separate representation in the ACTIVE report (different tabs for plan statistics and plan details) was one of the reasons why I started putting together my XPLAN_ASH script (see for example http://oracle-randolf.blogspot.com/2016/06/new-version-of-xplanash-utility.html) that attempts to combine the information from the V$SQL_MONITOR* views with the V$SQL_PLAN information.

    I haven’t managed to update the script significantly recently but it still turns out to be helpful in many cases. Hopefully I’ll manage to add some more features in the future (like objects referenced in ASH) and increased support for in-memory and other recent features added to Oracle. Of course SQL Monitor keeps adding more (unstructured) information as well that are usually only available from the ACTIVE report, so sometimes it is still helpful to have a SQL Monitor report in addition to a XPLAN_ASH report (in particular if the execution plan is no longer available from V$SQL_PLAN or DBA_HIST_SQL_PLAN but still available in V$SQL_MONITOR / DBA_HIST_REPORTS).

    Randolf

    Comment by Randolf Geist — April 18, 2018 @ 11:08 pm BST Apr 18,2018 | Reply


RSS feed for comments on this post. TrackBack URI

Comments and related questions are welcome.

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 )

Google+ photo

You are commenting using your Google+ 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 )

w

Connecting to %s

This site uses Akismet to reduce spam. Learn how your comment data is processed.

Powered by WordPress.com.