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

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.

June 9, 2018

ASH, SQL Monitor and Extended trace

Filed under: ASH,SQL Monitor — hourim @ 3:21 pm

Without any analogy with Sergio Leone’s famous movie “The Good, the Bad and the Ugly” which has brought up my teenage years, I would rather define the above three Oracle features as “The Good, the Good and the Good” as they made my consultancy days very often. This article has been inspired by the last Nenad Noveljic blog post about negative unaccounted-for where he mentioned that the SQL Monitor Global Stats section might show a wrong value in the Elapsed time. In Nenad’s case this misleading piece of information was due to unaccounted-for time. In fact, I know three other situations where this time discrepancy might occur: when fetching data, during a long hard parsing query and when using parallel execution. In this article I will start by demonstrating the fetching data case. Two other articles for the parse and parallel cases will follow to complete the series.

Fetching data

I executed a query which takes few minutes to complete but spent a considerable amount of time fetching a large number of columns with quite a large number of rows. While the query was running I took several snapshots of its corresponding 12cR2 SQL monitor which I am presenting below:

Global Information
------------------------------
 Status              :  EXECUTING             
 Instance ID         :  1                     
 SQL ID              :  g6px76dmjv1jy                    
 Execution Started   :  06/05/2018 09:54:19   
 First Refresh Time  :  06/05/2018 09:54:25  
 Last Refresh Time   :  06/05/2018 09:54:29   
 Duration            :  11s                  
                 
Global Stats
=========================================
| Elapsed |   Cpu   |  IO      | Buffer |
| Time(s) | Time(s) | Waits(s) |  Gets  |
=========================================
|    10   |    8.36 |     1.34 |   2M   |
=========================================

SQL Plan Monitoring Details (Plan Hash Value=2278376452)
===========================================================================
| Id    |                 Operation |       Name       | Execs |   Rows   |
|       |                           |                  |       | (Actual) |
===========================================================================
|     0 | SELECT STATEMENT          |                  |     1 |          |
|     1 |   NESTED LOOPS OUTER      |                  |     1 |          |
|     2 |    NESTED LOOPS           |                  |     1 |          |
|     3 |     FILTER                |                  |     1 |          |

As you can see, both Elapsed time and Duration are showing the same time of 10 seconds. But spot as well that at this stage of the query execution, data was not yet sent to the client (Actual Rows column is empty).

At exactly the same moment, ASH is also showing approximately the same elapsed time as shown below:

column  cnt   format 9999
compute sum label 'Total Elapsed' of cnt on report

break   on report

select 
   sql_plan_line_id
  ,count(1) cnt
from
   gv$active_session_history
 where
    sample_time between to_date('&datefrom', 'mm/dd/yyyy hh24:mi:ss')
				and     to_date('&dateto', 'mm/dd/yyyy hh24:mi:ss')
and sql_id = '&sql_id'
group by sql_plan_line_id
order by 2 desc;

SQL> @ashplanlineId
Enter value for datefrom:  06/05/2018 09:54:19
Enter value for dateto:  06/05/2018 09:54:29
Enter value for sql_id: g6px76dmjv1jy


SQL_PLAN_LINE_ID   CNT
---------------- -----
              10    7
              13    1
              11    1
                 -----
Total Elapsed       9

However, as soon as Oracle has started sending data to the client, a discrepancy between Elapsed time in Global Stats section and Duration began to be displayed as shown below:

Global Information
------------------------------
 Status              :  EXECUTING             
 Instance ID         :  1                     
 SQL ID              :  g6px76dmjv1jy                    
 Execution Started   :  06/05/2018 09:54:19   
 First Refresh Time  :  06/05/2018 09:54:25  
 Last Refresh Time   :  06/05/2018 09:56:18   
 Duration            :  120s                  
 Fetch Calls         :  375            
    
Global Stats
=================================================
| Elapsed |   Cpu   |  IO      | Fetch | Buffer |
| Time(s) | Time(s) | Waits(s) | Calls |  Gets  |
=================================================
|    32   |    11   |     21   |   375 |   3M   |
=================================================

SQL Plan Monitoring Details (Plan Hash Value=2278376452)
===========================================================================
| Id    |                 Operation |       Name       | Start |   Rows   |
|       |                           |                  | Active| (Actual) |
===========================================================================
| ->  0 | SELECT STATEMENT          |                  |   +30 |     5611 |
| ->  1 |   NESTED LOOPS OUTER      |                  |   +30 |     5611 |
| ->  2 |    NESTED LOOPS           |                  |   +30 |     5611 |
| ->  3 |     FILTER                |                  |   +30 |          |

ASH, in accordance with SQL monitor Elapsed time, started also to report a wrong elapsed time as shown below:

SQL> @ashplanlineId
Enter value for datefrom:  06/05/2018 09:54:19
Enter value for dateto:  06/05/2018 09:56:18
Enter value for sql_id: g6px76dmjv1jy


SQL_PLAN_LINE_ID   CNT
---------------- -----
              13    25
              10     7
              4      1
              4      1
                 -----
Total Elapsed       34

And so on until the query has finished fetching the entire set of data in about 527 seconds while both ASH and Elapsed time of the SQL monitor section are showing roughly 34 seconds of elapsed time as shown below respectively:

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)             
 Instance ID         :  1                     
 SQL ID              :  g6px76dmjv1jy                    
 Execution Started   :  06/05/2018 09:54:19   
 First Refresh Time  :  06/05/2018 09:54:25  
 Last Refresh Time   :  06/05/2018 10:03:06   
 Duration            :  527s                  
 Fetch Calls         :  2085            
    
Global Stats
=================================================
| Elapsed |   Cpu   |  IO      | Fetch | Buffer |
| Time(s) | Time(s) | Waits(s) | Calls |  Gets  |
=================================================
|    34   |    12   |     22   |  2085 |   3M   |
=================================================

SQL> @ashplanlineId
Enter value for datefrom:  06/05/2018 09:54:19
Enter value for dateto:  06/05/2018 09:56:18
Enter value for sql_id: g6px76dmjv1jy


SQL_PLAN_LINE_ID   CNT
---------------- -----
              13    26
              10     7
               4     1
              11     1
               5     1
                 -----
Total Elapsed       36

Using Nenad query, I can also report the same wrong elapsed time from ASH.

column  event format a30
column  cnt   format 9999
compute sum label 'Total Elapsed' of cnt on report

break   on report
select 
   session_state, event
  ,count(1) cnt
from
   gv$active_session_history
 where
   sql_id = '&sql_id'
 and sql_exec_id = (select max(sql_exec_id) 
                    from gv$active_session_history
					where sql_id = '&sql_id'
					)
group by event, session_state
;
SESSION EVENT                            CNT
------- ------------------------------ -----
WAITING direct path read                  26
ON CPU                                    11
                                       -----
Total Elapsed                             37

TKPROF

In a second attempt to make this time difference crystal clear I traced another execution of the same query using the 10046 trace events. I reproduced below the corresponding SQL monitor report and TKPROF summary respectively:

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)             
 Instance ID         :  1                     
 SQL ID              :  g6px76dmjv1jy                    
 Execution Started   :  06/05/2018 09:27:23   
 First Refresh Time  :  06/05/2018 09:27:30  
 Last Refresh Time   :  06/05/2018 09:39:21   
 Duration            :  718s                  
 Fetch Calls         :  2085            
    
Global Stats
=================================================
| Elapsed |   Cpu   |  IO      | Fetch | Buffer |
| Time(s) | Time(s) | Waits(s) | Calls |  Gets  |
=================================================
|    198  |    15   |     183  |  2085 |   3M   |
=================================================


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.21       0.21          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch     2085     15.18     198.03     647106    2918455          0       31246
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     2087     15.39     198.24     647106    2918455          0       31246


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                    2085        0.00          0.00
  SQL*Net more data to client                     2        0.00          0.00
  Disk file operations I/O                       90        0.00          0.00
  db file sequential read                     30313        0.09        158.42
  reliable message                                1        0.00          0.00  
  enq: KO – fast object checkpoint                1        0.00          0.00
  direct path read                             1220        0.09         24.76
  SQL*Net message from client                  2085        0.93        519.45
********************************************************************************

As you can see, the Duration of the SQL monitor is showing that the query took 718 seconds while the Elapsed time is showing only 198 seconds (15 sec for CPU and 183 sec for IO waits).
However, the TKPROF file comforts the reliability of the SQL monitor Duration information since it shows that the total elapsed time of the query is:

158.42 + 24.76     = 183.18 seconds for I/O waits
158.42 + 519.45    = 702.63 seconds for I/O waits and  SQL*Net message from client
702.63 + 15.39(cpu)= 718.02 seconds 

Naturally, ASH can’t display the correct piece of information since a large part of the query has been spent on the idle SQL*Net message from client wait event:

SQL> @ashplanlineId
Enter value for datefrom:  06/05/2018 09:27:23
Enter value for dateto:  06/05/2018 09:39:21
Enter value for sql_id: g6px76dmjv1jy

SQL_PLAN_LINE_ID   CNT
---------------- -----
              12   153
              13    28
              10     9
              11     6
              14     1
                 -----
Total Elapsed      197

Summary

We have clearly shown that when a query is fetching a large amount of data to the client, this transfer time is not taken into account by the Elapsed time of the SQL monitor Global Stats section. This is why, as mentioned by Nenad in his article, you should always rely on the time reported by the Duration in the Global information of the SQL Monitor instead of the Elapsed time of the Global stats section.

