Mohamed Houri’s Oracle Notes

October 28, 2018

Diagnosing the past using AWR: hard parse headache

Filed under: AWR — hourim @ 8:22 am

This is a document I initially wrote, almost two years ago, for one of my clients to help developers interpreting AWR reports. I believe it is interesting to share it world wide

Diagnosing the past using AWR-hard parse headache

I have two other documents concerning two others situations where AWR report has been very helpful and which I hope to share with you when I will make them publishable.

Advertisements

September 12, 2018

Troubleshooting via indexing

Filed under: Oracle — hourim @ 6:27 pm

The damage that can be inflicted by a filter predicate applied on a big table is difficult to calculate. But it is clear that it has been almost always a tragic mistake to filter a huge amount of rows from a very large table. This article outlines one of those practical cases where the creation of a chirurgical index overcame the waste of time and energy spent at the table level in a very critical third party software query.

To begin with here’s a SQL monitoring report of this critical query taken from a 12cR2 release:

SELECT
    conRef h,
    vamisin h
FROM 
  TABLEHIST h
WHERE h.typeisin <> 4
AND h.optionv NOT IN
  (SELECT  vwx.ident 
   FROM AGGREGATE_VW vwx 
   WHERE (vwx.I1 = 2298535)
  )
AND h.backclient NOT IN (106, 28387)
AND h.vamisin        IN (91071113)

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)       
 Instance ID         :  1                     
 Session             :  XXXXXX (2198:9848) 
 SQL ID              :  7v8109fkuusw3         
 SQL Execution ID    :  17529954              
 Execution Started   :  08/01/2018 04:58:31   
 First Refresh Time  :  08/01/2018 04:58:35   
 Last Refresh Time   :  08/01/2018 04:59:16   
 Duration            :  45s                   
 Module/Action       :  JDBC Thin Client/-    
 Service             :  sphpre1               
 Program             :  JDBC Thin Client      
 Fetch Calls         :  6                     

Global Stats
=================================================================
| Elapsed |   Cpu   |    IO    | Fetch | Buffer | Read  | Read  |
| Time(s) | Time(s) | Waits(s) | Calls |  Gets  | Reqs  | Bytes |
=================================================================
|      44 |    2.35 |       42 |     6 |  81930 | 39157 | 311MB |
=================================================================

SQL Plan Monitoring Details (Plan Hash Value=4122899908)
========================================================================================================
| Id |               Operation                |          Name          |   Time    | Start  |   Rows   |
|    |                                        |                        | Active(s) | Active | (Actual) |
========================================================================================================
|  0 | SELECT STATEMENT                       |                        |        42 |     +4 |    50549 |
|  1 |   HASH JOIN ANTI                       |                        |        42 |     +4 |    50549 |
|  2 |    TABLE ACCESS BY INDEX ROWID BATCHED |TABLEHIST               |        42 |     +4 |    50549 |
|  3 |     INDEX RANGE SCAN                   |TABLEHIST_IND4          |        42 |     +4 |     281K |
|  4 |    VIEW                                |                        |         1 |    +45 |    12883 |
|  5 |     CONNECT BY WITH FILTERING (UNIQUE) |                        |         1 |    +45 |    21028 |
|  6 |      INDEX RANGE SCAN                  |IDX_AGGREGAT_VIEW_IDENT |         1 |    +45 |       40 |
|  7 |      HASH JOIN                         |                        |         1 |    +45 |        0 |
|  8 |       NESTED LOOPS                     |                        |         1 |    +45 |    20988 |
|  9 |        STATISTICS COLLECTOR            |                        |         1 |    +45 |        9 |
| 10 |         CONNECT BY PUMP                |                        |         1 |    +45 |    21028 |
| 11 |        INDEX RANGE SCAN                |IDX_AGGREGAT_VIEW_IDENT |         1 |    +45 |    20988 |
| 12 |       INDEX FAST FULL SCAN             |IDX_AGGREGAT_VIEW_IDENT |           |        |          |
========================================================================================================

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("H"."OPTIONV"="IDENT")
   2 - filter(("H"."BACKCLIENT"<>:SYS_B_3 AND "H"."BACKCLIENT"<>:SYS_B_2 
           AND "H"."TYPEISIN"<>:SYS_B_0))
   3 - access("H"."VAMISIN"=:1)
   4 - filter((TO_NUMBER(REPLACE(REGEXP_SUBSTR 
                  ("IDENT_PATH",'@@(.+?)(@@|$)',1,1,HEXTORAW('5824EBC2000')),'@@',NULL))=:SYS_B_1 
              AND "IDENT">0))
   5 - access("F"."MGR"=PRIOR NULL)
   6 - access("F"."MGR"=1)
   9 - access("connect$_by$_pump$_005"."prior f.ident "="F"."MGR")
 
Note
-----
   - this is an adaptive plan 

In their attempt to fix this performance pain, DBAs and developers were focusing their efforts in reviewing the part of the execution plan that involves the hierarchical query (operation n°4 to 12).

But whoever knows how to interpret correctly the multitude information provided by the SQL monitor report would have immediately pointed out where most of the query time is spent. Look at the Start Active column of operations n°0 to 3: they all shows +4 seconds. This means that those operations started to be active 4 seconds after the beginning of the query. And whoever knows how to interpret an execution plan would have pointed out that the parent-child operation n°2-3 is the first to be started by Oracle. Look now to the Time Active(s) column of these two operations. They both indicate 42 seconds. This means that the table/index operation 2-3 took 42 seconds. Since the total duration of this query is 45 seconds we know then clearly what part of the query we have to address.

The index at operations n°3 supplied its parent table at line n°2 with 281K of rowids which has thrown away all but only 50549 using the filter predicate n°2

   2 - filter(("H"."BACKCLIENT"<>:SYS_B_3 AND "H"."BACKCLIENT"<>:SYS_B_2 
           AND "H"."TYPEISIN"<>:SYS_B_0))

Most of the 81930 buffer gets come from the TABLEHIST table at operation line n°2. We need then to engineer an index starting by the column in the predicate on which an equality is applied (VAMISIN) followed by the other three columns from the other predicates on which an inequality is applied (OPTIONV, BACKCLIENT, TYPEISIN).

SQL> create index TABLEHIST_IND_MHO on TABLEHIST 
       (VAMISIN, OPTIONV, BACKCLIENT, TYPEISIN)

Since the select part of this critical query involves only two columns of which one (VAMISIN) is already included in the new index then why not add the second selected column to this index and avoid visiting the table at all?

SQL> create index TABLEHIST_IND_MHO on TABLEHIST 
       (VAMISIN, OPTIONV, BACKCLIENT, TYPEISIN, CONREF)

Although this will increase the size of the index it has, however, the potentiality to eliminate 96% of I/O.
Indeed, following the creation of the new index, Oracle has used the following execution plan:

-------------------------------------------------------------------------------
| Id  | Operation                            | Name                   | Rows  |
-------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                     |                        |       |
|*  1 |  HASH JOIN ANTI                      |                        |     1 |
|*  2 |   INDEX RANGE SCAN                   |TABLEHIST_IND_MHO       |    49 |
|*  3 |   VIEW                               |                        |    89 |
|*  4 |    CONNECT BY WITH FILTERING (UNIQUE)|                        |       |
|*  5 |     INDEX RANGE SCAN                 |IDX_AGGREGAT_VIEW_IDENT |     5 |
|   6 |     NESTED LOOPS                     |                        |    84 |
|   7 |      CONNECT BY PUMP                 |                        |       |
|*  8 |      INDEX RANGE SCAN                |IDX_AGGREGAT_VIEW_IDENT |    17 |
-------------------------------------------------------------------------------


SQL> @sqlstats
Enter value for sql_id: 7v8109fkuusw3

     CHILD SQL_PROFILE          PLAN_HASH_VALUE   AVG_GETS    EXECS
---------- -------------------- --------------- ---------- --------
1	                           860019752       3651      204

As you can see Oracle is not visiting anymore the TABLEHIST table and the reduction of the logical I/O consumption is very remarkable as it went from 81930 to 3651.

September 11, 2018

Exploded index causes a wrong execution plan

Filed under: Oracle — hourim @ 6:57 pm

A couple of days ago I have been asked to look at performance issue which occurred in a very simple delete statement. Below is this delete with its good and bad execution plan respectively:

SQL_ID gq3khfnctny4h
--------------------
DELETE FROM table_t1 WHERE evt_id = :1  AND eng_id = :2
 
Plan hash value: 1362912592 
-----------------------------------------------------------------
| Id  | Operation          | Name          | Rows  | Cost (%CPU)|
-----------------------------------------------------------------
|   0 | DELETE STATEMENT   |               |       |     3 (100)|
|   1 |  DELETE            | TABLE_T1      |       |            |
|   2 |   INDEX UNIQUE SCAN| PK_TABLE_T117 |     1 |     3   (0)| -- cost = 3
-----------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
    2 - access("EVT_ID"=:1 AND "ENG_ID"=:2)
SQL_ID gq3khfnctny4h
--------------------
DELETE FROM table_t1 WHERE evt_id = :1  AND eng_id = :2
 
Plan hash value: 3057265474 
-------------------------------------------------------------------
| Id  | Operation             | Name          | Rows  |Cost (%CPU)|
-------------------------------------------------------------------
|   0 | DELETE STATEMENT      |               |       |    2 (100)|
|   1 |  DELETE               | TABLE_T1      |       |           |
|   2 |   INDEX FAST FULL SCAN| PK_TABLE_T117 |     1 |    2   (0)| -- cost = 2
-------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
    2 - access("EVT_ID"=:1 AND "ENG_ID"=:2)

The statistics of the different executions of this delete over the last couple of weeks are:

SQL> @HistStats
Enter value for sql_id: gq3khfnctny4h
Enter value for from_date: 01092018

SNAP_BEGIN                PLAN_HASH_VALUE    EXECS END_OF_FETCH  AVG_ETIME  AVG_LIO   AVG_ROWS
------------------------- --------------- -------- ------------ ---------- -------- ----------
04-SEP-18 01.00.23.666 PM      1362912592     5109         5109          0     19.3          1 -- good execution plan
04-SEP-18 02.00.32.471 PM      1362912592      574          574          0       20          1
04-SEP-18 03.00.48.319 PM      1362912592     1472         1472          0       20          1
05-SEP-18 08.00.10.847 AM      1362912592     3378         3378          0     19.4          1
05-SEP-18 05.00.04.444 PM      1362912592    17759        17759          0     19.7          1
05-SEP-18 08.00.43.235 PM      1362912592   201040       201040          0     18.6          1
05-SEP-18 09.00.30.871 PM      1362912592    59826        59826          0     19.7          1
05-SEP-18 10.01.28.933 PM      1362912592   140850       140850          0     17.7          1
06-SEP-18 12.01.11.664 AM      1362912592    17951        17951          0     22.9          1
06-SEP-18 09.00.31.336 AM      3057265474    22899        22899         19   2136.5          1 -- bad plan switch 
06-SEP-18 10.00.44.721 AM      3057265474    45736        45736         14     1315          1
06-SEP-18 11.00.48.929 AM      3057265474    56729        56729         11  37105.8          1
06-SEP-18 05.00.43.993 PM      3057265474    48568        48568         12    11275          1

As you can see, when the delete statement switched from an execution plan using a INDEX UNIQUE SCAN (1362912592) to an execution plan using an INDEX FAST FULL SCAN (3057265474) of the same primary key index, the average elapsed time of the delete went from 0 to 19 seconds.

The AVG_ROWS column above clearly shows that we are always deleting a single row. This is because the two columns of the predicate part represent the two primary key columns (evt_id, eng_id). So why on earth would Oracle FAST FULL scan an entire index to end up by locating a single row and delete it?

If you look back to the above execution plan you will realize that Oracle has completely messed up its estimations as it has considered that FAST FULL scanning the PK_TABLE_T117 primary key index will cost only 2 while the cost of unique scanning the same index would be 3. This is why it has switched for the bad execution plan causing a serious performance issue.

The statistics of this unique index are:

SQL> select
        index_name
      , blevel
      , leaf_blocks
      , distinct_keys
      , num_rows
      , clustering_factor
      , sample_size    
    from user_indexes
    where index_name = 'PK_TABLE_T117';

INDEX_NAME     BLEVEL LEAF_BLOCKS DISTINCT_KEYS   NUM_ROWS CLUSTERING_FACTOR SAMPLE_SIZE 
-------------- ------ ----------- ------------- ---------- ----------------- ----------- 
PK_TABLE_T117       3       28860        524234     524234            348959      524234   

Since I have at my disposable a PRE-PRODUCTION copy of this database I decided to get the same index statistics from this database:

SQL> select
        index_name
      , blevel
      , leaf_blocks
      , distinct_keys
      , num_rows
      , clustering_factor
      , sample_size    
    from user_indexes
    where index_name = 'PK_TABLE_T117';

INDEX_NAME      BLEVEL LEAF_BLOCKS DISTINCT_KEYS   NUM_ROWS CLUSTERING_FACTOR SAMPLE_SIZE 
-------------- ------- ----------- ------------- ---------- ----------------- ----------- 
PK_TABLE_T117        2       21470        617240     617240            190479      617240 

How could a BLEVEL of an index be equal to 3 in PRODUCTION and the BLEVEL of the same index with much more rows be equal to 2 in another database?

That’s probably an indication of an exploded index due to the delete and its pattern. Let’s check this using a little bit enhanced Jonathan Lewis script

SQL> @IndexEfficiency2
Enter value for m_schemaname: xxxx
../..
PK_TABLE_T117
      Current Index Size GB: 1.44         Expected Index size GB: .07

This index certainly needs a rebuild

SQL> alter index PK_TABLE_T117 rebuild online;
SQL> select
            index_name
          , blevel
          , leaf_blocks
          , distinct_keys
          , num_rows
          , clustering_factor
          , sample_size      
     from user_indexes
     where index_name = 'PK_TABLE_T117';

INDEX_NAME      BLEVEL LEAF_BLOCKS DISTINCT_KEYS   NUM_ROWS CLUSTERING_FACTOR SAMPLE_SIZE 
-------------- ------- ----------- ------------- ---------- ----------------- ----------- 
PK_TABLE_T117        2        1461        524202     524202            348956      524202

SQL> @sizeBySegName
Enter value for segment_name: PK_TABLE_T117
Enter value for owner: xxxx

SEGMENT_TYPE       TABLESPACE_NAME  SEGMENT_NAME      GB
------------------ ---------------- --------------- -----
INDEX              IDX              PK_TABLE_T117   .0117
                                                    ------
Total Segment Size                                  .0117 

And here’s below the new execution plan:

SQL> explain plan for
     DELETE FROM table_t1 WHERE evt_id = :1  AND eng_id = :2;
  
SQL> select * from table(dbms_xplan.display);

--------------------------------------------------------------------
| Id  | Operation          | Name          | Rows  | Bytes | Cost  |
--------------------------------------------------------------------
|   0 | DELETE STATEMENT   |               |     1 |    31 |     2 |
|   1 |  DELETE            | TABLE_T1|     |       |       |
|   2 |   INDEX UNIQUE SCAN| PK_TABLE_T117 |     1 |    31 |     2 | -- cost = 2
--------------------------------------------------------------------

SQL> explain plan for 
    delete /*+ index_ffs(TABLE_T1, PK_TABLE_T117) */ table_t1 
    WHERE evt_id = :1  AND eng_id = :2;

SQL> select * from table(dbms_xplan.display);

----------------------------------------------------------------------
| Id  | Operation             | Name          | Rows  | Bytes | Cost  |
-----------------------------------------------------------------------
|   0 | DELETE STATEMENT      |               |     1 |    31 |   402 |
|   1 |  DELETE               | TABLE_T1      |       |       |       |
|   2 |   INDEX FAST FULL SCAN| PK_TABLE_T117 |     1 |    31 |   402 | -- cost = 402
-----------------------------------------------------------------------

CONCLUSION

I have never considered rebuilding an index to be a reliable tuning strategy. This is why, I have already ousted this operation from my list of tuning steps. But, as Tom Kyte says “always is never true, never is always false”, it is then interesting to see practical real life cases where rebuilding index reveals to be a fix for a wrong execution plan choice.

August 17, 2018

Wrong utilisation of Result Cache

Filed under: result cache — hourim @ 5:43 pm

Still, not everyone is so in love with the Oracle result cache feature. Franck Pachot has already explained why here and here. In this article I will show you a practical real life case where result cache has been wrongly used. A couple of weeks ago I had to look at an annoying sporadic 5 to 10 min spike occurring randomly during the day. A simple ASH query during the spike shows high CPU consumption coupled with a latch free wait event popping up at the TOP. Using ASH again I found that almost all latch free wait events were due to the following TOP query:

1. Real life case

SQL> select sql_id, count(1)
    from gv$active_session_history
    where
        sample_time between to_date('03082018 10:00:00', 'ddmmyyyy hh24:mi:ss')
                    and     to_date('03082018 11:00:00', 'ddmmyyyy hh24:mi:ss')
    and event = 'latch free'
    group by sql_id
    order by 2 desc;

SQL_ID            COUNT(1)
--------------- ----------
3djqkyz0taafr           77 -->
                        15
9fxqwts01uzzw            6
43sh58j74rr0a            2
b7qrux84y1hna            1
dr3s0wjmn5h2s            1
g4k4tt8uh1tv6            1

The corresponding SQL monitoring report outlines the evidence:

SQL Text
------------------------------
SELECT
  /*+ RESULT_CACHE */
  {list_of_columns}
FROM table
WHERE 
  {list_of_predicates}
ORDER BY col1;

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)     
 Instance ID         :  1                   
 SQL ID              :  3djqkyz0taafr       
 SQL Execution ID    :  21511509            
 Execution Started   :  08/01/2018 10:48:03 
 First Refresh Time  :  08/01/2018 10:48:15 
 Last Refresh Time   :  08/01/2018 10:48:21 
 Duration            :  18s                  
 Fetch Calls         :  1                

Global Stats
===========================================================================
| Elapsed |   Cpu   |    IO    |  Other   | Fetch | Buffer | Read | Read  |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes |
===========================================================================
|      18 |    0.05 |     0.86 |       17 |     1 |   1656 |  654 |   5MB |
===========================================================================

SQL Plan Monitoring Details (Plan Hash Value=289067707)
==========================================================================================================
| Id |            Operation            |            Name            | Execs |   Rows   | Activity Detail |
|    |                                 |                            |       | (Actual) |   (# samples)   |
==========================================================================================================
|  0 | SELECT STATEMENT                |                            |     1 |        0 |                 |
|  1 |   RESULT CACHE                  | gv2j746786jamb4s329xj0ur8g |     1 |        0 | latch free (18) |
|  2 |    FILTER                       |                            |     1 |     1540 |                 |
|  3 |     TABLE ACCESS BY INDEX ROWID | HIST_TABLE                 |     1 |     1540 |                 |
|  4 |      INDEX RANGE SCAN           | HIST_IDX                   |     1 |     1540 |                 |
==========================================================================================================

As you can see out of the 18 seconds of the total query response time, 18 were due to the wait event latch free. This latch free itself is caused by what seems to be a wrong utilisation of the result cache hint.

Of course that was the ideal moment to use the so-famous Tanel Poder latchprof.sql script, which, when launched, shows the following picture:

SQL> @latchprof sid,name,sqlid % "Result" 100000

-- LatchProf 2.02 by Tanel Poder ( http://www.tanelpoder.com )

       SID NAME                     SQLID               Held       Gets  Held % 
---------- ------------------------ ------------- ---------- ---------- ------- 
      1753 Result Cache: RC Latch   3djqkyz0taafr        248         62     .25 
       298 Result Cache: RC Latch   3djqkyz0taafr        151         45     .15 
        35 Result Cache: RC Latch   3djqkyz0taafr        148         32     .15 
      3671 Result Cache: RC Latch   3djqkyz0taafr        136         35     .14 
      2681 Result Cache: RC Latch   3djqkyz0taafr        130         34     .13 
       273 Result Cache: RC Latch   3djqkyz0taafr         94         18     .09 
      1238 Result Cache: RC Latch   6hbsjju24n8d1         56         56     .06 

Not only did the latchprof.sql succeed to show 7 different sessions waiting on Result Cache: RC Latch wait event; but it outlined also that all those sessions were executing the same query already spotted above via ASH and SQL monitor report.

Close on the heels of the above latchprof.sql script, I executed the following query to check the content of result cache object view:

SQL> select
         to_char(dbms_sqltune.sqltext_to_signature(name, 1))
        , count(1)
     from
        gv$result_cache_objects
     group by
        to_char(dbms_sqltune.sqltext_to_signature(name, 1))
     having count(1) > 3
     order by 2 desc;

TO_CHAR(DBMS_SQLTUNE.SQLTEXT_TO_SIGNATUR   COUNT(1)
---------------------------------------- ----------
11688800737312996943                         106782 --> this is a portion of 3djqkyz0taafr
778588378770889215                              879
9760132213098432565                              62
13511637134398334555                              7
10994613278769629249                              7
13666841246362081009                              6
2234831540847838164                               5
16412641633620715561                              4

8 rows selected.

I don’t think that it is normal to see so many rows (106,782) for the same force matched cache_id into the result cache object memory. This is rather an indication of something trashing the result cache.

Another clue about this miss-utilisation of the result cache resides in the high number of invalidation for the same force matched name as shown below:

select 
    status
  , count(1)
  from
    gv$result_cache_objects
where 
   to_char(dbms_sqltune.sqltext_to_signature(name, 1)) = '11688800737312996943'
  group by status;
  
  STATUS      COUNT(1)
--------- ----------
Invalid        77583
Published      30185
New	           1

At this stage of the investigation, there was enough low-level evidence to have some cause for concern about the result cache wrong utilisation done by this query. This is why I asked the developer to get rid of the

 /*+ result_cache */ 

hint, tracked back the new sql_id and confirmed the disappearance of the Result Cache: RC Latch wait event.

2. General case

For the sake of completeness I will try to show, below, how attractive the result cache pool looks like when it is very well used and when it isn’t:

exec dbms_result_cache.flush();

alter session set cursor_sharing=force;

declare
    x number;
begin
    for i in 1..&1 loop
    	execute immediate 'select /*+ result_cache */ mgr from emp where sal >= 1000          
                  and rownum=1' into x;	
    end loop;
end;
/		
Enter value for 1: 100

PL/SQL procedure successfully completed. 

All what I did is:

  • Flush the result cache memory
  • Force the cursor sharing in order to use system bind variable
  • Execute 100 times an exactly identical query using the same bind variable value at each execution

And here’s below how the result cache memory looks like in this particular ideal case:

 select
   to_char(dbms_sqltune.sqltext_to_signature(name, 1))
   ,count(1)
 from
   gv$result_cache_objects
 where
  type != 'Dependency'
 group by
   to_char(dbms_sqltune.sqltext_to_signature(name, 1))
 having count(1) >= 1
 order by 2 desc;

TO_CHAR(DBMS_SQLTUNE.SQLTEXT_TO_SIGNATUR   COUNT(1)
---------------------------------------- ----------
9830716796482200263                               1

select 
    status
  , scan_count 
  , count(1)
  from
    gv$result_cache_objects
where 
   to_char(dbms_sqltune.sqltext_to_signature(name, 1)) = ‘9830716796482200263’
and type != 'Dependency'
group by 
    status
   ,scan_count
order by 3 desc
    ;    

STATUS    SCAN_COUNT   COUNT(1)
--------- ---------- ----------
Published         99          1

The presence of a single row in gv$result_cache_objects is a clear indication of the result cache being very well reused. The scan_count figure indicates that out of 100 executions we’ve initiated 99 scans in the cached result. This is a perfect use of the result cache feature.

But let’s now disturb a little bit this ideal setup by changing the above PL/SQL anonymous block so that cached result will not be always found and re-used because of different bind variable values used for the last 30 executions:

exec dbms_result_cache.flush();

declare
    x number;
begin
    for i in 1..&1 loop
     if i <= 70 then execute immediate 'select /*+ result_cache */ mgr from emp where sal >= 1000          
                  and rownum=1' into x;	
     else
       execute immediate 'select /*+ result_cache */ mgr from emp where sal >= '||2*i          
                  || 'and rownum=1' into x;	

     end if;
    end loop;
end;
/		
Enter value for 1: 100

PL/SQL procedure successfully completed. 

And here’s below how the result cache memory looks like now:

 select
     to_char(dbms_sqltune.sqltext_to_signature(name, 1))
    ,count(1)
 from
    gv$result_cache_objects
 where
  type != 'Dependency'
 group by
    to_char(dbms_sqltune.sqltext_to_signature(name, 1))
 having count(1) >= 1
 order by 2 desc;

TO_CHAR(DBMS_SQLTUNE.SQLTEXT_TO_SIGNATUR   COUNT(1)
---------------------------------------- ----------
9830716796482200263                              31

select 
    status
  , scan_count 
  , count(1)
  from
    gv$result_cache_objects
where 
   to_char(dbms_sqltune.sqltext_to_signature(name, 1)) = '9830716796482200263'
and type != 'Dependency'
group by 
    status
   ,scan_count
order by 3 desc;    

STATUS    SCAN_COUNT   COUNT(1)
--------- ---------- ----------
Published          0         30
Published         69          1

Since I have used 30 different bind variable values for the last 30 executions I have then failed to initiate any scan count into the result cache for these particular executions. However the first 70 executions have perfectly re-used the result cache 69 times (the first execution is the one that stored the result cache).

You might have probably already guessed that we can fail reusing a stored result cache even in the absence of any dependent object invalidation. It suffices, as shown via the above 30 particular query executions, to use a different bind variable value to produce a new not already cached result. But let’s now introduce a couple of invalidations in the above setup:

exec dbms_result_cache.flush();

declare
    x number;
begin
    for i in 1..&1 loop
     if i <= 50 then execute immediate 'select /*+ result_cache */ mgr from emp where sal >= 1000          
                  and rownum=1' into x;	
     elsif mod(i,3) = 0 then
      execute immediate 'alter table emp modify (sal default 42)';
      execute immediate 'select /*+ result_cache */ mgr from emp where sal >= 1000          
                  and rownum=1' into x;	
     else
      execute immediate 'select /*+ result_cache */ mgr from emp where sal >= 1000          
                  and rownum=1' into x;	
     end if;
    end loop;
end;
/	
Enter value for 1: 100

PL/SQL procedure successfully completed.	

All what I did above is launch a query 100 times with:

  • The first 50 executions using the same bind variable value and thereby using the result cache
  • The next 50 executions flip flopping between reusing a result cache and failing to reuse it because of a DDL on the result cache dependent table
select
   to_char(dbms_sqltune.sqltext_to_signature(name, 1))
   ,count(1)
from
   gv$result_cache_objects
where
   type != 'Dependency'
group by
   to_char(dbms_sqltune.sqltext_to_signature(name, 1))
   having count(1) >= 1
order by 2 desc;

TO_CHAR(DBMS_SQLTUNE.SQLTEXT_TO_SIGNATUR   COUNT(1)
---------------------------------------- ----------
9830716796482200263                              18
SQL> @getRCStatus.sql
Enter value for force_match_sign: 9830716796482200263

STATUS                    SCAN_COUNT        CNT
------------------------- ---------- ----------
Invalid                           49          1
Invalid                            2         16
Published                          1          1
                                     ----------
Total cache creation                         18 

The output of the query above shows that the 100 executions have been decomposed as follows:

  • 1 execution (the first one) + 49 hits of the result cache for the next 49 executions
  • 16 invalidations with scan count = 2 meaning that 32 executions hit the cache before being invalidated
  • And since there are 18 rows (16 +1+1) in the result cache this means that they inevitably correspond to 18 result cache creations : the first execution and the 17 other one following each of the 17 invalidations.

And here we are done: 1+ 49 + 32 + 18 make the 100 executions.

Oracle gives also a way to retrieve statistics on the cache memory usage via the following package call:

SQL> exec dbms_result_cache.Memory_Report
R e s u l t   C a c h e   M e m o r y   R e p o r t
[Parameters]
Block Size          = 1K bytes
Maximum Cache Size  = 10496K bytes (10496 blocks)
Maximum Result Size = 524K bytes (524 blocks)
[Memory]
Total Memory = 205320 bytes [0.016% of the Shared Pool]
... Fixed Memory = 12592 bytes [0.001% of the Shared Pool]
... Dynamic Memory = 192728 bytes [0.015% of the Shared Pool]
....... Overhead = 159960 bytes
....... Cache Memory = 32K bytes (32 blocks)
........... Unused Memory = 13 blocks
........... Used Memory = 19 blocks
............... Dependencies = 1 blocks (1 count)
............... Results = 18 blocks
................... SQL     = 1 blocks (1 count)
................... Invalid = 17 blocks (17 count)

PL/SQL procedure successfully completed. 

This output doesn’t say anything else then what the following query lists:

select 
   status 
  ,count(*) 
  ,round(max(scan_count)) max_scan_cnt
  ,round(sum(block_count)) tot_blk_cnt
from 
  gv$result_cache_objects
where
  to_char(dbms_sqltune.sqltext_to_signature(name, 1)) = '9830716796482200263'
and type = 'Result'
group by 
  status; 

STATUS      COUNT(*) MAX_SCAN_CNT TOT_BLK_CNT
--------- ---------- ------------ -----------
Invalid           17           49          17
Published          1            1           1
  • There are 18 result cache creations : Results = 18 blocks
  •  One result cache has been created and published : SQL = 1 blocks (1 count)
  •  17 result caches have been invalidated : Invalid = 17 blocks (17 count)

3. Summary

The SQL query result cache can introduce a serious performance threat if not correctly used. In the same vein as you want to parse once and execute many, you would also like to store a result cache once and reuse it many times. To do so you need to take care that the query you intend to cache the result will almost always return the same result (use the same bind variable values). You will also take care to keep the result in the result cache pool valid as long as possible. To do so you will try to avoid DMLing or DDLing the SQL query dependent objects.

July 7, 2018

Subquery unnesting that does not require costing

Filed under: Subquery Unnesting — hourim @ 6:16 am

There are two types of subquery unnesting: the first one is merged by the CBO with its outer query and the second one is turned into an inline view before being, eventually, merged with its outer query. While the latter is cost based, the former is imperatively done provided it passes the subquery unnesting validity check. This is why, we may, sometimes, pay a performance penalty because of the automatic subquery unnesting.

Automatic subquery unnesting that does not require costing

This is precisely what I have experienced at one of my customer sites:

insert into t1_targ
     (id)
select
     t2_id
from
     t2 lt1
where
     t2.l_id > 0
and  t2.status in (0,1,3)
and  t2.class = 'XyyZgg'
and EXISTS
         (select null
          from t2 lt2
          where lt2.t1_id  = lt1.l_id
          and   lt2.status = 2
          and   lt2.class != 'XyyZgg'
          );
Global Stats
=========================================
| Elapsed |   Cpu   |  IO      | Buffer |
| Time(s) | Time(s) | Waits(s) |  Gets  |
=========================================
|    4070 |    343  |     3724 |   31M  |
=========================================

SQL Plan Monitoring Details (Plan Hash Value=1860787001)
===================================================================
| Id    |                 Operation                   |       Name |
|       |                                             |            |
===================================================================
|     0 | INSERT STATEMENT                            |            |
|     1 |   LOAD TABLE CONVENTIONAL                   | T1_ARG     |
|     2 |    HASH JOIN                                |            |
|     3 |     NESTED LOOPS                            |            |        
|     4 |      NESTED LOOPS                           |            |
|     5 |       STATISTICS COLLECTOR                  |            |
|     6 |        INLIST ITERATOR                      |            |
|     7 |         TABLE ACCESS BY INDEX ROWID BATCHED | T2         |
|     8 |          INDEX RANGE SCAN                   | IDX_T262   |
|     9 |       INDEX UNIQUE SCAN                     | PK_T250    |
|    10 |     TABLE ACCESS BY INDEX ROWID             | T2         |
|    11 |    TABLE ACCESS BY INDEX ROWID BATCHED      | T2         |
|    12 |     INDEX SKIP SCAN                         | IDX_T262   |
===================================================================

As you can see the EXISTS subquery has been unnested and merged into the body of the outer query to form a join as the following lines taken from the corresponding 10053 trace file prove:

*****************************
Cost-Based Subquery Unnesting
*****************************
SU: Unnesting query blocks in query block SEL$1 (#1) that are valid to unnest.
Subquery Unnesting on query block SEL$1 (#1)SU: Performing unnesting that does not require costing. -- automatic
SU: Considering subquery unnest on query block SEL$1 (#1).
SU:   Checking validity of unnesting subquery SEL$2 (#2)
SU:   Passed validity checks. -- subquery is valid for unnesting
SU:   Transforming EXISTS subquery to a join. -- unnesting is done here
Registered qb: SEL$5DA710D3 0x64c1aaf8 (SUBQUERY UNNEST SEL$1; SEL$2)

That is how the automatic subquery unnesting works: provided there are no restrictions pre-empting it, the unnesting will be automatically done.

if, I add a restriction (rownum <=10) into the above query, the unnesting will be bypassed as the following proves:

insert into t1_targ
     (id)
select
     t2_id
from
     t2 lt1
where
     t2.l_id > 0
and  t2.status in (0,1,3)
and  t2.class = 'XyyZgg';
and EXISTS
         (select null
          from t2 lt2
          where lt2.t1_id  = lt1.l_id
          and   lt2.status = 2
          and   lt2.class != 'XyyZgg';
          and   rownum <= 10 -- restriction
          );

===================================================================
| Id    |                 Operation                   |       Name |
===================================================================
|     0 | INSERT STATEMENT                            |            |
|     1 |   LOAD TABLE CONVENTIONAL                   | T1_ARG     |
|     2 |    INLIST ITERATOR                          |            |
|     3 |     TABLE ACCESS BY INDEX ROWID BATCHED     | T2         | 
|     4 |      INDEX RANGE SCAN                       | IDX_T262   |                       
|     5 |       COUNT STOPKEY                         |            |
|     6 |        TABLE ACCESS BY INDEX ROWID          | T2         |            
|     7 |         INDEX UNIQUE SCAN                   | PK_T250    |
===================================================================

*****************************
Cost-Based Subquery Unnesting
*****************************
SU: Unnesting query blocks in query block SEL$1 (#1) that are valid to unnest.
Subquery Unnesting on query block SEL$1 (#1)SU: Performing unnesting that does not require costing.
SU: Considering subquery unnest on query block SEL$1 (#1).
SU:   Checking validity of unnesting subquery SEL$2 (#2)
SU:     SU bypassed: Query block references ROWNUM. -- restriction
SU:   Validity checks failed.-- unnesting is bypassed

At my client site, however, automatically unnesting the subquery was a dramatic choice made by the CBO as the historical statistics of the corresponding insert/select displayed below clearly show (sometimes more than 14,000 seconds without completing):

@HistStats
Enter value for sql_id:6gryp77nfgtv8
Enter value for from_date: 15052018

SNAP_BEGIN                PLAN_HASH_VALUE EXECS END_OF_FETCH  AVG_ETIME  AVG_LIO  
------------------------- --------------- ----- ------------ ----------  --------
16-MAY-18 12.00.13.600 AM      1860787001     0            0      3607    2975544     
16-MAY-18 01.00.20.220 PM      1860787001     1            1      3062    2708725
16-MAY-18 02.00.41.960 PM      1860787001     0            0      2509    3374627
16-MAY-18 03.00.48.113 PM      1860787001     0            0      4169    4970849
16-MAY-18 04.00.54.446 PM      1860787001     0            0      7659   16659725
16-MAY-18 05.00.04.833 PM      1860787001     0            0     13342   21798355
16-MAY-18 06.00.14.538 PM      1860787001     0            0     14245   35578453
../...
17-MAY-18 08.00.59.398 PM      1860787001     0            0      3544    3627666

But immediately when I cancelled the unnesting (using /*+ no_unnest */) I got a better execution time as shown below:

@HistStats
Enter value for sql_id:6gryp77nfgtv8
Enter value for from_date: 17052018

SNAP_BEGIN                PLAN_HASH_VALUE EXECS END_OF_FETCH  AVG_ETIME  AVG_LIO  
------------------------- --------------- ----- ------------ ----------  --------
17-MAY-18 08.00.59.398 PM      1860787001     0            0     3544    3627666
18-MAY-18 11.00.30.847 AM          530894     2            2     116      528385  -- 116 sec/exec 

Cost based subquery unnesting

The subquery unnesting ceases, however, to be imperatively done whenever the subquery is transformed into an inline view. In this case, even when there is nothing preventing the subquery from being unnested, Oracle will evaluate the cost of unnesting it before proceeding to the transformation. Here’s below a typical illustration (the model is at the end of this blog post):

explain plan for
 select
     a.n1
 from
    t1 a
where
    a.n1 = 10
and exists
    (select 
	    null 
	 from
	    t1 b
	   ,t2 c
	 where
	    b.n1 = c.n1
	 and 
	    b.n2 = a.n3
    );

select * from table(dbms_xplan.display);

----------------------------------------------------------------
| Id  | Operation                    | Name    | Rows  | Bytes |
----------------------------------------------------------------
|   0 | SELECT STATEMENT             |         |     1 |     9 |
|   1 |  NESTED LOOPS SEMI           |         |     1 |     9 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1      |     1 |     7 |
|*  3 |    INDEX UNIQUE SCAN         | T1_PK   |     1 |       |
|   4 |   VIEW PUSHED PREDICATE      | VW_SQ_1 |     1 |     2 | -- subquery into view
|   5 |    NESTED LOOPS SEMI         |         |     1 |    11 |
|*  6 |     TABLE ACCESS FULL        | T1      |     3 |    21 |
|*  7 |     INDEX UNIQUE SCAN        | T2_PK   |   300 |  1200 |
----------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("A"."N1"=10)
   6 - filter("B"."N2"="A"."N3")
   7 – access("B"."N1"="C"."N1")

*****************************
Cost-Based Subquery Unnesting
*****************************
SU: Unnesting query blocks in query block SEL$1 (#1) that are valid to unnest.
Subquery Unnesting on query block SEL$1 (#1)SU: Performing unnesting that does not require costing.
SU: Considering subquery unnest on query block SEL$1 (#1).
SU:   Checking validity of unnesting subquery SEL$2 (#2)
SU:   Passed validity checks, but requires costing.  -- here where the CBO is costing the subquery unnesting
SU: Using search type: exhaustive
SU: Starting iteration 1, state space = (2) : (1)
SU:   Unnesting subquery query block SEL$2 (#2)Registered qb: SEL$683B0107 0x70409408 (SUBQ INTO VIEW FOR COMPLEX UNNEST SEL$2)

Summary

Don’t be surprised to see Oracle, sometimes, using a dramatic execution plan when it unnests a subquery. This might be related to the automatic unnesting which does not require costing. It is done by Oracle provided the subquery passes the unnesting validity check and is not transformed into an inline view prior to its unnesting.

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

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

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

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';

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.

May 25, 2018

Indexing Intelligibly

Filed under: Index — hourim @ 2:10 pm

Here’s again a simple but very practical tuning case taken from a real life running system. It started by a client complaint about a product inserting process that started to take a considerable amount of time (60 seconds per product). According to the client, it was not performing so badly a couple of days ago. And, this is sufficiently rare to be worthy of a note, the client supplied the sql_id of the query he found to be the root cause of this delay. In the next section I will explain, step by step, what I did to make my client very happy.

Get SQL monitoring report of the sql_id

And to make my task easy the sql_id was still in v$sql_monitor so that I immediately got its corresponding report (RTSM) shown below:

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)                
 Instance ID         :  1                    
 Session             :  xxxx (15:32901) 
 SQL ID              :  7bm6m1r2xsj5f        
 SQL Execution ID    :  16777216             
 Execution Started   :  04/05/2018 14:08:32  
 First Refresh Time  :  04/05/2018 14:08:38
 Last Refresh Time   :  04/05/2018 14:09:13
 Duration            :  41s                  
 Module/Action       :  JDBC Thin Client/-           
 Service             :  xxxxx            
 Program             :  JDBC Thin Client/-

Global Stats
=================================================
| Elapsed |   Cpu   |  Other   | Fetch | Buffer |
| Time(s) | Time(s) | Waits(s) | Calls |  Gets  |
=================================================
|    42   |    5.72 |     36   |    1  |  1M    |
=================================================

SQL Plan Monitoring Details (Plan Hash Value=4071256796)
========================================================================
| Id |               Operation |   Name   |  Rows   | Execs |   Rows   |
|    |                         |          | (Estim) |       | (Actual) |
========================================================================
|  0 | SELECT STATEMENT        |          |         |     1 |        1 |
|  1 |   NESTED LOOPS OUTER    |          |       1 |     1 |        1 |
|  2 |    NESTED LOOPS OUTER   |          |       1 |     1 |        1 |
|  3 |     NESTED LOOPS OUTER  |          |       1 |     1 |        1 |
.../...
| 12 |      TABLE ACCESS FULL  | T1       |       1 |    42 |        1 |
.../...
| 33 |   INDEX RANGE SCAN      | IDX-XXX  |       1 |     2 |          |
========================================================================

I didn’t have to search a lot. The query completes in 42 seconds of which 42 are due to the TABLE ACCESS FULL operation at line n°12.

But as interesting as this RTSM report is, it has a key limitation. It doesn’t report the predicate part. And as always, the predicate information is of a crucial importance to check what filters are applied on the above full table scan.

select * from table(dbms_xplan.display_cursor('7bm6m1r2xsj5f'));

Predicate Information (identified by operation id):
---------------------------------------------------
   12 – filter("XXX”.”COL1" = :3 AND "XXX”.”END_DATE" >=:5
               AND "XXX”.”START_DATE" <=:4 )
       

You don’t like speculation? Neither do I. This is why I immediately checked the following points:

  • There is no index starting by COL1 in table T1
  • And I executed the following query to check the pertinence of indexing COL1 column
SQL> select /*+ parallel(4) */ 
         col1, count(1)
     from t1
     group by col1
     order by 2 desc;

      COL1   COUNT(1)
---------- ----------
             60594499
    WTCLZ5         49
     LCOXS         47
    WTCLK1         47
     ../..

As you can see there is manifestly a design issue here as more than 99% of COL1 values are null. After I have got the confirmation from the client that the null value for COL1 is never used, I was going to create a single column index on COL1 when one of my DBA colleagues asked me the following question:

Why don’t you create a composite index on (COL1, END_DATE, START_DATE)?

And that was precisely the question that has motivated this blog post. I provided the following answer:

  • If we exclude null values, at maximum, we can filter down 49 rows from table T1 using COL1 column
  • While an inequality is applied on END_DATE and START_DATE columns an equality predicate is used against COL1
  • If we opt for the composite index (COL1, END_DATE, START_DATE) we will lose the formidable opportunity to have a very small and attractive index on COL1 since null values of COL1 will be added into the composite index.

Having sad that here’s below what happened next:

SQL> create index idx_t1_col1 on t1(COL1) parallel 4;

SQL> alter index idx_t1_col1 noparallel ;

With the new index having only 0,39GB of size out of table of 8,7GB as shown below:

SQL> @sizeBySegName
Enter value for segment_name: T1
Enter value for owner: xxxx

SEGMENT_TYPE       TABLESPACE_NAME   SEGMENT_NAME  PARTITION_NAME   GB
------------------ ----------------- ------------- --------------- -------
TABLE              XXXX               T1                            8.7012
                                                                   -------
Total Segment Size                                                  8.7012


SQL> @sizeBySegName
Enter value for segment_name: idx_t1_col1
Enter value for owner: xxxx

SEGMENT_TYPE       TABLESPACE_NAME   SEGMENT_NAME  PARTITION_NAME   GB
------------------ ----------------- ------------- --------------- ------
INDEX              XXXX               IDX_T1_COL1                  0.387
                                                                   ------
Total Segment Size                                                 0.387

Naturally the new execution plan uses the new index and resulted into a drastically improved query performance as the followings show via the new execution plan and the new elapsed time:

SQL_ID  7bm6m1r2xsj5f, child number 0
-------------------------------------
Plan hash value: 874603108

------------------------------------------------------------------------
| Id  | Operation                               | Name      | Rows     |
------------------------------------------------------------------------
|  0 | SELECT STATEMENT                         |            |         |
|  1 |   NESTED LOOPS OUTER                     |            |       1 |
|  2 |    NESTED LOOPS OUTER                    |            |       1 |
|  3 |     NESTED LOOPS OUTER                   |            |       1 |
.../...
| 12 |      TABLE ACCESS BY INDEX ROWID BATCHED | T1         |       1 |
| 13 |       INDEX RANGE SCAN                   | IDX_T1_COL1|       1 | 
|.../...                                                               |
------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   12 – filter( "XXX”.”END_DATE" >=:6 AND "XXX”.”START_DATE" <=:5 )
   13 - access("XXX”.”COL1" = :4)
SQL> @sqlstats
Enter value for sql_id: 7bm6m1r2xsj5f

     CHILD  PLAN_HASH_VALUE   GETS      ELAPS   EXECUTIONS
----------  --------------- ---------- ------  -----------
         0       874603108        11      0      897

Thanks to the new index the execution time of the client critical query dropped from 42 to 0 second and the logical I/O consumption from 1 million to only 11 buffer gets per execution.

Bottom Line

Through this simple real life example I wanted to show how crucial is the first column of an index when used in an equality predicate. I wanted also to emphasize that, sometimes, and all things being equal, it might be better to prefer a single column index to cover a multi-column where clause provided this single column is very selective and contains a bunch of null values making the single index very small and thereby very attractive to the CBO.

Next Page »

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)