Skip to Main Content

Breadcrumb

Question and Answer

Chris Saxon

Thanks for the question.

Asked: December 15, 2020 - 6:05 pm UTC

Last updated: December 22, 2020 - 7:29 am UTC

Version: 12.1.0.2

Viewed 100+ times

You Asked

I have a query that used to run under 2 seconds but it is now running over 2 minutes.

In other environments, it is still running in 2 seconds. In the execution plan, I only see a difference in the order of filter and E-Rows/byte.

Could you please suggest what might be the issue and if there are any hints I could try to optimize.

execution plan that is taking less than 2 seconds
******************************************************
SQL_ID  1jz584jsu4y4v, child number 0
-------------------------------------
select   /*+       BEGIN_OUTLINE_DATA       IGNORE_OPTIM_EMBEDDED_HINTS 
      OPTIMIZER_FEATURES_ENABLE('12.1.0.2')       
DB_VERSION('12.1.0.2')       OPT_PARAM('_optimizer_use_feedback' 
'false')       OPT_PARAM('_px_adaptive_dist_method' 'off')       
OPT_PARAM('_optimizer_dsdir_usage_control' 0)       
OPT_PARAM('_optimizer_adaptive_plans' 'false')       
OPT_PARAM('_optimizer_strans_adaptive_pruning' 'false')       
OPT_PARAM('_optimizer_gather_feedback' 'false')       
OPT_PARAM('_optimizer_nlj_hj_adaptive_join' 'false')       
OPT_PARAM('optimizer_index_cost_adj' 20)       ALL_ROWS       
OUTLINE_LEAF(@"SEL$1")       FULL(@"SEL$1" "CRTCL"@"SEL$1")      
 END_OUTLINE_DATA   */ count(case when ts <  trunc(sysdate) then 
1 end) weekly_error_ct             from log.CRTCL          
   where event_cntxt = 'PROCTOR' and             MSG like 
'%ResultId%' and             MSG not like '%ORA-20200%' and    
         MSG not like '%sp_ValidateRecord%' an
 

 
Plan hash value: 1601281016
 
--------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation          | Name         | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers | Reads  |
--------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |              |      1 |        |       |   446 (100)|          |      1 |00:00:00.04 |    1890 |     65 |
|   1 |  SORT AGGREGATE    |              |      1 |      1 |   137 |            |          |      1 |00:00:00.04 |    1890 |     65 |
|*  2 |   TABLE ACCESS FULL|        CRTCL |      1 |      1 |   137 |   446   (1)| 00:00:01 |      0 |00:00:00.04 |    1890 |     65 |
--------------------------------------------------------------------------------------------------------------------------------------
 

 
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
 
   1 - SEL$1
   2 - SEL$1 / CRTCL@SEL$1
 
Outline Data
-------------
 
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('12.1.0.2')
      DB_VERSION('12.1.0.2')
      OPT_PARAM('_optimizer_use_feedback' 'false')
      OPT_PARAM('_px_adaptive_dist_method' 'off')
      OPT_PARAM('_optimizer_dsdir_usage_control' 0)
      OPT_PARAM('_optimizer_adaptive_plans' 'false')
      OPT_PARAM('_optimizer_strans_adaptive_pruning' 'false')
      OPT_PARAM('_optimizer_gather_feedback' 'false')
      OPT_PARAM('_optimizer_nlj_hj_adaptive_join' 'false')
      OPT_PARAM('optimizer_index_cost_adj' 20)
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "CRTCL"@"SEL$1")
      END_OUTLINE_DATA
  */
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   2 - filter(("ts">=TRUNC(SYSDATE@!-7) AND "EVENT_CNTXT"='PROC' 
              AND "MSG" LIKE '%ResultId%' AND "MSG" NOT LIKE '%ORA-20200%' 
              AND "MSG" NOT LIKE '%sp_ValidateRecord%'))
 
Column Projection Information (identified by operation id):
-----------------------------------------------------------
 
   1 - (#keys=0) COUNT(CASE  WHEN "TS"<TRUNC(SYSDATE@!) THEN 1 END 
       )[22]
   2 - "TS"[DATE,7]
 
 -------------------------------------------------------


execution plan that is taking over 2 minutes
******************************************************
SQL_ID  1jz584jsu4y4v, child number 0
-------------------------------------
select   /*+       BEGIN_OUTLINE_DATA       IGNORE_OPTIM_EMBEDDED_HINTS 
      OPTIMIZER_FEATURES_ENABLE('12.1.0.2')       
DB_VERSION('12.1.0.2')       OPT_PARAM('_optimizer_use_feedback' 
'false')       OPT_PARAM('_px_adaptive_dist_method' 'off')       
OPT_PARAM('_optimizer_dsdir_usage_control' 0)       
OPT_PARAM('_optimizer_adaptive_plans' 'false')       
OPT_PARAM('_optimizer_strans_adaptive_pruning' 'false')       
OPT_PARAM('_optimizer_gather_feedback' 'false')       
OPT_PARAM('_optimizer_nlj_hj_adaptive_join' 'false')       
OPT_PARAM('optimizer_index_cost_adj' 20)       ALL_ROWS       
OUTLINE_LEAF(@"SEL$1")       FULL(@"SEL$1" "CRTCL"@"SEL$1")      
 END_OUTLINE_DATA   */ count(case when ts <  trunc(sysdate) then 
1 end) weekly_error_ct             from log.CRTCL          
   where event_cntxt = 'PROCTOR' and             MSG like 
'%ResultId%' and             MSG not like '%ORA-20200%' and    
         MSG not like '%sp_ValidateRecord%' an
 
 
Plan hash value: 1601281016
 
--------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation          | Name         | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers | Reads  |
--------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |              |      1 |        |       |  1341 (100)|          |      1 |00:02:14.40 |     448K|    443K|
|   1 |  SORT AGGREGATE    |              |      1 |      1 |   160 |            |          |      1 |00:02:14.40 |     448K|    443K|
|*  2 |   TABLE ACCESS FULL|        CRTCL |      1 |   4692 |   733K|  1341   (1)| 00:00:01 |      0 |00:02:14.40 |     448K|    443K|

 
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
 
   1 - SEL$1
   2 - SEL$1 / CRTCL@SEL$1
 
Outline Data
-------------
 
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('12.1.0.2')
      DB_VERSION('12.1.0.2')
      OPT_PARAM('_optimizer_use_feedback' 'false')
      OPT_PARAM('_px_adaptive_dist_method' 'off')
      OPT_PARAM('_optimizer_dsdir_usage_control' 0)
      OPT_PARAM('_optimizer_adaptive_plans' 'false')
      OPT_PARAM('_optimizer_strans_adaptive_pruning' 'false')
      OPT_PARAM('_optimizer_gather_feedback' 'false')
      OPT_PARAM('_optimizer_nlj_hj_adaptive_join' 'false')
      OPT_PARAM('optimizer_index_cost_adj' 20)
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "CRTCL"@"SEL$1")
      END_OUTLINE_DATA
  */
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   2 - filter(("MSG" LIKE '%ResultId%' AND "MSG" NOT LIKE 
              '%ORA-20200%' AND "MSG" NOT LIKE '%sp_ValidateRecord%' AND 
              "TS">=TRUNC(SYSDATE@!-7) AND "CNTXT"='PROC'))
 
Column Projection Information (identified by operation id):
-----------------------------------------------------------
 
   1 - (#keys=0) COUNT(CASE  WHEN "TS"<TRUNC(SYSDATE@!) THEN 1 END 
       )[22]
   2 - "TS"[DATE,7]
 

 

and we said...

It's really the same plan, it's just doing a lot more work in the slower query.

In both cases the query fetches zero rows from the table. But in the slower plan it does significantly more work (nearly half a million buffer gets as opposed to a couple of thousand; see the Buffers column).

Are there (lots) more data in the table in the slower database?

I see there's a full scan hint in the query:

FULL(@"SEL$1" "CRTCL"@"SEL$1")      


This will stop the optimizer using any candidate indexes. Try removing this and consider making an index on

( event_cntxt, msg, ts )


if it doesn't already exist.

Best case the database will be able to range scan this index to quickly spot the query returns no rows.

Or you could fall back to a full index scan, which is usually faster than a full table scan (due to the index being a smaller data structure).

Rating

  (1 rating)

Comments

spur230, December 21, 2020 - 4:55 pm UTC

Thanks Chris for looks into it.

Yes, the slower query had a lot more records. (94K more records)

I do not have index on ( event_cntxt, msg, ts ) currently.

msg is a clob column so probably I need a text index for it.

This is the simplified version of the query

select  count(*) from CRTCL          
               where ts > trunc(sysdate -7)   
               and msg like '%ResultId%'


If I remove the LIKE filter r on clob colum (msg), the query returns 1K records and comes within a second.

As soon as I add a filter on msg it takes over 2 minutes.

it is possible to add some hint so that clob filter is only done for the return 1k rows from " ts > trunc(sysdate -7) " instead of entire table.

I tried this but it seem it is sill filtering clob from the entire table.
SELECT /*+ no_merge no_push_pred */
      COUNT (*)
  FROM (SELECT msg
          FROM  crtcl WHERE ts > TRUNC (SYSDATE - 7)) v1
 WHERE msg LIKE '%ResultId%'




Connor McDonald
December 22, 2020 - 7:29 am UTC

I couldn't replicate your findings, eg

SQL> create table t ( pk int, ts date, m clob );

Table created.

SQL> set serverout on
SQL> declare
  2    c clob;
  3  begin
  4    c := 'asd qwe qwe qwe qw eas das dasd qwe qwe q we';
  5    for i in 1 .. 10 loop
  6       c := c || c;
  7    end loop;
  8    c := c || 'Hello';
  9    dbms_output.put_line('len='||length(c));
 10
 11    insert /*+ APPEND */ into t
 12    select rownum, date '2020-01-01'+trunc(rownum/40000), c
 13    from dual
 14    connect by level <= 40100;
 15    commit;
 16  end;
 17  /
len=45061

PL/SQL procedure successfully completed.

SQL> set timing on
SQL> select count(*)
  2  from   t
  3  where  ts > date '2020-01-01';

  COUNT(*)
----------
       101

Elapsed: 00:00:00.00

SQL> select count(*)
  2  from   t
  3  where  ts > date '2020-01-01'
  4  and m like '%Hello%';

  COUNT(*)
----------
       101

Elapsed: 00:00:00.26

SQL> select count(*)
  2  from   t
  3  where  m like '%Hello%';

  COUNT(*)
----------
     40100

Elapsed: 00:01:34.07


So you can see that we must have evaluated the date first. But let's assume that this *is* the case, and the clob is being checked. You could subvert that by just getting the rows that match the date, and then joining back to the table, eg

SQL> with rids as
  2   ( select /*+ materialize */ rowid r
  3     from t
  4     where ts > date '2020-01-01'
  5   )
  6  select /*+ leading(rids t) use_nl(t) */ count(*)
  7  from   t, rids
  8  where  t.rowid = rids.r
  9  and    t.m like '%Hello%';

  COUNT(*)
----------
       101

Elapsed: 00:00:00.28

------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                | Name                        | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                         |                             |     1 |    65 | 20172   (1)| 00:00:01 |
|   1 |  TEMP TABLE TRANSFORMATION               |                             |       |       |            |          |
|   2 |   LOAD AS SELECT (CURSOR DURATION MEMORY)| SYS_TEMP_0FD9D676F_D1488ECE |       |       |            |          |
|*  3 |    TABLE ACCESS FULL                     | T                           | 20050 |   391K|    94   (2)| 00:00:01 |
|   4 |   SORT AGGREGATE                         |                             |     1 |    65 |            |          |
|   5 |    NESTED LOOPS                          |                             |  1003 | 65195 | 20078   (1)| 00:00:01 |
|   6 |     VIEW                                 |                             | 20050 |   234K|    17   (0)| 00:00:01 |
|   7 |      TABLE ACCESS FULL                   | SYS_TEMP_0FD9D676F_D1488ECE | 20050 |   234K|    17   (0)| 00:00:01 |
|*  8 |     TABLE ACCESS BY USER ROWID           | T                           |     1 |    53 |     1   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------------------------

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

   3 - filter("TS">TO_DATE(' 2020-01-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))
   8 - filter("T"."M" /*+ LOB_BY_VALUE */  LIKE '%Hello%')




but before you head down that route, I'd recommend digging into some explain plans and perhaps 10053 to see why the normal SQL is not working as you expect.

More to Explore

SQL

The Oracle documentation contains a complete SQL reference.