Re: Query with same plan running longer

From: Laurentiu Oprea <laurentiu.oprea06_at_gmail.com>
Date: Mon, 28 Feb 2022 22:02:36 +0200
Message-ID: <CA+riqSU2Rwty2+uDGjSMkmMNMuDHJLGNABBXP798s0s72vMmzw_at_mail.gmail.com>



you`ve mentioned about some sesstats numbers but I don't see any, can you capture the sesstats for each run (long/short)?

The fact that full hints make a difference to me personally sounds suspicious.

can you also give a try with:
alter session set "_small_table_threshold"=1;

Also if this is possible, can you flush the buffer cache and then do a test run?

În lun., 28 feb. 2022 la 21:51, Lok P <loknath.73_at_gmail.com> a scris:

> I tried running the query by setting "_serial_direct_read"=always at
> session level, but it didn't work. It's again showing ~50% cell offloading
> percent with the same plan and running for ~2minutes+.
>
> But I again tried by forcing full hints for all the tables in the
> query(without any Parallel hint) and the seeing cell offloading percent
> ~90%+ and also the query finishing in quick time. Is it because we are just
> getting to the edge of any limit related to cell offloading percentage
> which is causing such behaviour?
>
>
> Global Information
> ------------------------------
> Status : DONE (ALL ROWS)
> Instance ID : 1
> SQL Execution ID : 16777216
> Execution Started : 02/28/2022 14:36:49
> First Refresh Time : 02/28/2022 14:36:58
> Last Refresh Time : 02/28/2022 14:37:04
> Duration : 15s
> Module/Action : SQL*Plus/-
> Program : sqlplus.exe
> Fetch Calls : 3
>
> Global Stats
>
> =====================================================================================================================================
> | Elapsed | Cpu | IO | Application | Fetch | Buffer | Read |
> Read | Uncompressed | Offload | Offload | Cell |
> | Time(s) | Time(s) | Waits(s) | Waits(s) | Calls | Gets | Reqs |
> Bytes | Bytes | Elig Bytes | Returned Bytes | Offload |
>
> =====================================================================================================================================
> | 15 | 1.74 | 13 | 0.02 | 3 | 26M | 201K |
> 196GB | 195GB | 196GB | 66MB | 99.97% |
>
> =====================================================================================================================================
>
>
> ===============================================================================================================================================================================================
> | 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 | +15 | 1 | 6357 | | | .
> | | |
> | 1 | SORT ORDER BY | |
> 3786 | 4M | 1 | +15 | 1 | 6357 | | | 1MB
> | | |
> | 2 | COUNT STOPKEY | |
> | | 1 | +15 | 1 | 6357 | | | .
> | | |
> | 3 | HASH JOIN | |
> 3786 | 4M | 1 | +15 | 1 | 6357 | | | 5MB
> | | |
> | 4 | JOIN FILTER CREATE | :BF0000 |
> 3713 | 4M | 1 | +15 | 1 | 6357 | | | .
> | | |
> | 5 | HASH JOIN | |
> 3713 | 4M | 7 | +9 | 1 | 6357 | | | 5MB
> | | |
> | 6 | JOIN FILTER CREATE | :BF0001 |
> 3720 | 4M | 7 | +9 | 1 | 6357 | | | .
> | | |
> | 7 | TABLE ACCESS STORAGE FULL | TAB1 |
> 3720 | 4M | 15 | +1 | 1 | 6357 | 201K | 196GB | 7MB
> | 100.00 | Cpu (1) |
> | | | |
> | | | | | | | |
> | | cell smart table scan (13) |
> | 8 | JOIN FILTER USE | :BF0001 |
> 2M | 3237 | 1 | +15 | 1 | 6577 | | | .
> | | |
> | 9 | TABLE ACCESS STORAGE FULL | TD |
> 2M | 3237 | 1 | +15 | 1 | 6577 | 176 | 174MB | 7MB
> | | |
> | 10 | JOIN FILTER USE | :BF0000 |
> 959K | 2596 | 1 | +15 | 1 | 1197 | | | .
> | | |
> | 11 | TABLE ACCESS STORAGE FULL | CMS |
> 959K | 2596 | 1 | +15 | 1 | 1197 | 144 | 143MB | 7MB
> | | |
>
> ===============================================================================================================================================================================================
>
> On Tue, Mar 1, 2022 at 12:48 AM Laurentiu Oprea <
> laurentiu.oprea06_at_gmail.com> wrote:
>
>> Hello Lok,
>>
>> If you can replicate this, can you set at session level:
>>
>> alter session set "_serial_direct_read"=always;
>>
>> and see if it has any effect?
>>
>> Thanks.
>>
>> În lun., 28 feb. 2022 la 21:05, Lok P <loknath.73_at_gmail.com> a scris:
>>
>>> The plan which I posted earlier was from dba_hist_reports. And
>>> currently when we run the query , the same plan is not doing ~90%+ cell
>>> offloading and running for 2minutes+. However, I just tried with
>>> parallel(2) hints and surprisingly the plan is almost the same but now cell
>>> offloading percent increased to ~99% and the query was finished in quick
>>> time.How is that happening? We have recently migrated our tablespaces to
>>> TDE , can that cause such an issue?
>>>
>>>
>>> Global Information
>>> ------------------------------
>>> Status : DONE (ALL ROWS)
>>> Instance ID : 1
>>> SQL Execution ID : 16777217
>>> Execution Started : 02/28/2022 04:32:47
>>> First Refresh Time : 02/28/2022 04:32:48
>>> Last Refresh Time : 02/28/2022 04:32:57
>>> Duration : 10s
>>> Module/Action : SQL*Plus/-
>>> Program : sqlplus.exe
>>> Fetch Calls : 18
>>>
>>> Global Stats
>>>
>>> ================================================================================================================================================
>>> | Elapsed | Cpu | IO | Application | Other | Fetch | Buffer
>>> | Read | Read | Uncompressed | Offload | Offload | Cell |
>>> | Time(s) | Time(s) | Waits(s) | Waits(s) | Waits(s) | Calls | Gets
>>> | Reqs | Bytes | Bytes | Elig Bytes | Returned Bytes | Offload |
>>>
>>> ================================================================================================================================================
>>> | 16 | 6.27 | 10 | 0.18 | 0.09 | 18 | 26M
>>> | 201K | 196GB | 195GB | 196GB | 96MB | 99.95% |
>>>
>>> ================================================================================================================================================
>>>
>>> Parallel Execution Details (DOP=2 , Servers Allocated=4)
>>>
>>> ========================================================================================================================================================================================================
>>> | Name | Type | Server# | Elapsed | Cpu | IO |
>>> Application | Other | Buffer | Read | Read | Uncompressed | Offload
>>> | Offload | Cell | Wait Events |
>>> | | | | Time(s) | Time(s) | Waits(s) |
>>> Waits(s) | Waits(s) | Gets | Reqs | Bytes | Bytes | Elig Bytes
>>> | Returned Bytes | Offload | (sample #) |
>>>
>>> ========================================================================================================================================================================================================
>>> | PX Coordinator | QC | | 0.47 | 0.20 | |
>>> 0.18 | 0.09 | 63 | | . | . | . |
>>> . | NaN% | |
>>> | p000 | Set 1 | 1 | 7.66 | 2.75 | 4.91 |
>>> | | 13M | 99612 | 97GB | 97GB | 97GB |
>>> 55MB | 99.94% | cell smart table scan (3) |
>>> | p001 | Set 1 | 2 | 7.89 | 2.89 | 5.00 |
>>> | | 13M | 101K | 99GB | 98GB | 99GB |
>>> 41MB | 99.96% | cell smart table scan (6) |
>>> | p002 | Set 2 | 1 | 0.22 | 0.22 | 0.00 |
>>> | | 10757 | | . | . | . |
>>> . | NaN% | |
>>> | p003 | Set 2 | 2 | 0.21 | 0.21 | 0.00 |
>>> | | 12026 | | . | . | . |
>>> . | NaN% | |
>>>
>>> ========================================================================================================================================================================================================
>>>
>>> SQL Plan Monitoring Details (Plan Hash Value=70366485)
>>>
>>> =====================================================================================================================================================================================================
>>> | 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 |
>>> | | | 3 | +8 | 1 | 83472 | |
>>> | . | | |
>>> | 1 | SORT ORDER BY |
>>> | 3883 | 2M | 3 | +8 | 1 | 83472 | |
>>> | 13MB | | |
>>> | 2 | COUNT STOPKEY |
>>> | | | 1 | +8 | 1 | 83472 | |
>>> | . | | |
>>> | 3 | PX COORDINATOR |
>>> | | | 1 | +8 | 5 | 83472 | |
>>> | . | | |
>>> | 4 | PX SEND QC (RANDOM) | :TQ10002
>>> | 3883 | 2M | 1 | +8 | 2 | 83472 | |
>>> | . | | |
>>> | 5 | COUNT STOPKEY |
>>> | | | 1 | +8 | 2 | 83472 | |
>>> | . | | |
>>> | 6 | HASH JOIN |
>>> | 3883 | 2M | 1 | +8 | 2 | 83472 | |
>>> | 41MB | 6.67 | Cpu (1) |
>>> | 7 | PX RECEIVE |
>>> | 3808 | 2M | 1 | +8 | 2 | 167K | |
>>> | . | | |
>>> | 8 | PX SEND BROADCAST | :TQ10001
>>> | 3808 | 2M | 1 | +8 | 2 | 167K | |
>>> | . | | |
>>> | 9 | HASH JOIN |
>>> | 3808 | 2M | 6 | +3 | 2 | 83472 | |
>>> | 36MB | | |
>>> | 10 | JOIN FILTER CREATE | :BF0000
>>> | 3815 | 2M | 6 | +3 | 2 | 167K | |
>>> | . | | |
>>> | 11 | PX RECEIVE |
>>> | 3815 | 2M | 6 | +3 | 2 | 167K | |
>>> | . | | |
>>> | 12 | PX SEND BROADCAST | :TQ10000
>>> | 3815 | 2M | 7 | +2 | 2 | 167K | |
>>> | . | 6.67 | Cpu (1) |
>>> | 13 | PX BLOCK ITERATOR |
>>> | 3815 | 2M | 6 | +3 | 2 | 83472 | |
>>> | . | | |
>>> | 14 | TABLE ACCESS STORAGE FULL | TAB1
>>> | 3815 | 2M | 8 | +1 | 535 | 83472 | 201K | 196GB
>>> | 14MB | 80.00 | Cpu (3) |
>>> | | |
>>> | | | | | | | |
>>> | | | cell smart table scan (9) |
>>> | 15 | JOIN FILTER USE | :BF0000
>>> | 2M | 1791 | 1 | +8 | 2 | 10942 | |
>>> | . | | |
>>> | 16 | PX BLOCK ITERATOR |
>>> | 2M | 1791 | 1 | +8 | 2 | 10942 | |
>>> | . | | |
>>> | 17 | TABLE ACCESS STORAGE FULL | TD
>>> | 2M | 1791 | 1 | +8 | 37 | 10942 | |
>>> | . | | |
>>> | 18 | PX BLOCK ITERATOR |
>>> | 959K | 249 | 1 | +8 | 2 | 959K | |
>>> | . | | |
>>> | 19 | INDEX STORAGE FAST FULL SCAN | TD_IX1
>>> | 959K | 249 | 1 | +8 | 25 | 959K | |
>>> | . | 6.67 | Cpu (1) |
>>>
>>> =====================================================================================================================================================================================================
>>>
>>>
>>> On Tue, Mar 1, 2022 at 12:12 AM Lok P <loknath.73_at_gmail.com> wrote:
>>>
>>>> Its version 19.9 of oracle. We are seeing suddenly a query taking
>>>> longer even is using same path and looking into the sql monitor report from
>>>> past it shows the cell offloading percentage has been dropped from ~98% to
>>>> ~56%. Want to understand the cause behind this and how to fix it?
>>>>
>>>> Below is the sql monitor for this and majority of time is on step-6 i.e
>>>> full scan of TAB1 , however the read request , read bytes all seems to be
>>>> the same but still there is a big difference in the offloading percentage.
>>>> When I run the query manually and peek into the v$sesstat seeing below
>>>> output from that.
>>>>
>>>> SELECT .....
>>>> FROM TAB1 , TD , CMC
>>>> WHERE ROWNUM <= 100000
>>>> AND TAB1.TDN = td.DID
>>>> AND TAB1.CO_ID = CMC.PME
>>>> AND 1 = 1
>>>> AND ATI IN ('XXXXX')
>>>> AND ( ( ( ( IDR = 'Y' AND TRUNC (SYSDATE) - 15 >
>>>> I_DT) OR IDR = 'N')
>>>> AND PCSC IN ('CR', 'CC', 'CA', 'CI1',
>>>> 'CR1', 'CC2', 'CC3', 'CI4'))
>>>> OR (PCSC IN ('CC1', 'CI', 'CA1', 'CI2', 'CR2',
>>>> 'CC4', 'CA2', 'CI3'))
>>>> OR ( ( ( IDR = 'Y' AND TRUNC (SYSDATE) - 15 >
>>>> I_DT) OR IDR = 'N') AND PCSC IN ('CI4', 'CI5') AND S_DT < TRUNC
>>>> (SYSDATE))
>>>> OR ( PCSC IN ('CI6', 'CI7') AND S_DT < TRUNC
>>>> (SYSDATE)))
>>>> AND ( D_DT > SYSDATE - 120 OR (IDR = 'N' AND D_DT IS NULL))
>>>> ORDER BY D_DT ASC, S_AMT DESC
>>>>
>>>> *********** Slow execution *****************
>>>>
>>>> Global Information
>>>> ------------------------------
>>>> Status : DONE (ALL ROWS)
>>>> Instance ID : 1
>>>> Execution Started : 02/26/2022 06:58:23
>>>> First Refresh Time : 02/26/2022 06:58:27
>>>> Last Refresh Time : 02/26/2022 07:00:40
>>>> Duration : 137s
>>>> Module/Action : JDBC Thin Client/-
>>>> Program : JDBC Thin Client
>>>> Fetch Calls : 3877
>>>>
>>>> Global Stats
>>>>
>>>> =====================================================================================================================================
>>>> | Elapsed | Cpu | IO | Application | Fetch | Buffer | Read |
>>>> Read | Uncompressed | Offload | Offload | Cell |
>>>> | Time(s) | Time(s) | Waits(s) | Waits(s) | Calls | Gets | Reqs |
>>>> Bytes | Bytes | Elig Bytes | Returned Bytes | Offload |
>>>>
>>>> =====================================================================================================================================
>>>> | 137 | 133 | 3.46 | 0.09 | 3877 | 26M | 201K |
>>>> 196GB | 111GB | 196GB | 84GB | 56.90% |
>>>>
>>>> =====================================================================================================================================
>>>>
>>>> SQL Plan Monitoring Details (Plan Hash Value=3977078242)
>>>>
>>>> ====================================================================================================================================================================================
>>>> | 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 | |
>>>> | | 3 | +135 | 1 | 38764 | | |
>>>> . | | |
>>>> | 1 | SORT ORDER BY | |
>>>> 3876 | 4M | 3 | +135 | 1 | 38764 | | |
>>>> 6MB | | |
>>>> | 2 | COUNT STOPKEY | |
>>>> | | 1 | +135 | 1 | 38764 | | |
>>>> . | | |
>>>> | 3 | HASH JOIN | |
>>>> 3876 | 4M | 1 | +135 | 1 | 38764 | | |
>>>> 15MB | | |
>>>> | 4 | HASH JOIN | |
>>>> 3802 | 4M | 132 | +4 | 1 | 38764 | | |
>>>> 13MB | | |
>>>> | 5 | JOIN FILTER CREATE | :BF0000 |
>>>> 3809 | 4M | 132 | +4 | 1 | 38764 | | |
>>>> . | | |
>>>> | 6 | TABLE ACCESS STORAGE FULL | TAB1 |
>>>> 3809 | 4M | 135 | +1 | 1 | 38764 | 201K | 196GB |
>>>> 7MB | | |
>>>> | 7 | JOIN FILTER USE | :BF0000 |
>>>> 2M | 3237 | 1 | +135 | 1 | 15626 | | |
>>>> . | | |
>>>> | 8 | TABLE ACCESS STORAGE FULL | TD |
>>>> 2M | 3237 | 1 | +135 | 1 | 15626 | | |
>>>> . | | |
>>>> | 9 | INDEX STORAGE FAST FULL SCAN | TD_IX1 |
>>>> 959K | 448 | 2 | +135 | 1 | 959K | | |
>>>> . | | |
>>>>
>>>> ====================================================================================================================================================================================
>>>>
>>>> ************** fast execution ***************
>>>>
>>>>
>>>> Global Information
>>>> ------------------------------
>>>> Status : DONE (ALL ROWS)
>>>> Instance ID : 1
>>>> SQL Execution ID : 16777247
>>>> Execution Started : 02/25/2022 15:38:36
>>>> First Refresh Time : 02/25/2022 15:38:40
>>>> Last Refresh Time : 02/25/2022 15:39:09
>>>> Duration : 33s
>>>> Module/Action : JDBC Thin Client/-
>>>> Program : JDBC Thin Client
>>>> Fetch Calls : 1801
>>>>
>>>> Global Stats
>>>>
>>>> =====================================================================================================================================
>>>> | Elapsed | Cpu | IO | Application | Fetch | Buffer | Read |
>>>> Read | Uncompressed | Offload | Offload | Cell |
>>>> | Time(s) | Time(s) | Waits(s) | Waits(s) | Calls | Gets | Reqs |
>>>> Bytes | Bytes | Elig Bytes | Returned Bytes | Offload |
>>>>
>>>> =====================================================================================================================================
>>>> | 33 | 8.29 | 25 | 0.02 | 1801 | 26M | 204K |
>>>> 195GB | 191GB | 195GB | 3GB | 98.21% |
>>>>
>>>> =====================================================================================================================================
>>>>
>>>> SQL Plan Monitoring Details (Plan Hash Value=3977078242)
>>>>
>>>> ====================================================================================================================================================================================
>>>> | 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 | +32 | 1 | 18003 | | |
>>>> . | | |
>>>> | 1 | SORT ORDER BY | |
>>>> 3866 | 4M | 2 | +32 | 1 | 18003 | | |
>>>> 3MB | | |
>>>> | 2 | COUNT STOPKEY | |
>>>> | | 1 | +32 | 1 | 18003 | | |
>>>> . | | |
>>>> | 3 | HASH JOIN | |
>>>> 3866 | 4M | 1 | +32 | 1 | 18003 | | |
>>>> 8MB | | |
>>>> | 4 | HASH JOIN | |
>>>> 3792 | 4M | 23 | +10 | 1 | 18003 | | |
>>>> 6MB | | |
>>>> | 5 | JOIN FILTER CREATE | :BF0000 |
>>>> 3800 | 4M | 23 | +10 | 1 | 18003 | | |
>>>> . | | |
>>>> | 6 | TABLE ACCESS STORAGE FULL | TAB1 |
>>>> 3800 | 4M | 32 | +1 | 1 | 18003 | 204K | 195GB |
>>>> 7MB | | |
>>>> | 7 | JOIN FILTER USE | :BF0000 |
>>>> 2M | 3237 | 1 | +32 | 1 | 11409 | | |
>>>> . | | |
>>>> | 8 | TABLE ACCESS STORAGE FULL | TD |
>>>> 2M | 3237 | 1 | +32 | 1 | 11409 | | |
>>>> . | | |
>>>> | 9 | INDEX STORAGE FAST FULL SCAN | TD_IX1 |
>>>> 959K | 448 | 1 | +32 | 1 | 959K | | |
>>>> . | | |
>>>>
>>>> ====================================================================================================================================================================================
>>>>
>>>> Predicate Information (identified by operation id):
>>>> ---------------------------------------------------
>>>>
>>>> 2 - filter(ROWNUM<=100000)
>>>> 3 - access("CMC"."PME"=TO_NUMBER("TAB1"."CO_ID"))
>>>> 4 - access("TAB1"."TDN"="TD"."DID")
>>>> 6 - storage("ATI"='XXXXXXX' AND (("PCSC"='CA2' OR "PCSC"='CR2' OR
>>>> "PCSC"='CC4' OR "PCSC"='CI3' OR "PCSC"='CA1' OR "PCSC"='CC1' OR
>>>> "PCSC"='CI' OR "PCSC"='CI2') OR ("PCSC"='CC3' OR "PCSC"='CC2' OR
>>>> "PCSC"='CI4' OR "PCSC"='CR1' OR "PCSC"='CA' OR
>>>> "PCSC"='CC' OR "PCSC"='CI1' OR "PCSC"='CR') AND ("IDR"='N' OR "IDR"='Y'
>>>> AND "I_DT"<TRUNC(SYSDATE_at_!)-15) OR
>>>> ("PCSC"='CI7' OR "PCSC"='CI6') AND "S_DT"<TRUNC(SYSDATE_at_!)
>>>> OR ("PCSC"='CI5' OR "PCSC"='CI4') AND ("IDR"='N' OR "IDR"='Y' AND
>>>> "I_DT"<TRUNC(SYSDATE_at_!)-15) AND "S_DT"<TRUNC(SYSDATE_at_!))
>>>> AND ("D_DT" IS NULL AND "IDR"='N' OR "D_DT">SYSDATE_at_
>>>> !-120))
>>>> filter("ATI"='XXXXXXX' AND (("PCSC"='CA2' OR "PCSC"='CR2' OR
>>>> "PCSC"='CC4' OR "PCSC"='CI3' OR "PCSC"='CA1' OR "PCSC"='CC1' OR "PCSC"='CI'
>>>> OR "PCSC"='CI2') OR ("PCSC"='CC3' OR "PCSC"='CC2' OR
>>>> "PCSC"='CI4' OR "PCSC"='CR1' OR "PCSC"='CA' OR
>>>> "PCSC"='CC' OR "PCSC"='CI1' OR "PCSC"='CR') AND ("IDR"='N' OR "IDR"='Y'
>>>> AND "I_DT"<TRUNC(SYSDATE_at_!)-15) OR
>>>> ("PCSC"='CI7' OR "PCSC"='CI6') AND "S_DT"<TRUNC(SYSDATE_at_!)
>>>> OR ("PCSC"='CI5' OR "PCSC"='CI4') AND ("IDR"='N' OR "IDR"='Y' AND
>>>> "I_DT"<TRUNC(SYSDATE_at_!)-15) AND "S_DT"<TRUNC(SYSDATE_at_!))
>>>> AND ("D_DT" IS NULL AND "IDR"='N' OR "D_DT">SYSDATE_at_
>>>> !-120))
>>>> 8 - storage(SYS_OP_BLOOM_FILTER(:BF0000,"TD"."DID"))
>>>> filter(SYS_OP_BLOOM_FILTER(:BF0000,"TD"."DID"))
>>>>
>>>

--
http://www.freelists.org/webpage/oracle-l
Received on Mon Feb 28 2022 - 21:02:36 CET

Original text of this message