Re: Variable execution time of sql with same plan

Thank you Andy and Mark. Actually I have removed the bind variable section purposely so as not to expose the exact data. But yes in all the three cases the bind values were different. So as you mentioned the difference in run time in the first two cases was just merely because of the way the caching of index/table data was there in the buffer cache. And I am wondering if both the first and second execution happened at almost the same time, but why there is so much difference in the caching of that index and table blocks in those two executions. Our sga_target is ~44GB and sga_max_size is ~45GB, our db_cache_size is set as 0. Table SFE is having size ~1.2TB and index SFE_IX1 is having size ~154GB. So is there anything wrong with it , which we should fix? And this query runs in ~10 threads for different binds at same time, and we are seeing a significantly variable run time i.e. ~<10minutes to ~1hrs few of the times and so wondering if there is any relation of these concurrent runs with the slowness.

There already exists an index on FHID but I will try to see what other columns we can add to make the existing composite(etyp,eid ) index better so that access to the table SFE can be more selective here.

This table is composite partitioned (i.e. list-range partition) on a different column altogether. But none of the partition/subpartition keys/columns are used here in this query in th ejoin/filer predicates. So yes we may not get much help out of those. Ptcode has ~419 distinct values and even there already exists an index(SFE_IX4) on that column , but it's not used mostly because it's not that unique. And those three ptcode constitutes ~90million out of total ~1.7billion row in that table.

XX- ~89million
YY - ~2.6million
ZZ - .2million

On Fri, Nov 26, 2021 at 11:44 PM Mark W. Farnham <mwf_at_rsiz.com> wrote:

> 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_at_freelists.org [mailto:
> oracle-l-bounce_at_freelists.org] *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_at_gmail.com> 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")
>
>
>
>
>
>

--
http://www.freelists.org/webpage/oracle-l