Mohamed Houri’s Oracle Notes

June 28, 2018

SQL Monitor and parallel processing

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

Very often, people get confused about the actual execution time taken by a parallel query. I’ve seen this asked a few times so that I have always thought it deserves a simple blog post. This is then the last article of the series about SQL monitor Duration and Elapsed time information where we’re going to become acquainted with how to get wall clock time of queries executed using parallelism.

SQL monitor and Parallelism

In the first article we learned that SQL monitor Elapsed time doesn’t sum up time spent outside the database by idle sessions. In the second 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 the Duration information of the SQL monitor report rather than that of the Elapsed time.

Having said that, here’s below a query which I will run using parallelism (t1 being a simple copy of all_objects table):

SQL> select /*+ parallel(4) */ 
        object_type
	  , count(1)
    from t1
    group by object_type;

43 rows selected.

Elapsed: 00:00:09.91

As you can see it took almost 10 seconds wall clock time for the above query to complete using the following parallel execution plan:

SQL_ID  08ka9ybgk43v1, child number 0
-------------------------------------
----------------------------------------------------------------------------------
| Id  | Operation                | Name     | Rows  |    TQ  |IN-OUT| PQ Distrib |
----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT         |          |       |        |      |            |
|   1 |  PX COORDINATOR          |          |       |        |      |            |
|   2 |   PX SEND QC (RANDOM)    | :TQ10001 |    43 |  Q1,01 | P->S | QC (RAND)  |
|   3 |    HASH GROUP BY         |          |    43 |  Q1,01 | PCWP |            |
|   4 |     PX RECEIVE           |          |    43 |  Q1,01 | PCWP |            |
|   5 |      PX SEND HASH        | :TQ10000 |    43 |  Q1,00 | P->P | HASH       |
|   6 |       HASH GROUP BY      |          |    43 |  Q1,00 | PCWP |            |
|   7 |        PX BLOCK ITERATOR |          | 23131 |  Q1,00 | PCWC |            |
|*  8 |         TABLE ACCESS FULL| T1       | 23131 |  Q1,00 | PCWP |            |
----------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   8 - access(:Z>=:Z AND :Z<=:Z)

Note
-----
   - Degree of Parallelism is 4 because of hint

If you want to, or are planning to analyze the above parallel query through the SQL monitor report then pay attention to the following:

SELECT DBMS_SQLTUNE.report_sql_monitor(
  sql_id       => '08ka9ybgk43v1',
  type         => 'TEXT',
  report_level => 'ALL') AS report
FROM dual; 

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)     
 Instance ID         :  1                   
 Session             :  XXXX(296:2203)   
 SQL ID              :  08ka9ybgk43v1       
 SQL Execution ID    :  16777216            
 Execution Started   :  06/28/2018 07:30:52 
 First Refresh Time  :  06/28/2018 07:30:54 
 Last Refresh Time   :  06/28/2018 07:31:02 
 Duration            :  10s                 
 Module/Action       :  SQL*Plus/-          
 Service             :  YYYYY
 Program             :  sqlplus.exe         
 Fetch Calls         :  4                   

Global Stats
=========================================================
| Elapsed |   Cpu   |    IO    | Application |  Other   |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   | Waits(s) |
=========================================================
|      32 |    0.91 |       29 |        1.74 |     0.08 |
=========================================================

It is, again, the Duration of the Global Information which gives the wall clock time taken by the query executed via parallelism. The Elapsed Time of the Global Stats section represents time taken by the Query Coordinator and all its parallel slaves as clearly shown in the same SQL monitor report:

Parallel Execution Details (DOP=4 , Servers Allocated=8)
=================================================================================
|      Name      | Type  | Server# | Elapsed |   Cpu   |    IO    | Application |
|                |       |         | Time(s) | Time(s) | Waits(s) |  Waits(s)   |
=================================================================================
| PX Coordinator | QC    |         |    2.26 |    0.01 |     0.50 |        1.74 |
| p000           | Set 1 |       1 |    0.00 |    0.00 |          |             |
| p001           | Set 1 |       2 |    0.00 |    0.00 |          |             |
| p002           | Set 1 |       3 |    0.00 |    0.00 |          |             |
| p003           | Set 1 |       4 |    0.00 |    0.00 |          |             |
| p004           | Set 2 |       1 |    7.38 |    0.20 |     7.17 |             |
| p005           | Set 2 |       2 |    7.22 |    0.22 |     6.97 |             |
| p006           | Set 2 |       3 |    7.57 |    0.27 |     7.28 |             |
| p007           | Set 2 |       4 |    7.32 |    0.21 |     7.10 |             |
=================================================================================

Based on the information provided by the gv$sql_monitor view I’ve developed the following scripts showing how the query execution time has been distributed between the Query Coordinator and its parallel slaves

-- this gives execution time consumed by parallel slaves
SQL> @PXElaps
Enter value for sql_id: 08ka9ybgk43v1
Enter value for exec_id: 16777216

SQL_ID        SQL_EXEC_ID        SID PROCE    ELAPSED
------------- ----------- ---------- ----- ----------
08ka9ybgk43v1    16777216        254 p003           0
08ka9ybgk43v1    16777216        193 p000           0
08ka9ybgk43v1    16777216        214 p001           0
08ka9ybgk43v1    16777216        234 p002           0
08ka9ybgk43v1    16777216        299 p005        7.22
08ka9ybgk43v1    16777216          2 p007        7.32
08ka9ybgk43v1    16777216        277 p004        7.38
08ka9ybgk43v1    16777216        318 p006        7.57
                                           ----------
Total Slaves                                    29.49

8 rows selected.
-- this gives execution time consumed by Query Coordinator
SQL> @QCElaps
Enter value for sql_id: 08ka9ybgk43v1
Enter value for exec_id: 16777216

SQL_ID           QC_TIME        DOP PX_SERVERS_REQUESTED PX_SERVERS_ALLOCATED
------------- ---------- ---------- -------------------- --------------------
08ka9ybgk43v1       2.26          4                    8                    8 
-- this gives execution time consumed by Query Coordinator and its PX slaves
SQL> @QCPXElaps
Enter value for sql_id: 08ka9ybgk43v1
Enter value for sql_exec_id: 16777216

SQL_ID                           SID PROCE      ELAPS
------------------------- ---------- ----- ----------
08ka9ybgk43v1                    254 p003           0
08ka9ybgk43v1                      2 p007        7.32
08ka9ybgk43v1                    214 p001           0
08ka9ybgk43v1                    299 p005        7.22
08ka9ybgk43v1                    296 QC          2.26
08ka9ybgk43v1                    193 p000           0
08ka9ybgk43v1                    277 p004        7.38
08ka9ybgk43v1                    318 p006        7.57
08ka9ybgk43v1                    234 p002           0
                                           ----------
Elapsed time(s)                                 31.75

9 rows selected.

The devil is in the details
Before you start crying ‘yes, but what about…‘, make sure you understand the following statistics of AWR historical execution of a particular parallel query taken from a running system:

SQL> @HistStats
Enter value for sql_id: a8yny7n0x1gj1
Enter value for from_date: 01062018

SNAP_BEGIN                PLAN_HASH_VALUE    EXECS END_OF_FETCH  AVG_ETIME    AVG_PIO    AVG_LIO   AVG_ROWS
------------------------- --------------- -------- ------------ ---------- ---------- ---------- ----------
20-JUN-18 08.00.58.250 PM       765437158        1            0        665    4708199    4789407          0
25-JUN-18 08.00.43.224 PM       765437158        1            0        773    5446986    5545989          0

At first glance many persons will think that this query took 665 seconds. In effect, we should not consider the above average elapsed time without the fundamental information which is: avg_px

agv_px = px_servers_execs_delta/decode (executions_delta, 0, 1, executions_delta)

This metric indicates whether the query runs parallel or not. If it is not null then the AVG_ETIME represents the cumulated execution time of taken by the Query Coordinator and all its parallel slaves used to run the query concurrently.

Here’s below the same AWR historical execution statistics augmented with the avg_px metric:

@HistStats
Enter value for sql_id:  a8yny7n0x1gj1
Enter value for from_date: 01052018

SNAP_BEGIN                PLAN_HASH_VALUE EXECS END_OF_FETCH  AVG_ETIME AVG_PX   AVG_LIO 
------------------------- --------------- ----- ------------ ---------- ------  --------
20-JUN-18 08.00.58.250 PM      765437158      1            0      665      8     4789407    
25-JUN-18 08.00.43.224 PM      765437158      1            0      773      8     5545989

Thanks to the avg_px supplementary information we know now that this query has used parallelism during its execution and that the AVG_ETIME of 665 seconds (or 773) corresponds to the Elapsed time taken by all parallel servers(8) including the query coordinator. If you want to measure the actual wall clock time taken by this query you have then to use the following approximative arithmetic:

 ag_wc_time = trunc(avg_etime/decode(avg_px,0,1,avg_px) ,2) avg_px_time

Which when implemented into the above Histstats script gives this:

@HistStats
Enter value for sql_id:a8yny7n0x1gj1
Enter value for from_date: 01052018

SNAP_BEGIN                PLAN_HASH_VALUE EXECS END_OF_FETCH  AVG_ETIME AVG_PX AVG_WC_TIME  
------------------------- --------------- ----- ------------ ---------- ------ ----------- 
20-JUN-18 08.00.58.250 PM      765437158      1            0      665      8        166.25     
25-JUN-18 08.00.43.224 PM      765437158      1            0      773      8        193.25 

Finally we are able to say that, approximatively, this query took about 193 seconds wall clock time during it execution of June the 25th at around 8PM.

Since the above query used parallelism it has been monitored as the following proves:

SQL> select
       sql_exec_id
       ,to_char(sql_exec_start, 'dd/mm/yyyy hh24:mi:ss') exec_date
    from
      gv$sql_monitor
    where
      sql_id = 'a8yny7n0x1gj1';

SQL_EXEC_ID EXEC_DATE
----------- -------------------
 16777225    25/06/2018 20:01:09

SELECT DBMS_SQLTUNE.report_sql_monitor(
  sql_id       => 'a8yny7n0x1gj1',
  sql_exec_id  =>  16777225,
  type         => 'TEXT',
  report_level => 'ALL') AS report
FROM dual;

Global Information
------------------------------
 Status              :  DONE (ERROR)             
 Instance ID         :  1                     
 SQL ID              :  a8yny7n0x1gj1  
 SQL Execution ID    :  16777225                   
 Execution Started   :  06/25/2018 20:01:09   
 First Refresh Time  :  06/25/2018 20:01:09  
 Last Refresh Time   :  06/25/2018 20:04:20   
 Duration            :  191s                  
                 
Global Stats
================================
| Elapsed |   Cpu   |  IO      |
| Time(s) | Time(s) | Waits(s) |
================================
|  776    |  236    |   538    | 
================================

Notice how using AWR historical tables(HistStats.sql) we are able to derive, almost reliably, the actual time taken by a query ran in parallel.

Summary
SQL monitor feature monitors performance of SQL statements while they execute. It is started automatically when a SQL statement runs parallel or serial but has consumed at least 5 seconds either on CPU or on I/O wait. The parsed phased of SQL statements is not monitored. In order to have an idea about the exact duration of the SQL statement execution then we have better to rely on the Duration information rather than on the Elapsed Time of the Global Stats section of the report. This is because Elapsed Time doesn’t include time spent by idle session fetching data for example. And when a SQL statement runs parallel, the Elapsed Time includes execution time of both the Query Coordinator and all its parallel server slaves while the Duration represents the wall clock time of the query that runs both serial and parallel.

SQL scritps

@PxElaps
compute sum label 'Total Slaves time' of elapsed on report
break   on report
select
          sql_id
		 ,sql_exec_id
		 ,sid		 
         , process_name 		 
         , round(elapsed_time/1e6,2) elapsed
       --  , round(cpu_time/1e6) cpu
         --, round(concurrency_wait_time/1e6,2) conc
       --  , round(user_io_wait_time/1e6) IO_Waits
   from gv$sql_monitor
   where sql_id = '&sql_id'   
   and sql_exec_id = '&exec_id'
   and sql_text is  null
   order by round(elapsed_time/1e6,2);
@QCElaps
select
           sql_id
		 , round(elapsed_time/1e6,2) QC_time
         , px_maxdop DOP
         , px_servers_requested
         , px_servers_allocated        
         , round(cpu_time/1e6) cpu
         --, round(concurrency_wait_time/1e6,2) conc
         , round(user_io_wait_time/1e6) IO_Waits
   from gv$sql_monitor
   where sql_id = '&sql_id'
   and sql_exec_id = '&exec_id'
   and sql_text is not null;
@QCPXElaps
column label format a25
col sql_id format a25
compute sum label 'Elapsed time(s)' of elaps on report
break   on report
select
          sql_id	
         ,sid          		 
         ,decode(process_name, 'ora', 'QC', process_name) process
         ,round(elapsed_time/1e6,2) elaps
from gv$sql_monitor
where sql_id    = '&sql_id'   
and sql_exec_id = '&exec_id';
Advertisements

Leave a Comment »

No comments yet.

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: