SQL Monitor and parsing

In part I of this short series on SQL Monitoring Duration and Elapsed time information we saw that in the case of a query fetching data to the client, we have better to rely on the former information rather than on the latter. Indeed, the Elapsed time of the SQL monitor Global Stats section doesn’t keep count of the time spent passing the data to the client. Piotr Wrzosek, Tanel Poder and Robert have emphasized that, while Duration represents the wall clock time, Elapsed time in SQL monitor refers to the DB time measured for non-idle sessions that are either waiting or actively working on CPU. This is why time spent outside the database by idle sessions is not measured by the SQL monitor Elapsed time information.

In part 2 we will be trying to demonstrate that, all things being equal, the SQL monitor kicks in only during the query execution phase. Any preliminary steps occurring between the launch of the query and its execution phase will not be monitored. Typically, time spent in the hard parse phase, will appear neither in the Duration nor in the Elapsed time of the SQL monitor report.

Here’s below a quick demonstration

Parsing

I started looking around on how to produce a sufficiently long hard parse situation within a single query. Very quickly few ideas germinated in my mind like extreme Adaptive Cursor Sharing, or several SQL Plan Management baselined execution plans which Oracle has to reproduce and cost before selecting the best costed plan. But I finally ended up by using a simple join between two tables of 3 million rows each but with an imense IN-LIST predicate:

create table t1
as select
    rownum n1
   ,trunc((rownum-1)/3) n2
   ,mod(rownum,10) n3
from dual
connect by level <= 3e6;


create table t2
as select
    2*rownum n1
   ,trunc(rownum,5) n2
   ,lpad('x',5) vc
from dual
connect by level <= 3e6;

alter table t1 add constraint t1_pk primary key (n1);
alter table t2 add constraint t2_pk primary key (n1);

select /*+ monitor */
     t1.n1
    ,t1.n2
    ,t1.n3
from
     t1
where
     t1.n1 in
           (select t2.n2
           from t2
           where
                (
                 (
                  (
                   (
                          (t2.n1 in (33183, 31917, 31405)
                           or t2.n1 in (33383, 33917, 38405)
                           or t2.n1 in (150, 234, 456)
                           or t2.n1 in (309, 33456, 675)
                           or t2.n1 in (10, 2345, 42367)
                           or 
                           or
                           etc..
                    )
                   )
                  )
                 )
		   )
	     );

Just before launching this query I actived the 10046 trace event as shown below:

SQL> set timing on

SQL> @46on 12

SQL>@MyLongParsingQuery

        N1         N2         N3
---------- ---------- ----------
         5          1          5
        75         24          5
       117         38          7
       228         75          8
     16728       5575          8

Elapsed: 00:00:14.39

SQL> @46off

As you can see the query took 14 seconds wall clock time to complete. And you have to believe me when I say that the same query when executed without tracing lasted 14 seconds too.

Since the query execution phase is super-fast (less than 5 seconds) and is run serially, it will not be automatically monitored. This is why I forced it to be monitored using the hint /*+ monitor */. Here is below the corresponding SQL monitor report (reduced to the Global Information and Global Stats sections):

Global Information
------------------------------
 Status              :  DONE ( ALL ROWS)             
 Instance ID         :  1                     
 SQL ID              :  1w1jpyxgk0asj                    
 Execution Started   :  06/08/2018 12:16:31   
 First Refresh Time  :  06/08/2018 12:16:31  
 Last Refresh Time   :  06/08/2018 12:16:32   
 Duration            :  1s                  
                 
Global Stats
=================================================
| Elapsed |   Cpu   |  IO      | Fetch | Buffer |
| Time(s) | Time(s) | Waits(s) | Calls |  Gets  |
=================================================
|  0.08   |  0.02   |   0.06   |   2   |   542  |
=================================================

It is interesting to note that both Duration and Elapsed time are not showing the correct time of 14 seconds taken by the query.

However the TKPROF of the query 10046 trace file generated above is clearly showing where most of those 14 seconds have been spent:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1     12.89      14.22          0          0          3           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.02       0.08         40        542          0           4
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     12.91      14.30         40        542          3           4

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                         1179        0.00          0.01
  acknowledge over PGA limit                    117        0.10          1.30
  SQL*Net message to client                       2        0.00          0.00
  db file sequential read                        40        0.01          0.06
  SQL*Net message from client                     2        0.00          0.01
********************************************************************************

Thanks to the above TKPROF lines we now have a clear image of the query execution time distribution:

 elapsed time    = 14.30 seconds (of which 14.22 for parsing)
 cpu consumption = 12.91 seconds (of which 12.89 for parsing)
 wait events     = 0.01 + 1.30 + 0.00 + 0.06 + 0.01 = 1.38 seconds
 elapsed -cpu    = 14.30 -12.91 = 1.39 seconds

Summary

In this second part of the series about Duration and Elapsed time information displayed by the SQL monitor report, we have demonstrated the following two points:

• SQL monitor monitors only the execution phase of the query
• Any preliminary steps preceding the execution phase will not be considered by the SQL monitor. Typically, time taken by a long hard parsing situation, will not show up neither in the Duration nor in the Elapsed time.