DBMS_SQLTUNE.REPORT_SQL_MONITOR - reporting "DONE(ERROR)"

 Dears,

Today while I was watching a SQL query execution statsistics, I noticed a weired behaviour coming out of oracle's DBMS_SQLTUNE.REPORT_SQL_MONITOR package.

DBMS_SQLTUNE.REPORT_SQL_MONITOR is used to report the live execution statistics of the SQL.

This particular package reported my active SQL as "DONE(ERROR)" as if like some one killed the session or it failed due to a temp or undo or datafile space error.

It didnt report why it failed though still. Interestingly the elapsed time is 7748 vs it's overall query duration reported was 317s.

It took me by surprise, then I check v$session and noticed it isnt rolling back the merge it was running; since it wasnt reading from undo datafile.

So I suspected this is a weird reporting issue. So I continued checking if the session is really active.

Yes the session was really active and v$sql perfectly increments elapsed, cpu, io wait times along with its corresponding other metrics.

Cause: the query ran using parallel slaves, query had plan regression and it ended up running longer with few slaves staying idle for more than 30mins.

Now oracle says this particular condition where a px slave part of the query execution staying idle is an anomaly and is reported as a failed sql execution from oracle end; but really isnt the case :)

RDBMS: Oracle

Version: 12.2

Oracle note: 1900060.1

Bug: 13523091 (Incorrect status in v$sql_monitor with parallel query)

Thank you!

how to monitor a sql with subsecond elapsed time

Monitor a sql execution which lasted only for few seconds or even less... report the execution using dbms_sqltune

1) introduce the hint MONITOR in the desired sql, such that how short the execution time, the sql execution is monitored.

insert /*+ MONITOR */ into T1
select * from T1@to_r1;

2) use the dbms_sqltune to report the monitored sql.

SELECT DBMS_SQLTUNE.report_sql_monitor(sql_id=>'bfjf7tz62t1p5',type=>'TEXT',report_level => 'ALL')
from dual;

SQL Monitoring Report

SQL Text
------------------------------
insert /*+ MONITOR */ into T1 select * from T1@to_r1

Global Information
------------------------------
 Status              :  DONE
 Instance ID         :  1
 Session             :  SYSTEM (268:1203)
 SQL ID              :  bfjf7tz62t1p5
 SQL Execution ID    :  16777216
 Execution Started   :  12/02/2018 21:48:34
 First Refresh Time  :  12/02/2018 21:48:34
 Last Refresh Time   :  12/02/2018 21:48:37
 Duration            :  3s
 Module/Action       :  SQL*Plus/-
 Service             :  pdb2
 Program             :  sqlplus@db12c.oracle.com (TNS V1-V3)

Global Stats
===================================================================================
| Elapsed |   Cpu   |    IO    |  Other   | Buffer | Read | Read  | Write | Write |
| Time(s) | Time(s) | Waits(s) | Waits(s) |  Gets  | Reqs | Bytes | Reqs  | Bytes |
===================================================================================
|    3.10 |    1.20 |     0.02 |     1.88 |  20794 |   22 | 336KB |    18 |  10MB |
===================================================================================

SQL Plan Monitoring Details (Plan Hash Value=1788691278)
==============================================================================================================================================
| Id |         Operation         |        Name         |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Activity | Activity Detail |
|    |                           |                     | (Estim) |      | Active(s) | Active |       | (Actual) |   (%)    |   (# samples)   |
==============================================================================================================================================
|  0 | INSERT STATEMENT          |                     |         |      |         2 |     +2 |     1 |        0 |          |                   |
|  1 |   LOAD TABLE CONVENTIONAL |                     |         |      |         3 |     +1 |     1 |        0 |          |                   |
|  2 |    REMOTE                 | T1               |    186K | 3879 |         2 |     +2 |     1 |     186K |          |                   |
==============================================================================================================================================