June 7, 2018

12cR2 Partitioning: auto-list and the disk space threat

Filed under: Partitioning — hourim @ 5:55 pm

Oracle 12cR2 comes with the auto-list partitioning option; It allows for system named partitions to be created on the fly as data arrives:

SQL> select banner from v$version where rownum=1;

BANNER
--------------------------------------------------------------------------------
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production

SQL> create table auto_list_part
  	( n1 number  
       ,n2 number 
       ,vc1 varchar2(30)
      )
     partition by list(n1)
     AUTOMATIC  
     (partition p1 values(1,2,3,4,5)
     ,partition p2 values(6,7,8,9,10)
     ,partition p3 values(11,12,13,14,15) 
      )
     /

You only need to add the AUTOMATIC clause to the old way of creating list partitioned tables to have this feature enabled.

There is, however, a subtlety to consider: the AUTOMATIC clause doesn’t work with the DEFAULT clause:

SQL> create table auto_list_part
  	( n1 number  
       ,n2 number 
       ,vc1 varchar2(30)
      )
     partition by list(n1)
     AUTOMATIC
     (partition p1 values(1,2,3,4,5)
     ,partition p2 values(6,7,8,9,10)
     ,partition p3 values(11,12,13,14,15) 
     ,partition p_default values (default)
      )
     /
create table auto_list_part
*
ERROR at line 1:
ORA-14851: DEFAULT [sub]partition cannot be specified for AUTOLIST [sub]partitioned objects.

This is perfectly coherent as you don’t want to ask Oracle creating automatic list partitions for each of your newly arrived partition key values and ask it in the same time to put them into the DEFAULT partition.

That’s said let’s insert into the above automatic list partitioned table, rows that will go both in the already pre-created partitions and rows that need to go into non-existent ones:

SQL> insert into auto_list_part
     select
          rownum
         ,mod(rownum,5)
         ,'v'
     from dual
     connect by level <= 20;

 20 rows created.

SQL> exec dbms_stats.gather_table_stats(user, 'auto_list_part');

PL/SQL procedure successfully completed.



SQL> @getPartTab
Enter value for table_name: auto_list_part

TABLE_NAME           PARTITION_NAME  PARTITION_POSITION   NUM_ROWS TABLESPACE_NAME
-------------------- --------------- ------------------ ---------- ---------------
AUTO_LIST_PART       P1                               1          5 USERS
AUTO_LIST_PART       P2                               2          5 USERS
AUTO_LIST_PART       P3                               3          5 USERS
AUTO_LIST_PART       SYS_P3054                        4          1 USERS
AUTO_LIST_PART       SYS_P3055                        5          1 USERS
AUTO_LIST_PART       SYS_P3056                        6          1 USERS
AUTO_LIST_PART       SYS_P3057                        7          1 USERS
AUTO_LIST_PART       SYS_P3058                        8          1 USERS
                                                        ----------
Total num_rows                                                  20

8 rows selected.

I inserted 20 rows of which 5 have been embedded into 5 new SYS-partitions created automatically to store not foreseen partition key values greater than 15. It is important to note as well that the AUTOMATIC clause creates one partition per partition key. This is why you should absolutely take care in basing your partition strategy upon a data load pattern that will insert a reasonable amount of rows per partition key.

Let’s now get the size of the partitioned table:

SQL> @SizeBySegNameMB
Enter value for segment_name: auto_list_part
Enter value for owner: c##mhouri

SEGMENT_TYPE       TABLESPACE_NAME  SEGMENT_NAME         PARTITION_NAME          MB
------------------ ---------------- -------------------- --------------- ----------
TABLE PARTITION    USERS            AUTO_LIST_PART       P1                       8
TABLE PARTITION    USERS            AUTO_LIST_PART       P2                       8
TABLE PARTITION    USERS            AUTO_LIST_PART       P3                       8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3054                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3055                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3056                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3057                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3058                8
                                                                         ----------
Total Segment Size                                                               64

8 rows selected.

As you can see the 8 partitions occupy 64MB of disk space as their initial extend is 8MB regardless of the tiny number of rows they contain:

SQL> select 
        initial_extent/power(1024,2) initial_extentMB
       ,next_extent/power(1024,2)    next_extentMB
       ,extents
     from
        sys_dba_segs
     where
        segment_name = 'AUTO_LIST_PART'
     and
        owner        = 'C##MHOURI'
     and rownum      = 1   -- show only for one partition 
   ; 
INITIAL_EXTENTMB NEXT_EXTENTMB    EXTENTS
---------------- ------------- ----------
               8             1          1

And now the question that motivated this blog post: what happens when a very big insert into an auto-list partitioned table fails and is rolled back (by the transaction itself or via an explicit user rollback):

SQL> insert into auto_list_part
     select
          rownum
         ,mod(rownum,5)
         ,'w'
     from dual
     connect by level <= 100;

100 rows created.

SQL> rollback;

Rollback complete.

SQL> @sizebySegnameMB
Enter value for segment_name: auto_list_part
Enter value for owner: c##mhouri

SEGMENT_TYPE       TABLESPACE_NAME  SEGMENT_NAME         PARTITION_NAME          MB
------------------ ---------------- -------------------- --------------- ----------
TABLE PARTITION    USERS            AUTO_LIST_PART       P1                       8
TABLE PARTITION    USERS            AUTO_LIST_PART       P2                       8
TABLE PARTITION    USERS            AUTO_LIST_PART       P3                       8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3054                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3055                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3056                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3057                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3058                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3069                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3070                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3071                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3072                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3073                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3074                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3075                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3076                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3077                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3078                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3079                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3080                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3081                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3082                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3083                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3084                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3085                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3086                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3087                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3088                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3089                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3090                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3091                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3092                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3093                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3094                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3095                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3096                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3097                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3098                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3099                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3100                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3101                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3102                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3103                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3104                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3105                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3106                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3107                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3108                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3109                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3110                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3111                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3112                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3113                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3114                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3115                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3116                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3117                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3118                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3119                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3120                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3121                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3122                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3123                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3124                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3125                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3126                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3127                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3128                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3129                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3130                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3131                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3132                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3133                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3134                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3135                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3136                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3137                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3138                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3139                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3140                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3141                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3142                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3143                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3144                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3145                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3146                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3147                8
TABLE PARTITION    USERS            AUTO_LIST_PART       SYS_P3148                8
                                                                         ----------
Total Segment Size                                                              704

88 rows selected.

As you might have already pointed it out, it doesn’t matter whether I commit or rollback, Oracle will create on the fly, as much partitions as the distinct partition key values I have tried to insert. The immediate consequence is that I ended up with an almost empty partitioned table having 704MB worth of disk space.

If you want to shrink this ”wasted” space then you can move those partitions to use a less bigger initial extent:

SQL> alter table auto_list_part move partition SYS_P3148 
          storage(initial 65536 next 1M);

Table altered.
SQL> @sizeBySegNameMB
Enter value for segment_name: auto_list_part
Enter value for owner: c##mhouri

SEGMENT_TYPE       TABLESPACE_NAME SEGMENT_NAME         PARTITION_NAME          MB
------------------ --------------- -------------------- --------------- ----------
TABLE PARTITION    USERS           AUTO_LIST_PART       P1                       8
TABLE PARTITION    USERS           AUTO_LIST_PART       P2                       8
TABLE PARTITION    USERS           AUTO_LIST_PART       P3                       8
TABLE PARTITION    USERS           AUTO_LIST_PART       SYS_P3054                8
TABLE PARTITION    USERS           AUTO_LIST_PART       SYS_P3055                8
../..
TABLE PARTITION    USERS           AUTO_LIST_PART       SYS_P3148              ,06
                                                                        ----------
Total Segment Size                                                          696,06

you can also prevent such a disk space explosion due to the future automatically created list partitions by un-setting the following parameter (make sure you have read this before):

SQL> alter system set "_partition_large_extents"=false;

SQL> insert into auto_list_part values (9999, 3, 'z');

SQL>@sizebysegNameMB
Enter value for segment_name: auto_list_part
Enter value for owner: c##mhouri

SEGMENT_TYPE       TABLESPACE_NAME SEGMENT_NAME         PARTITION_NAME          MB
------------------ --------------- -------------------- --------------- ----------
TABLE PARTITION    USERS           AUTO_LIST_PART       P1                       8
TABLE PARTITION    USERS           AUTO_LIST_PART       P2                       8
TABLE PARTITION    USERS           AUTO_LIST_PART       P3                       8
TABLE PARTITION    USERS           AUTO_LIST_PART       SYS_P3054                8
../..
TABLE PARTITION    USERS           AUTO_LIST_PART       SYS_P3148              ,06
TABLE PARTITION    USERS           AUTO_LIST_PART       SYS_P3149              ,06
                                                                        ----------
Total Segment Size                                                          696,12

Bottom Line
While the new 12cR2 auto-list partitioning option releases you from foreseeing in advance the creation of new partitions as data arrives, it puts you under two threats (1) a roll backed insert can leave you with a bunch of empty partitions having potentially 8MB of disk space each increasing the total space occupied by your partitioned table (2) since this automatic feature creates one partition per partition key you should make sure to have many rows per partition key; otherwise the one row per partition doesn’t make sense.

Create a free website or 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)