RE: Variable execution time of sql with same plan

  • From: "Mark W. Farnham" <mwf@xxxxxxxx>
  • To: <andysayer@xxxxxxxxx>, "'Pap'" <oracle.developer35@xxxxxxxxx>
  • Date: Fri, 26 Nov 2021 13:14:03 -0500

What Andy said, and:

 

1)    You haven’t told use what the partitioning strategy is, and it could be 
relevant depending on unstated correlations on the filter predicates

2)    AND SFE.eid = STD.did   AND SFE.eid = SBD.did implies that STD.did must 
equal SBD.did. Now the CBO can detect if that is useful under some 
circumstances, but IF you know there is a strong reduction in candidate rows 
from doing that first, you could produce a materialized inline view of the join 
of STD and SBD filtered by SBD.HD_ID = :b1  AND SBD.STAT = :b2 with only the 
relevant columns being returned and then join that inline view with SFE. 

3)    A count(*), pt_code grouping by pt_code on SFE where ptcode in XX, YY, ZZ 
would be useful. IF XX, YY, and ZZ are a tiny fraction of SFE, you might want 
to prune SFE on that hardcoded set of ptcodes preemptively. IF ptcode is the 
partition, then that inline view could be the preemptive individual partitions 
union-all’ed with just the relevant columns returned.

 

Often the Oracle CBO can sort all that out for you under the covers, but if you 
know something about the texture of your data that will be constant you can 
spoon feed an easier to optimize puzzle to the CBO. 

 

Good luck. That count grouping by ptcode and information about your 
partitioning could also tell us that my notion is absurd compared to the actual 
data. But it is worth checking. Hard coded constants in queries are a flashing 
neon sign to ask “what is special about these values, and can it help me write 
the code to get good answers faster.”

 

Likewise if the join of STD and SBD on did returns a large fraction of the rows 
with SBD filtered on its non-join predicates.

 

mwf

 

From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx] On ;
Behalf Of Andy Sayer
Sent: Friday, November 26, 2021 9:03 AM
To: Pap
Cc: Oracle L
Subject: Re: Variable execution time of sql with same plan

 

Hi Pap,

 

You didn't include the captured bind variables (these can be trusted in live 
report monitors) but there's enough to go off with what you included.

 

To start, your faster execution is still 3 minutes and is doing 11M buffer gets 
- mostly reading 108M rows from SFE from your SFE_IX1 index to end up with 
15000 rows. Keep that in mind.

 

Your second execution, the additional time is mostly IO and we can see that 
this IO is mostly on the SFE & SFE_IX1 lines (going from 170K physical IOs to 
864K IOs. Judging by the buffer gets, my first guess would be that of all the 
buffers that needed reading (we already know there's millions) a lot more were 
not found in cache in this execution.

 

The third execution is a bit more obvious, the index range scan of SFE_IX1 
identifies 4G rows which all need looking up in SFE (to end up with 14998).

 

Based on this, the starting suggestion would be to improve how you are 
accessing SFE. We can see the additional predicates that get applied on line 8 
that aren't solved by your index. It looks like "sfhid" and "oid" could be good 
candidates for adding to the index. If that's not enough then the ptcode column 
could be added.

 

 

Thanks,
Andrew 

 

 

On Fri, 26 Nov 2021 at 12:36, Pap <oracle.developer35@xxxxxxxxx> wrote:

Hello All, It's version 12.1.0.2.0 of oracle database with 
optimizer_feature_enable set as 11.2.0.4. We have the below query which 
sometimes runs in ~3-4minutes and sometimes goes for ~10minutes or even ~1hrs 
also. As its version 12.1 so was able to capture the sql monitor for a few of 
the good and bad runs for comparison. So I wanted to understand what is the 
reason behind the same and if we can make it better?

From the sql monitor it seems , it's the plan_line_id 8 and 9 i.e. fetching 
rows from table SFE using index SFE_IX1 is making the difference. But I want to 
understand , how come the difference is so much with the same plan hash value 
and even the EXECS column in the sql monitor shows the same amount of iteration 
in those index access steps?

SELECT *
  FROM (SELECT /*+ ordered  index(SFE SFE_IX1) index(SBD SBD_IX1) */
              ....,
               ROW_NUMBER ()
               OVER (PARTITION BY SBD.BDID
                     ORDER BY SFE.FID DESC) rn
          FROM SBD , SFE ,STD 
         WHERE     SFE.fhid = SBD.sfhid  AND SFE.eid = STD.did   AND SFE.eid = 
SBD.did    AND SFE.oid = SBD.sid    AND SFE.ptcode IN ('XX', 'YY', 'ZZ')
               AND SFE.ETYP = 'ZZZZ'    AND NVL (SFE.SCID, '0') =    NVL 
(SBD.SCID, 0)  AND SBD.P_DT = SFE.P_DT AND SBD.HD_ID = :b1  AND SBD.STAT = :b2)
 WHERE rn < 2;
 
Table SBD having total ~1.7million rows and table STD having ~4.2million rows. 

 

SFE is the biggest one having ~1.7billion rows and partitioned.  But all the 
indexes are global here. and the partition key is not used in the filter/join 
criteria. We have four indexes on the columns of the table that are used as 
join/filter predicate in this query.
 


 COLUMN_NAME

NUM_DISTINCT

DENSITY

NUM_NULLS

HISTOGRAM


EIS

367397

2.72185E-06

0

NONE


ETYP

2

0.5

0

NONE


OID

219100

4.56413E-06

0

NONE


FHID

558916

1.78918E-06

0

NONE


PTCODE

419

0.002386635

0

NONE


SCID

1742

0.000574053

1693771500

NONE


P_DT

6546

0.0001527

0

NONE

 

Index SFE_IX4 - On column ptcode.
Index SFE_IX2 - On column fhid.
Index SFE_X1 - On column etyp , eid.
Index SFE_TMP - On column p_dt.  

 


INDEX_NAME

BLEVEL

LEAF_BLOCKS

CLUSTERING_FACTOR

NUM_ROWS

distinct_keys


SFE_IX4

4

12553800

456127300

1670902700

419


SFE_IX2

4

13526400

79324200

1771657400

558916


SFE_X1

4

9883200

168223500

1730409900

367397


SFE_TMP

4

15856000

74249900

1737505200

6546

 

Below are the three different sql monitors captured with a big difference in 
run time.


Global Information
------------------------------
 Status              :  DONE (ALL ROWS)          
 Instance ID         :  1                        
 SQL Execution ID    :  16777286                 
 Execution Started   :  11/10/2021 01:30:27      
 First Refresh Time  :  11/10/2021 01:30:31      
 Last Refresh Time   :  11/10/2021 01:33:11      
 Duration            :  164s                     
 Program             :  JDBC Thin Client         
 Fetch Calls         :  1001                     

Global Stats
=========================================================================================
| Elapsed |   Cpu   |    IO    | Concurrency | Cluster  | Fetch | Buffer | Read 
| Read  |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   | Waits(s) | Calls |  Gets  | Reqs 
| Bytes |
=========================================================================================
|     175 |      94 |       81 |        0.00 |     0.73 |  1001 |    11M | 170K 
|   1GB |
=========================================================================================

=============================================================================================================================================================================================
| Id |                 Operation                 |            Name            | 
 Rows   | Cost |   Time    | Start  | Execs |   Rows   | Read  | Read  |  Mem  
| Activity | Activity Detail |
|    |                                           |                            | 
(Estim) |      | Active(s) | Active |       | (Actual) | Reqs  | Bytes | (Max) 
|   (%)    |   (# samples)   |
=============================================================================================================================================================================================
|  0 | SELECT STATEMENT                          |                            | 
        |      |         2 |   +163 |     1 |    10000 |       |       |       
|          |                 |
|  1 |   VIEW                                    |                            | 
      1 | 1385 |         2 |   +163 |     1 |    10000 |       |       |       
|          |                 |
|  2 |    WINDOW SORT PUSHED RANK                |                            | 
      1 | 1385 |       161 |     +4 |     1 |    15000 |       |       |    5M 
|          |                 |
|  3 |     NESTED LOOPS                          |                            | 
        |      |       160 |     +4 |     1 |    15000 |       |       |       
|          |                 |
|  4 |      NESTED LOOPS                         |                            | 
      1 | 1384 |       160 |     +4 |     1 |    15000 |       |       |       
|          |                 |
|  5 |       NESTED LOOPS                        |                            | 
      1 | 1382 |       160 |     +4 |     1 |    15000 |       |       |       
|          |                 |
|  6 |        TABLE ACCESS BY INDEX ROWID        | SBD                        | 
      1 |  699 |       160 |     +4 |     1 |    10000 |       |       |       
|          |                 |
|  7 |         INDEX RANGE SCAN                  | SBD_IX1                    | 
   9476 |   79 |       160 |     +4 |     1 |    10000 |       |       |       
|          |                 |
|  8 |        TABLE ACCESS BY GLOBAL INDEX ROWID | SFE                        | 
      1 |  683 |       163 |     +1 | 10000 |    15000 |  152K |   1GB |       
|          |                 |
|  9 |         INDEX RANGE SCAN                  | SFE_IX1                    | 
   4688 |  220 |       160 |     +4 | 10000 |     108M | 18160 | 142MB |       
|          |                 |
| 10 |       INDEX UNIQUE SCAN                   | STD_PK                     | 
      1 |    1 |       161 |     +4 | 15034 |    15000 |     3 | 24576 |       
|          |                 |
| 11 |      TABLE ACCESS BY INDEX ROWID          | STD                        | 
      1 |    2 |       160 |     +4 | 15160 |    15000 |       |       |       
|          |                 |
=============================================================================================================================================================================================


Global Information
------------------------------
 Status              :  DONE (ALL ROWS)          
 Instance ID         :  1                        
 SQL Execution ID    :  16777285                 
 Execution Started   :  11/10/2021 01:30:27      
 First Refresh Time  :  11/10/2021 01:30:31      
 Last Refresh Time   :  11/10/2021 01:38:48      
 Duration            :  501s                     
 Program             :  JDBC Thin Client         
 Fetch Calls         :  1001                     

Global Stats
===========================================================================
| Elapsed |   Cpu   |    IO    | Cluster  | Fetch | Buffer | Read | Read  |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes |
===========================================================================
|     561 |     156 |      401 |     3.94 |  1001 |     9M | 864K |   7GB |
===========================================================================

============================================================================================================================================================================================
| Id |                 Operation                 |            Name            | 
 Rows   | Cost |   Time    | Start  | Execs |   Rows   | Read | Read  |  Mem  | 
Activity | Activity Detail |
|    |                                           |                            | 
(Estim) |      | Active(s) | Active |       | (Actual) | Reqs | Bytes | (Max) | 
  (%)    |   (# samples)   |
============================================================================================================================================================================================
|  0 | SELECT STATEMENT                          |                            | 
        |      |         1 |   +501 |     1 |    10000 |      |       |       | 
         |                 |
|  1 |   VIEW                                    |                            | 
      1 | 1385 |         1 |   +501 |     1 |    10000 |      |       |       | 
         |                 |
|  2 |    WINDOW SORT PUSHED RANK                |                            | 
      1 | 1385 |       498 |     +4 |     1 |    15000 |      |       |    5M | 
         |                 |
|  3 |     NESTED LOOPS                          |                            | 
        |      |       498 |     +4 |     1 |    15000 |      |       |       | 
         |                 |
|  4 |      NESTED LOOPS                         |                            | 
      1 | 1384 |       498 |     +4 |     1 |    15000 |      |       |       | 
         |                 |
|  5 |       NESTED LOOPS                        |                            | 
      1 | 1382 |       498 |     +4 |     1 |    15000 |      |       |       | 
         |                 |
|  6 |        TABLE ACCESS BY INDEX ROWID        | SBD                        | 
      1 |  699 |       498 |     +4 |     1 |    10000 |    5 | 40960 |       | 
         |                 |
|  7 |         INDEX RANGE SCAN                  | SBD_IX1                    | 
   9476 |   79 |       498 |     +4 |     1 |    10000 |      |       |       | 
         |                 |
|  8 |        TABLE ACCESS BY GLOBAL INDEX ROWID | SFE                        | 
      1 |  683 |       498 |     +4 | 10000 |    15000 | 696K |   5GB |       | 
         |                 |
|  9 |         INDEX RANGE SCAN                  | SFE_IX1                    | 
   4688 |  220 |       501 |     +1 | 10000 |      97M | 168K |   1GB |       | 
         |                 |
| 10 |       INDEX UNIQUE SCAN                   | STD_PK                     | 
      1 |    1 |       498 |     +4 | 15045 |    15000 |    5 | 40960 |       | 
         |                 |
| 11 |      TABLE ACCESS BY INDEX ROWID          | STD                        | 
      1 |    2 |       498 |     +4 | 15994 |    15000 |    2 | 16384 |       | 
         |                 |
============================================================================================================================================================================================
 

Global Information
------------------------------
 Status              :  DONE (ALL ROWS)          
 Instance ID         :  1                        
 SQL Execution ID    :  16780848                 
 Execution Started   :  09/14/2021 12:17:54      
 First Refresh Time  :  09/14/2021 12:17:58      
 Last Refresh Time   :  09/14/2021 13:22:10      
 Duration            :  3856s                    
 Program             :  JDBC Thin Client         
 Fetch Calls         :  1001                     

Global Stats
=====================================================================================================
| Elapsed |   Cpu   |    IO    | Concurrency | Cluster  |  Other   | Fetch | 
Buffer | Read  | Read  |
| Time(s) | Time(s) | Waits(s) |  Waits(s)   | Waits(s) | Waits(s) | Calls |  
Gets  | Reqs  | Bytes |
=====================================================================================================
|    3855 |    3822 |       26 |        0.02 |     2.31 |     5.45 |  1001 |   
609M | 42879 | 335MB |
=====================================================================================================

=============================================================================================================================================================================================
| Id |                 Operation                 |            Name            | 
 Rows   | Cost |   Time    | Start  | Execs |   Rows   | Read  | Read  |  Mem  
| Activity | Activity Detail |
|    |                                           |                            | 
(Estim) |      | Active(s) | Active |       | (Actual) | Reqs  | Bytes | (Max) 
|   (%)    |   (# samples)   |
=============================================================================================================================================================================================
|  0 | SELECT STATEMENT                          |                            | 
        |      |         2 |  +3855 |     1 |    10000 |       |       |       
|          |                 |
|  1 |   VIEW                                    |                            | 
      1 | 1374 |         2 |  +3855 |     1 |    10000 |       |       |       
|          |                 |
|  2 |    WINDOW SORT PUSHED RANK                |                            | 
      1 | 1374 |      3853 |     +4 |     1 |    14998 |       |       |    5M 
|          |                 |
|  3 |     NESTED LOOPS                          |                            | 
        |      |      3852 |     +4 |     1 |    14998 |       |       |       
|          |                 |
|  4 |      NESTED LOOPS                         |                            | 
      1 | 1373 |      3852 |     +4 |     1 |    14998 |       |       |       
|          |                 |
|  5 |       NESTED LOOPS                        |                            | 
      1 | 1371 |      3852 |     +4 |     1 |    14998 |       |       |       
|          |                 |
|  6 |        TABLE ACCESS BY INDEX ROWID        | SBD                        | 
      1 |  677 |      3852 |     +4 |     1 |    10000 |   304 |   2MB |       
|          |                 |
|  7 |         INDEX RANGE SCAN                  | SBD_IX1                    | 
   9362 |   78 |      3852 |     +4 |     1 |    10000 |    57 | 456KB |       
|          |                 |
|  8 |        TABLE ACCESS BY GLOBAL INDEX ROWID | SFE                        | 
      1 |  694 |      3854 |     +2 | 10000 |    14998 | 39830 | 311MB |       
|          |                 |
|  9 |         INDEX RANGE SCAN                  | SFE_IX1                    | 
   4180 |  230 |      3851 |     +4 | 10000 |       4G |  2688 |  21MB |       
|          |                 |
| 10 |       INDEX UNIQUE SCAN                   | STD_PK                     | 
      1 |    1 |      3853 |     +4 | 14998 |    14998 |       |       |       
|          |                 |
| 11 |      TABLE ACCESS BY INDEX ROWID          | STD                        | 
      1 |    2 |      3852 |     +4 | 14998 |    14998 |       |       |       
|          |                 |
=============================================================================================================================================================================================

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("RN"<2)
   2 - filter(ROW_NUMBER() OVER ( PARTITION BY "SBD"."BDID" ORDER BY 
INTERNAL_FUNCTION("SFE"."FID") DESC )<2)
   6 - filter("SBD"."STAT"=:B2)
   7 - access("HD_ID"=:B1)
   8 - filter(("SFE"."ptcode"='ZZ' OR "SFE"."ptcode"='XX' OR 
"SFE"."ptcode"='YY') AND "SFE"."fhid"="SBD"."sfhid" AND "SFE"."oid"="SBD"."sid" 
AND
              NVL("SFE"."SCID",0)=NVL("SBD"."SCID",0) AND 
"SBD"."P_DT"="SFE"."P_DT")
   9 - access("SFE"."ETYP"='ZZZZ' AND "SFE"."eid"="SBD"."did")
  10 - access("SFE"."eid"="STD"."did")

 

 

Other related posts: