Mohamed Houri’s Oracle Notes

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.

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's blog

Just another blog : Databases, Linux and other stuffs

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.

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)