Query executes slower after indexes are created and dbms_stats compute is used

Question

I have a table with 1.5 million rows. I run a query which fetches records having non repeating values in a column. I am observing a behaviour in which after creating indexes the performance of the query degrades. I also used dbms_stats with 100% estimate percentage(compute mode) to gather statistics so that oracle 11g CBO makes a more informed decision for the query plan, but it doesnt improve the query execution time.

 SQL> desc tab3;
 Name                 Null?    Type
 ----------------------------------------------
 COL1                          NUMBER(38)
 COL2                          VARCHAR2(100)
 COL3                          VARCHAR2(36)
 COL4                          VARCHAR2(36)
 COL5                          VARCHAR2(4000)
 COL6                          VARCHAR2(4000)
 MEASURE_0                     VARCHAR2(4000)
 MEASURE_1                     VARCHAR2(4000)
 MEASURE_2                     VARCHAR2(4000)
 MEASURE_3                     VARCHAR2(4000)
 MEASURE_4                     VARCHAR2(4000)
 MEASURE_5                     VARCHAR2(4000)
 MEASURE_6                     VARCHAR2(4000)
 MEASURE_7                     VARCHAR2(4000)
 MEASURE_8                     VARCHAR2(4000)
 MEASURE_9                     VARCHAR2(4000)

The column measure_0 has 0.4 million unique values.

SQL> select count(*) from (select measure_0 from tab3 group by measure_0 having count(*) = 1) abc;

  COUNT(*)
----------
    403664

The following is the query with the execution plan, please note there are no indexes on the table.

SQL> set autotrace traceonly;

SQL> SELECT * FROM (
  2     SELECT
  3             (ROWNUM -1) AS COL1,
  4             ft.COL1         AS OLD_COL1,
  5             ft.COL2,
  6             ft.COL3,
  7             ft.COL4,
  8             ft.COL5,
  9             ft.COL6,
 10             ft.MEASURE_0,
 11             ft.MEASURE_1,
 12             ft.MEASURE_2,
 13             ft.MEASURE_3,
 14             ft.MEASURE_4,
 15             ft.MEASURE_5,
 16             ft.MEASURE_6,
 17             ft.MEASURE_7,
 18             ft.MEASURE_8,
 19             ft.MEASURE_9
 20     FROM tab3 ft
 21     WHERE MEASURE_0 IN
 22      (
 23             SELECT MEASURE_0
 24             FROM tab3
 25             GROUP BY MEASURE_0
 26             HAVING COUNT(*) = 1
 27      )
 28  ) ABC WHERE COL1 >= 0 AND COL1 <=449;

450 rows selected.

Elapsed: 00:00:01.90

Execution Plan
----------------------------------------------------------
Plan hash value: 3115757351

------------------------------------------------------------------------------------
| Id  | Operation               | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT        |          |  1243 |    28M|   717K  (1)| 02:23:29 |
|*  1 |  VIEW                   |          |  1243 |    28M|   717K  (1)| 02:23:29 |
|   2 |   COUNT                 |          |       |       |            |          |
|*  3 |    HASH JOIN            |          |  1243 |    30M|   717K  (1)| 02:23:29 |
|   4 |     VIEW                | VW_NSO_1 |  1686K|  3219M|  6274   (2)| 00:01:16 |
|*  5 |      FILTER             |          |       |       |            |          |
|   6 |       HASH GROUP BY     |          |     1 |  3219M|  6274   (2)| 00:01:16 |
|   7 |        TABLE ACCESS FULL| TAB3     |  1686K|  3219M|  6196   (1)| 00:01:15 |
|   8 |     TABLE ACCESS FULL   | TAB3     |  1686K|    37G|  6211   (1)| 00:01:15 |
------------------------------------------------------------------------------------

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

   1 - filter("COL1">=0 AND "COL1"<=449)
   3 - access("MEASURE_0"="MEASURE_0")
   5 - filter(COUNT(*)=1)

Note
-----
   - dynamic sampling used for this statement (level=2)


Statistics
----------------------------------------------------------
        354  recursive calls
          0  db block gets
      46518  consistent gets
      45122  physical reads
          0  redo size
      43972  bytes sent via SQL*Net to client
        715  bytes received via SQL*Net from client
         31  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
        450  rows processed

The query takes up 1.90 seconds. If I run the query again it takes 1.66 seconds. Why does it take more time in the first run?

