Mohamed Houri’s Oracle Notes

June 21, 2018

SQL Monitor and parsing

Filed under: SQL Monitor — hourim @ 6:32 pm

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.

Advertisements

3 Comments »

  1. Hi Mohamed,

    It’s a very useful blog post, as it’s always essential to know what gets measured.

    Just two more ideas for producing extreme parsing times.

    1. Create extended statistics to amplify the effect of the long IN lists

    2. For 12.2
    create table t (a number) ;
    select /* insert some huge comment here */
    case when
    (((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((((
    t.a <=1
    )))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))
    then 10
    else null
    end
    from sys.t;

    Best regards,

    Nenad

    Comment by Nenad Noveljic (@NenadNoveljic) — June 22, 2018 @ 8:00 am | Reply

  2. Thanks Nenad for your extreme parsing suggestions

    Best regards

    Comment by hourim — June 22, 2018 @ 10:10 am | Reply

  3. […] one we outlined that the SQL monitor begins monitoring the query only when this one reaches its execution phase. In this article we will see that,for parallel query, the wall clock time, very often, approaches […]

    Pingback by SQL Monitor and parallel processing | Mohamed Houri’s Oracle Notes — June 28, 2018 @ 6:25 pm | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

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

Blog at WordPress.com.

Tony's Oracle Tips

Tony Hasler's light hearted approach to learning about Oracle

Richard Foote's Oracle Blog

Focusing Specifically On Oracle Indexes, Database Administration and Some Great Music

Hatem Mahmoud Oracle's blog

Just another Oracle blog : Database topics and techniques

Mohamed Houri’s Oracle Notes

Qui se conçoit bien s’énonce clairement

Oracle Diagnostician

Performance troubleshooting as exact science

Raheel's Blog

Things I have learnt as Oracle DBA

Coskan's Approach to Oracle

What I learned about Oracle

So Many Oracle Manuals, So Little Time

“Books to the ceiling, Books to the sky, My pile of books is a mile high. How I love them! How I need them! I'll have a long beard by the time I read them”—Lobel, Arnold. Whiskers and Rhymes. William Morrow & Co, 1988.

EU Careers info

Your career in the European Union

Carlos Sierra's Tools and Tips

Tools and Tips for Oracle Performance and SQL Tuning

Oracle Scratchpad

Just another Oracle weblog

OraStory

Dominic Brooks on Oracle Performance, Tuning, Data Quality & Sensible Design ... (Now with added Sets Appeal)

%d bloggers like this: