Query much slower with a where clause on column which has index-CodePudding

The following query has good performance

    select distinct i.TERMINALNAME, 
           to_char(i.BEGINTIME,'mm/dd/yyyy hh:mi:ss AM') BEGINTIME,
           i.ERRORTEXT, 
           i.RECORDSPROCESSED, 
           i.RECORDTYPE 
      from MYLOGGING i
inner join (select recordtype, 
                   max(BEGINTIME) as lastrundate 
              from MYLOGGING group by recordtype) im on 
      im.recordtype=i.recordtype and im.lastrundate=i.BEGINTIME
     where i.ERRORTEXT in ('Success', 'Failure') 
       and i.TERMINALNAME Not In ('REE300', 'XEE300', 'YT', 'QX', 'VC', 'DF') 
    ORDER BY i.TERMINALNAME ASC;

QUERY PLAN

Plan hash value: 3900617130
 
------------------------------------------------------------------------------------------
| Id  | Operation             | Name             | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |                  |     2 |   132 |  1257   (2)| 00:00:01 |
|   1 |  SORT UNIQUE          |                  |     2 |   132 |  1256   (2)| 00:00:01 |
|*  2 |   HASH JOIN RIGHT SEMI|                  |     2 |   132 |  1255   (2)| 00:00:01 |
|   3 |    VIEW               |                  |   772 | 16984 |   630   (2)| 00:00:01 |
|   4 |     HASH GROUP BY     |                  |   772 | 16212 |   630   (2)| 00:00:01 |
|   5 |      TABLE ACCESS FULL| MYLOGGING |   281K|  5765K|   623   (1)| 00:00:01 |
|*  6 |    TABLE ACCESS FULL  | MYLOGGING |   191K|  8222K|   625   (1)| 00:00:01 |
------------------------------------------------------------------------------------------

However with the new where clause added at the end of the query and i.BEGINTIME>= trunc(sysdate) - 60, it results the query to run much slower if running for the first time, after running it the second time it will be fast.

     select distinct i.TERMINALNAME, 
               to_char(i.BEGINTIME,'mm/dd/yyyy hh:mi:ss AM') BEGINTIME, 
               i.ERRORTEXT, 
               i.RECORDSPROCESSED, 
               i.RECORDTYPE 
          from MYLOGGING i
    inner join (select recordtype, 
                       max(BEGINTIME) as lastrundate 
                  from MYLOGGING group by recordtype) im on im.recordtype=i.recordtype 
           and im.lastrundate=i.BEGINTIME
         where i.ERRORTEXT in ('Success', 'Failure') 
           and i.TERMINALNAME Not In ('REE300', 'XEE300', 'YT', 'QX', 'VC', 'DF') 
           and i.BEGINTIME>= trunc(sysdate) - 60 ORDER BY i.TERMINALNAME ASC;

Query Plan

Plan hash value: 2346866897
 
----------------------------------------------------------------------------------------------------------------
| Id  | Operation                               | Name                 | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                        |                      |     1 |    86 |   809   (1)| 00:00:01 |
|   1 |  SORT UNIQUE                            |                      |     1 |    86 |   809   (1)| 00:00:01 |
|*  2 |   FILTER                                |                      |       |       |            |          |
|   3 |    SORT GROUP BY                        |                      |     1 |    86 |   809   (1)| 00:00:01 |
|*  4 |     HASH JOIN                           |                      | 32572 |  2735K|   807   (1)| 00:00:01 |
|*  5 |      TABLE ACCESS BY INDEX ROWID BATCHED| MYLOGGING     |     1 |    64 |     4   (0)| 00:00:01 |
|*  6 |       INDEX RANGE SCAN                  | IX2_MYLOGGING |     1 |       |     3   (0)| 00:00:01 |
|   7 |      TABLE ACCESS FULL                  | MYLOGGING     |   283K|  6081K|   802   (1)| 00:00:01 |
----------------------------------------------------------------------------------------------------------------

The query plan shows that the query runs fast since it was not the first time I ran it and I assume the data is cached. I don't privilege to flush the cache.

Any idea what could be causing the query to run very slow the first time it's ran? More than 2-3 minutes. Currently the index on the BEGINTIME column has "join_index" to no. Could that have anything to do with it?

CodePudding user response：

I'd narrow down the MYLOGGING table first so it has less to search from and put it into another subquery. Narrowing it down by date. Since FROM takes place before WHERE.

select distinct i.TERMINALNAME
, to_char(i.BEGINTIME,'mm/dd/yyyy hh:mi:ss AM') BEGINTIME
, i.ERRORTEXT
, i.RECORDSPROCESSED
, i.RECORDTYPE 
from 
(select i2.*
 from MYLOGGING i2
 where i2.BEGINTIME >= trunc(sysdate) - 60
) i
inner join (select recordtype
            , max(BEGINTIME) as lastrundate 
            from MYLOGGING 
            group by recordtype
           ) im on im.recordtype=i.recordtype 
            and im.lastrundate=i.BEGINTIME
     where i.ERRORTEXT in ('Success', 'Failure') and i.TERMINALNAME Not In ('REE300', 'XEE300', 'YT', 'QX', 'VC', 'DF')  ORDER BY i.TERMINALNAME ASC;

CodePudding user response：

You can probably avoid the performance problem by converting the self-join into an analytic function. Without the join, there's less work to do and fewer ways for the optimizer to choose a bad plan.

select distinct
    TERMINALNAME, 
    to_char(BEGINTIME,'mm/dd/yyyy hh:mi:ss AM') BEGINTIME, 
    ERRORTEXT, 
    RECORDSPROCESSED, 
    RECORDTYPE
from
(
    select MYLOGGING.*, max(BEGINTIME) over (partition by recordtype) MAX_BEGINTIME_PER_RECORDTYPE
    from MYLOGGING
)
where BEGINTIME = MAX_BEGINTIME_PER_RECORDTYPE
  and ERRORTEXT in ('Success', 'Failure') 
  and TERMINALNAME Not In ('REE300', 'XEE300', 'YT', 'QX', 'VC', 'DF') 
  and BEGINTIME>= trunc(sysdate) - 60
ORDER BY TERMINALNAME ASC;

Finding out why the original query ran slowly can be more difficult. You'll want to find the actual execution plan with actual numbers, instead of using only the explain plan guesses. See this question for information on how to use /* GATHER_PLAN_STATISTICS */ and DBMS_XPLAN to display the execution plan.

The full execution plan, especially the data in the "note" section, may give you a clue as to why the plan was slow and why it got faster. Perhaps there was a dynamic reoptimization, where Oracle recognized the first run was bad, and adjusted the plan. You may also want to try using DBMS_XPLAN.DISPLAY_AWR to see a history of execution plans.

The actual time, and the actual number of rows compared with the estimated number of rows, can often tell you how and why Oracle made a bad decision. For example, the extra WHERE clause may have caused Oracle to significantly under-estimate the number of rows returned, which made an index access and nested loops operation look faster. But for several reasons, nested loops and index scans usually work best for returning a small percentage of rows, whereas hash joins and full table scans usually work best for returning a large percentage of rows.

Gathering and interpreting this data can take hours, especially if you're not familiar with the process. You could take this opportunity to learn more about query tuning, or if you're out of time, just use the above analytic function approach and avoid the problem entirely.