In order to speed it up I created indexes on the two columns used in the query.

SQL> create index ind_tab3_orgid on tab3(COL1);

Index created.

Elapsed: 00:00:01.68
SQL> create index ind_tab3_msr_0 on tab3(measure_0);

Index created.

Elapsed: 00:00:01.83

When I fired the query after this for the first time it took a whooping 21 seconds to come back. Whereas subsequent runs bought it to 2.9 seconds. Why does oracle take so much time in the first run, is it warming up or something.. baffles me!

This is the plan when it takes 2.9 seconds-

450 rows selected.

Elapsed: 00:00:02.92

Execution Plan
----------------------------------------------------------
Plan hash value: 240271480

-------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name           | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                |  1243 |    28M|   711K  (1)| 02:22:15 |
|*  1 |  VIEW                          |                |  1243 |    28M|   711K  (1)| 02:22:15 |
|   2 |   COUNT                        |                |       |       |            |          |
|   3 |    NESTED LOOPS                |                |       |       |            |          |
|   4 |     NESTED LOOPS               |                |  1243 |    30M|   711K  (1)| 02:22:15 |
|   5 |      VIEW                      | VW_NSO_1       |  1686K|  3219M|  6274   (2)| 00:01:16 |
|*  6 |       FILTER                   |                |       |       |            |          |
|   7 |        HASH GROUP BY           |                |     1 |  3219M|  6274   (2)| 00:01:16 |
|   8 |         TABLE ACCESS FULL      | TAB3           |  1686K|  3219M|  6196   (1)| 00:01:15 |
|*  9 |      INDEX RANGE SCAN          | IND_TAB3_MSR_0 |  1243 |       |     2   (0)| 00:00:01 |
|  10 |     TABLE ACCESS BY INDEX ROWID| TAB3           |  1243 |    28M|    44   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------

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

   1 - filter("COL1">=0 AND "COL1"<=449)
   6 - filter(COUNT(*)=1)
   9 - access("MEASURE_0"="MEASURE_0")

Note
-----
   - dynamic sampling used for this statement (level=2)


Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
     660054  consistent gets
      22561  physical reads
          0  redo size
      44358  bytes sent via SQL*Net to client
        715  bytes received via SQL*Net from client
         31  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
        450  rows processed

I was expecting the time to be lower than when the table was non indexed. Why does the indexed version of the table takes more time to fetch the results than the non indexed version? If I am not wrong it is the TABLE ACCESS BY INDEX ROWID that is taking up time. Can I enforce oracle to use TABLE ACCESS FULL?

I then gathered statistics on the table so that CBO improves the plan with compute option. So now the statistics would be accurate.

SQL> EXECUTE dbms_stats.gather_table_stats (ownname=>'EQUBE67DP', tabname=>'TAB3',estimate_percent=>null,cascade=>true);

PL/SQL procedure successfully completed.

Elapsed: 00:01:02.47
SQL> set autotrace off;
SQL> select COLUMN_NAME,NUM_DISTINCT,SAMPLE_SIZE,HISTOGRAM,LAST_ANALYZED from dba_tab_cols where table_name = 'TAB3' ;

COLUMN_NAME                    NUM_DISTINCT SAMPLE_SIZE HISTOGRAM       LAST_ANALYZED
------------------------------ ------------ ----------- --------------- ---------
COL1                                1502257     1502257 NONE            27-JUN-12
COL2                                      0             NONE            27-JUN-12
COL3                                      1     1502257 NONE            27-JUN-12
COL4                                      0             NONE            27-JUN-12
COL5                                1502257     1502257 NONE            27-JUN-12
COL6                                1502257     1502257 NONE            27-JUN-12
MEASURE_0                            405609     1502257 HEIGHT BALANCED 27-JUN-12
MEASURE_1                            128570     1502257 NONE            27-JUN-12
MEASURE_2                           1502257     1502257 NONE            27-JUN-12
MEASURE_3                            185657     1502257 NONE            27-JUN-12
MEASURE_4                               901     1502257 NONE            27-JUN-12
MEASURE_5                                17     1502257 NONE            27-JUN-12
MEASURE_6                              2202     1502257 NONE            27-JUN-12
MEASURE_7                              2193     1502257 NONE            27-JUN-12
MEASURE_8                                21     1502257 NONE            27-JUN-12
MEASURE_9                             27263     1502257 NONE            27-JUN-12

I again ran the query

450 rows selected.

Elapsed: 00:00:02.95

Execution Plan
----------------------------------------------------------
Plan hash value: 240271480

-------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name           | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                |    31M|   718G|  8046   (2)| 00:01:37 |
|*  1 |  VIEW                          |                |    31M|   718G|  8046   (2)| 00:01:37 |
|   2 |   COUNT                        |                |       |       |            |          |
|   3 |    NESTED LOOPS                |                |       |       |            |          |
|   4 |     NESTED LOOPS               |                |    31M|    62G|  8046   (2)| 00:01:37 |
|   5 |      VIEW                      | VW_NSO_1       |  4057 |  7931K|  6263   (2)| 00:01:16 |
|*  6 |       FILTER                   |                |       |       |            |          |
|   7 |        HASH GROUP BY           |                |     1 | 20285 |  6263   (2)| 00:01:16 |
|   8 |         TABLE ACCESS FULL      | TAB3           |  1502K|  7335K|  6193   (1)| 00:01:15 |
|*  9 |      INDEX RANGE SCAN          | IND_TAB3_MSR_0 |     4 |       |     2   (0)| 00:00:01 |
|  10 |     TABLE ACCESS BY INDEX ROWID| TAB3           |   779K|    75M|     3   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------

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

   1 - filter("COL1">=0 AND "COL1"<=449)
   6 - filter(COUNT(*)=1)
   9 - access("MEASURE_0"="MEASURE_0")


Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
     660054  consistent gets
      22561  physical reads
          0  redo size
      44358  bytes sent via SQL*Net to client
        715  bytes received via SQL*Net from client
         31  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
        450  rows processed

This time the query came back in 2.9 seconds (sometimes it took 3.9 seconds too).

My goal is to minimize the query execution time as much as possible. But after adding indexes or after computing statistics the query time just kept increasing. Why is this happening and how can I improve even by keeping the indexes?

Why does it take longer for the query the first run? For one thing, it's those 254 recursive SQL calls reported by autotrace. All the work that needs to be done to parse the query for syntax, for semantics (do referenced objects and names exist and do you have privileges on them), and then the work to prepare the execution plan (what indexes are available, estimate costs of various possible plans). There's a lot of heavy lifting being done there on that first execution. — spencer7593, Jun 27 '12 at 19:12
On your second query, which takes the 29 seconds the first run, that's likely physical reads... Oracle is getting blocks from disk and filling the buffer cache. (autotrace would show a summary of this, an event 10046 trace would have details for all of the waits.) — spencer7593, Jun 27 '12 at 19:23
On that second query that took 21 seconds (not 29) on the first run, according to what you have shown, Oracle did not have statistics on the indexes, so Oracle spent time estimating statistics on the indexes, before it selected an execution plan. — spencer7593, Jun 27 '12 at 19:36
It doesn't matter for this specific query, but the `ROWNUM` in the inner query seems like a bug waiting to happen. If you add an `ORDER BY`, it will not happen before the `ROWNUM`. Better to always filter by `ROWNUM` in the outer-most query, instead of aliasing it and filtering on that alias. — Jon Heller, Jun 28 '12 at 06:17
@spencer7593 Thanks, so during the first time hard parses are happening, I read up on it now. How do applications tackle this problem of time taken by queries the first time, do they fire queries just like that which might be used in the future so that next invocations of the query would be soft parse? — rirhs, Jun 28 '12 at 08:33

Vincent Malgrat · Accepted Answer · 2012-06-28T09:17:39.787

First of all, let me quote Tom Kyte:

just keep saying to yourself over and over

"full scans are not evil, indexes are not good"
"full scans are not evil, indexes are not good"
"full scans are not evil, indexes are not good"
"full scans are not evil, indexes are not good"
"full scans are not evil, indexes are not good"
"full scans are not evil, indexes are not good"

Indexes will not always improve performance, they are not the magical silver bullet (as if such a thing ever existed :)

Now you're asking why it takes longer with your index. The answer is pretty simple:

with the full table scan: 46518 consistent gets
with your index: 660054 consistent gets

In other words: Oracle perform more read operations with your index than with the full table scan. This happens because:

FULL TABLE SCAN reads are bulk operations (many blocks at a time) and are therefore an efficient way to read lots of data
sometimes when you read from an index you end up reading the exact same data block more than once.

As to why the optimizer chose to use this obviously non-efficient index, this is because even with esimate_percent=100 and full histograms (which you have collected on the MEASURE_0 column), some data distribution still can not be reliably expressed by the simple analysis of the optimizer. In particular, cross-column and cross-table dependency is not well-understood by the analyzer. This leads to wrong estimates, which lead to poor plan choice.

Edit: it seems the working hypothesis of the CBO are not working at all for this self-join (your last query expects 31 million rows whereas only 450 are selected !). This is quite puzzling since the table has only 1.5 M rows. What version of Oracle are you using?

I think you will find that you can remove the self-join and therefore improve query performance with analytics:

SELECT * FROM (
   SELECT (ROWNUM -1) AS COL1, ABC.*
     FROM (
      SELECT
              ft.COL1 AS OLD_COL1,
              [...],
              COUNT(*) OVER (PARTITION BY MEASURE_O) nb_0
      FROM tab3 ft
      ) ABC 
    WHERE nb_0 = 1
      AND ROWNUM - 1 <= 449
   ) v
 WHERE COL1 >= 0;

You were also asking why the first time a query is run takes more time in general. This is because there are caches at work. On the database level there is the SGA where all blocks are first copied from disk and then can be read multiple times (the first time a block is queried is always a physical read). Then some systems also have an independent system cache that will return data faster if it has been read recently.

For further reading:

an explication of a data discrepancy that can lead to wrong estimates and a solution involving SQL profiles.

Thanks, I would certainly keep Tom Kyte's qoute in mind :). I am using Oracle 11g. I read up on SQL profiles, unfortunately I don't think SQL profiles can solve my problem. SQL profiles apply to queries whose predicate doesn't change, the query that I mentioned here would change(the last filter `COL1 >= 0 AND COL1 <=449` can be anything like `COL1 >= 400000 AND COL1 <=400449`). I tried to use dynamic sampling hint but I am not sure I am doing it right. I put a Dynamic sampling level 3 hint in the second select on `tab3`, but to no effect. — rirhs, Jun 28 '12 at 09:01
I tried to run the query you have written, it takes around 14 seconds to get back. — rirhs, Jun 28 '12 at 09:06
(1) You could use bind variables :) and (2) have you tried the query with analytics? Anyway I don't think the use of index would be helpful in this case: you're basically paginating through the whole table with a filter on `MEASURE_0` that will select nearly half of the rows. Index are very good when there is a strong selectivity, not so much when the filter is weak. — Vincent Malgrat, Jun 28 '12 at 09:09
I've modified the query so that it is the equivalent of your original query. It may still be inferior to your original query: not even analytics are a silver bullet :) — Vincent Malgrat, Jun 28 '12 at 09:23

score 3 · Answer 2 · answered Jun 27 '12 at 19:46

3

How does this code perform?

SELECT ROWNUM - 1      AS col1
,      ft.col1         AS old_col1
,      ft.col2
,      ft.col3
,      ft.col4
,      ft.col5
,      ft.col6
,      ft.measure_0
,      ft.measure_1
,      ft.measure_2
,      ft.measure_3
,      ft.measure_4
,      ft.measure_5
,      ft.measure_6
,      ft.measure_7
,      ft.measure_8
,      ft.measure_9
FROM   tab3 ft
WHERE  NOT EXISTS (SELECT NULL
                   FROM   tab3   ft_prime
                   WHERE  ft_prime.measure_0 = ft.measure_0
                   AND    ft_prime.ROWID <> ft.ROWID)
AND    ROWNUM <= 450;

answered Jun 27 '12 at 19:46

Tebbe

1,372
9
12

This query performs really well, it came back in 0.04 seconds, but the query that I mentioned here would change(the last filter `COL1 >= 0 AND COL1 <=449` can be anything like `COL1 >= 400000 AND COL1 <=400449`). So I surrounded your query with a select specifying this predicate, and got results in 1.6 seconds, which is anytime better than what is happening with the previous query. Thanks! – rirhs Jun 28 '12 at 09:25
@shri: You could let the upper range filter `ROWNUM <= 450` in the inner query, this will let Oracle know that at most 450 rows are needed. The additional filter `COL1 >= 0` needs to be in the outer query of course. See this [discussion on the pagination optimization](http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:127412348064). – Vincent Malgrat Jun 28 '12 at 09:43

Query executes slower after indexes are created and dbms_stats compute is used

2 Answers2