Thursday, January 18, 2018

VW_TE_2 view and the wrong execution plan when Table Expansion take place

Our customer has a problem today.
The very simple queries take very different time :

select min(a.ENTRYDATE) from ORDERS_BASE a where a.ENTRYDATE < to_date('01.01.2015','dd.mm.yyyy');
select min(a.ENTRYDATE) from ORDERS_BASE a where a.ENTRYDATE < trunc(sysdate-1112);
select min(a.ENTRYDATE) from ORDERS_BASE a where a.ENTRYDATE < date '2015-01-01';


First query takes 850 second.
2nd and 3rd queries take .04 second.

Find the difference !
:(

The queries were tested at 17-JAN-2018 so trunc(sysdate-1112) == to_date('01.01.2015','dd.mm.yyyy') that day.

For clarity and for checking the difference in data types i did dump of these values:

SQL>  select dump(trunc(sysdate-1112)) from dual;

DUMP(TRUNC(SYSDATE-1112))
--------------------------------------------------------------------------------
Typ=13 Len=8: 223,7,1,1,0,0,0,0

SQL> select dump(to_date('01.01.2015','dd.mm.yyyy')) from dual;

DUMP(TO_DATE('01.01.2015','DD.M
-------------------------------
Typ=13 Len=8: 223,7,1,1,0,0,0,0

SQL> select dump(date '2015-01-01') from dual;

DUMP(DATE'2015-01-01')
-------------------------------
Typ=13 Len=8: 223,7,1,1,0,0,0,0



INVESTIGATION:

Step 0: Gather facts

DB version is 12.1.0.2.170418, Oracle on Linux x64.

Table has 65 columns:

SQL> desc ORDERS_BASE
 Name                                      Null?    Type
 ----------------------------------------- -------- ------
...
 ENTRYDATE                                          DATE

...


  CREATE TABLE "ORDERS_BASE"
   (     ...
    "ENTRYDATE" DATE,
         ...
   )
  PARTITION BY RANGE ("ENTRYDATE")
 (PARTITION "CURR_ORDERS_BASE_P_20050804"  VALUES LESS THAN (TO_DATE(' 2005-08-05 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')) SEGMENT CREATION DEFERRED ,
  PARTITION "CURR_ORDERS_BASE_P_20050805"  VALUES LESS THAN (TO_DATE(' 2005-08-06 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN')) SEGMENT CREATION DEFERRED ,
  ...
 PARTITION "CURR_ORDERS_BASE_P_20200310"  VALUES LESS THAN (TO_DATE(' 2020-03-11 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN'))  SEGMENT CREATION DEFERRED ,
 PARTITION "CURR_ORDERS_BASE_P_20200409"  VALUES LESS THAN (TO_DATE(' 2020-04-10 00:00:00', 'SYYYY-MM-DD HH24:MI:SS', 'NLS_CALENDAR=GREGORIAN'))  SEGMENT CREATION DEFERRED
 ) ;
Table has about 5000 partitions.

Table has 2 indexes:

  CREATE UNIQUE INDEX "ORDERS_CURR_UIDX" ON "ORDERS_BASE" ("ENTRYDATE", "ORDERNO")   LOCAL;

All 2014 year is in unusable state :

  ALTER INDEX "ORDERS_CURR_UIDX"  MODIFY PARTITION "CURR_ORDERS_BASE_P_20140101" UNUSABLE;
  ...
  ALTER INDEX "ORDERS_CURR_UIDX"  MODIFY PARTITION "CURR_ORDERS_BASE_P_20141231" UNUSABLE;



  CREATE INDEX "ORDER_CURR_ORDNO_IDX" ON "ORDERS_BASE" ("ORDERNO")   LOCAL;

All 2014 year is in unusable state :

  ALTER INDEX "ORDER_CURR_ORDNO_IDX"  MODIFY PARTITION "CURR_ORDERS_BASE_P_20140101" UNUSABLE;
  ...
  ALTER INDEX "ORDER_CURR_ORDNO_IDX"  MODIFY PARTITION "CURR_ORDERS_BASE_P_20141231" UNUSABLE;



Step 1: Lets measure

SQL> select min(a.ENTRYDATE) from ORDERS_BASE a where a.ENTRYDATE < trunc(sysdate-1112);

MIN(A.ENTRYDATE)
-------------------
10.01.2006 00:00:00

Elapsed: 00:00:00.04

SQL> select min(a.ENTRYDATE) from ORDERS_BASE a where a.ENTRYDATE < date '2015-01-01';

MIN(A.ENT
---------
10-JAN-06

Elapsed: 00:00:00.04

SQL> select min(a.ENTRYDATE) from ORDERS_BASE a where a.ENTRYDATE < to_date('01.01.2015','dd.mm.yyyy');

MIN(A.ENTRYDATE)
-------------------
10.01.2006 00:00:00

Elapsed: 00:14:10.64




Step 2: Lets look at the execution plan

The good plan at first:

SQL> set autotrace on
SQL> set lines 999 pages 99
SQL> select min(a.ENTRYDATE) from ORDERS_BASE a where a.ENTRYDATE < trunc(sysdate-1112);

MIN(A.ENTRYDATE)
-------------------
10.01.2006 00:00:00

Elapsed: 00:00:00.02

Execution Plan
----------------------------------------------------------
Plan hash value: 2553418393

----------------------------------------------------------------------------------------------------------------
| Id  | Operation                        | Name        | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                 |             |     1 |     8 |  1404K (65)| 00:00:36 |       |       |
|   1 |  PARTITION RANGE ITERATOR MIN/MAX|             |     1 |     8 |            |          |     1 |   KEY |
|   2 |   SORT AGGREGATE                 |             |     1 |     8 |            |          |       |       |
|*  3 |    TABLE ACCESS STORAGE FULL     | ORDERS_BASE |  9195M|    68G|  1404K (65)| 00:00:36 |     1 |   KEY |
----------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - storage("A"."ENTRYDATE"<TRUNC(SYSDATE@!-1112))
       filter("A"."ENTRYDATE"<TRUNC(SYSDATE@!-1112))

Statistics
----------------------------------------------------------
          0  recursive calls
          2  db block gets
         19  consistent gets
         13  physical reads
          0  redo size
        555  bytes sent via SQL*Net to client
        552  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

Here i added the dummy hint to force hard parsing and generate the new plan:

SQL> select /*+ U */ min(a.ENTRYDATE) from ORDERS_BASE a where a.ENTRYDATE < trunc(sysdate-1112);

MIN(A.ENTRYDATE)
-------------------
10.01.2006 00:00:00

Elapsed: 00:00:00.03

Execution Plan
----------------------------------------------------------
Plan hash value: 2553418393

----------------------------------------------------------------------------------------------------------------
| Id  | Operation                        | Name        | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                 |             |     1 |     8 |  1404K (65)| 00:00:36 |       |       |
|   1 |  PARTITION RANGE ITERATOR MIN/MAX|             |     1 |     8 |            |          |     1 |   KEY |
|   2 |   SORT AGGREGATE                 |             |     1 |     8 |            |          |       |       |
|*  3 |    TABLE ACCESS STORAGE FULL     | ORDERS_BASE |  9195M|    68G|  1404K (65)| 00:00:36 |     1 |   KEY |
----------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - storage("A"."ENTRYDATE"<TRUNC(SYSDATE@!-1112))
       filter("A"."ENTRYDATE"<TRUNC(SYSDATE@!-1112))

Statistics
----------------------------------------------------------
          1  recursive calls
          2  db block gets
         19  consistent gets
         13  physical reads
          0  redo size
        555  bytes sent via SQL*Net to client
        552  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

After hard parsing the new plan was generated and we see the no difference.
Oracle strongly keep the best plan.

Let probe the bad query:

SQL> select  min(a.ENTRYDATE) from ORDERS_BASE a where a.ENTRYDATE < to_date('01.01.2015','dd.mm.yyyy');

MIN(A.ENTRYDATE)
-------------------
10.01.2006 00:00:00

Elapsed: 00:14:10.64

Execution Plan
----------------------------------------------------------
Plan hash value: 2334607833

-------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name        | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
-------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |             |     1 |     8 |   285K (31)| 00:00:08 |       |       |
|   1 |  SORT AGGREGATE               |             |     1 |     8 |            |          |       |       |
|   2 |   VIEW                        | VW_TE_2     |  9195M|    77G|   285K (31)| 00:00:08 |       |       |
|   3 |    UNION-ALL                  |             |       |       |            |          |       |       |
|   4 |     PARTITION RANGE ITERATOR  |             |  6615M|    49G|   195K (30)| 00:00:05 |     1 |  3072 |
|   5 |      TABLE ACCESS STORAGE FULL| ORDERS_BASE |  6615M|    49G|   195K (30)| 00:00:05 |     1 |  3072 |
|   6 |     PARTITION RANGE ITERATOR  |             |  2579M|    19G| 89337  (32)| 00:00:03 |  3073 |  3437 |
|   7 |      TABLE ACCESS STORAGE FULL| ORDERS_BASE |  2579M|    19G| 89337  (32)| 00:00:03 |  3073 |  3437 |
-------------------------------------------------------------------------------------------------------------

Statistics
----------------------------------------------------------
        657  recursive calls
       3206  db block gets
   17682261  consistent gets
   17666575  physical reads
        120  redo size
        555  bytes sent via SQL*Net to client
        552  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed


We see absolutely different plan:
- ONE full table scan has become TWO table scans
- and the view VW_TE_2 appeared

Let find the information about this view. I suppose the chars T and E may be in russian codepage
(russian chars with the T and E image), so I excluded them and left only english chars.
And I supposed that there may be leading and trailing spaces  (invisible chars).
Therefore i searched the  like '%VW%2%'.

[~]$ sqlplus / as sysdba

SQL*Plus: Release 12.1.0.2.0 Production on Wed Jan 17 17:21:04 2018
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production

Is it the view ?
SQL> select * from dba_views where view_name like '%VW%2%';
no rows selected

Is it the synonym ?
SQL> select * from SYS.DBA_SYNONYMS where synonym_name like '%VW%2%' ;
no rows selected

What is the object ?
SQL> select * from dba_objects where object_name like '%VW%2%';
no rows selected

SQL> select * from sys.obj$ where name like '%VW%2%';
no rows selected


Obvious, there is no such view in the dictionary !
What's the hell ? Where the view VW_TE_2 was taken from ? 


Step 3: Let look VW_TE_2 in the support.oracle.com and in Internet


Great! One of my friends have wrote some post with VW_TE_2 view:
https://iusoltsev.wordpress.com/2014/06/25/table-expansion-features/

This is the Table Expansion feature:  https://blogs.oracle.com/optimizer/optimizer-transformations:-table-expansion

This feature is applicable for queries on partitioned tables which have local indexes.
Oracle can have access to table rows via index or directly to table using full table/partition scan.
And during parse Optimizer decide which path is better.
In some cases when the query benefits from index access path then Oracle can take the data from the index and not touch the table rows.
Index-only access path, "Fast Full Index Scan" for example.

And what to do if our query benefits from index-only access, but some index partitions are in UNUSABLE state ?
Table expansion take place here !
It is just my case.

Optimizer divide one query to two similar sub-queries.
One sub-query is go to table rows (not use index) and scan particular partitions.
Other sub-query is using index (local partitions which are in USABLE state).
As you can see in my post above.

Look at the last two columns of plan table. These columns show Pstart Pstop partitons of the table:
-----------------
| Pstart| Pstop |
-----------------
|       |       |
|       |       |
|       |       |
|       |       |
|     1 |  3072 |
|     1 |  3072 |
|  3073 |  3437 |
|  3073 |  3437 |
-----------------


As you can see the one sub-query scans the 1-3072 partitions, and 2nd sub-query scans 3073-3437 partitions.

Step 4: how to disable TE ?

If my diagnose about TE feature is correct, then after disabling this feature the long-running query will go fast.
It will confirm my diagnose.

Internet helped to find two hints:

-  /*+ opt_param('_optimizer_table_expansion', 'false') */ - will disable TE
-  /*+ EXPAND_TABLE(tab_alias) */   - will force TE

The query has 3 form of predicates:
- date '2015-01-01'
- trunc(sysdate-1112) ( for today 18-JAN-2018 we use trunc(sysdate-1113) and so on...)
- to_date('01.01.2015','dd.mm.yyyy')


In our case we have an issue. The syntax " date '2015-01-01' " and " trunc(sysdate-1112) " prevent the table expansion feature:

- date '2015-01-01'                  - no TE and fast plan
- trunc(sysdate-1112)                - no TE and fast plan
- to_date('01.01.2015','dd.mm.yyyy') - TE take place and wrong plan.



Therefore we can make two experiments:
- disabling TE for bad query will lead to good plan and short time
- forcing TE for good queries will lead to bad plan and long time


SQL> set lines 999 pages 99
SQL> set timing on
SQL> set autot on
SQL> select /*+ opt_param('_optimizer_table_expansion', 'false') */  min(a.ENTRYDATE) from ORDERS_BASE a where a.ENTRYDATE < to_date('01.01.2015','dd.mm.yyyy');

MIN(A.ENT
---------
10-JAN-06

Elapsed: 00:00:00.04

Execution Plan
----------------------------------------------------------
Plan hash value: 2553418393

----------------------------------------------------------------------------------------------------------------
| Id  | Operation                        | Name        | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                 |             |     1 |     8 |   309K (30)| 00:00:08 |       |       |
|   1 |  PARTITION RANGE ITERATOR MIN/MAX|             |     1 |     8 |            |          |     1 |  3437 |
|   2 |   SORT AGGREGATE                 |             |     1 |     8 |            |          |       |       |
|   3 |    TABLE ACCESS STORAGE FULL     | ORDERS_BASE |  9195M|    68G|   309K (30)| 00:00:08 |     1 |  3437 |
----------------------------------------------------------------------------------------------------------------


Statistics
----------------------------------------------------------
          0  recursive calls
          2  db block gets
         19  consistent gets
         13  physical reads
          0  redo size
        555  bytes sent via SQL*Net to client
        552  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

Great, be obtain the good plan and short time !

Try aggravate the good plan:

SQL> select /*+ EXPAND_TABLE(a) */  min(a.ENTRYDATE) from ORDERS_BASE a where a.ENTRYDATE < date '2015-01-01';

MIN(A.ENT
---------
10-JAN-06

Elapsed: 00:13:29.91

Execution Plan
----------------------------------------------------------
Plan hash value: 2354560326

-------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name        | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
-------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |             |     1 |     9 |   347K (43)| 00:00:09 |       |       |
|   1 |  SORT AGGREGATE               |             |     1 |     9 |            |          |       |       |
|   2 |   VIEW                        | VW_TE_1     |  9195M|    77G|   347K (43)| 00:00:09 |       |       |
|   3 |    UNION-ALL                  |             |       |       |            |          |       |       |
|   4 |     PARTITION RANGE ITERATOR  |             |  6615M|   123G|   240K (43)| 00:00:07 |     1 |  3072 |
|   5 |      TABLE ACCESS STORAGE FULL| ORDERS_BASE |  6615M|   123G|   240K (43)| 00:00:07 |     1 |  3072 |
|   6 |     PARTITION RANGE ITERATOR  |             |  2579M|    48G|   106K (43)| 00:00:03 |  3073 |  3437 |
|   7 |      TABLE ACCESS STORAGE FULL| ORDERS_BASE |  2579M|    48G|   106K (43)| 00:00:03 |  3073 |  3437 |
-------------------------------------------------------------------------------------------------------------


Statistics
----------------------------------------------------------
       1068  recursive calls
       3206  db block gets
   17684816  consistent gets
   17666603  physical reads
        240  redo size
        555  bytes sent via SQL*Net to client
        552  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed


Yes! After we forced the TE the fast query run the very long time !



1 comment:

  1. Interesting CBO bug - using TE for NOT index-based plan by itself!

    More interesting, Plan Cost for TE-plan is cheaper than for fast one - at least in first examples

    This would be usefull to look TE-plan CBO trace - what used as TE index path - TABLE ACCESS STORAGE FULL?, and how Cost was calculated?)

    ReplyDelete

Could not locate shrept.lst make: *** [client_sharedlib] Error 1

 Installing the quarterly database patch i got unpleasant message : " Patching component oracle.sdo, 12.2.0.1.0... Make failed to ...