Re: Same query with no plan change or volume but runs for hours vs minutes
From: Dominic Brooks <dombrooks_at_hotmail.com>
Date: Tue, 28 Nov 2023 11:27:18 +0000
Message-ID: <DBAPR02MB6470371F7B841B7BFAB47A06A1BCA_at_DBAPR02MB6470.eurprd02.prod.outlook.com>
From: oracle-l-bounce_at_freelists.org <oracle-l-bounce_at_freelists.org> on behalf of Jonathan Lewis <jlewisoracle_at_gmail.com> Sent: 28 November 2023 10:11
To: Oracle L <oracle-l_at_freelists.org> Subject: Re: Same query with no plan change or volume but runs for hours vs minutes
Date: Tue, 28 Nov 2023 11:27:18 +0000
Message-ID: <DBAPR02MB6470371F7B841B7BFAB47A06A1BCA_at_DBAPR02MB6470.eurprd02.prod.outlook.com>
It's all about the buffer gets.
I would think this is probably a side-effect of some other processing.
316M compared to 18G - only a few of which require actual physical reads.
From: oracle-l-bounce_at_freelists.org <oracle-l-bounce_at_freelists.org> on behalf of Jonathan Lewis <jlewisoracle_at_gmail.com> Sent: 28 November 2023 10:11
To: Oracle L <oracle-l_at_freelists.org> Subject: Re: Same query with no plan change or volume but runs for hours vs minutes
Which version of Oracle?
What's the average row length of the rows inserted into the table?
How many indexes on the table - is it just one on the sequence-generated column?
Does the "fun1()" function in the where clause execute any SQL?
Does the select list include any pl/sql functions that execute any SQL?
There are two possible places suggested by what you've told us that might be where the excess CPU is used.
- In some PL/SQL function code that either executes very late in the statement, or execute fairly early but gets reported in the wrong place
- the amount of time Oracle spends check the ASSM bitmaps for free space has exploded - possible because of some catastrophic activity in the table that happened before this insert started.
Regards
Jonathan Lewis
On Mon, 27 Nov 2023 at 20:15, Lok P <loknath.73_at_gmail.com<mailto:loknath.73_at_gmail.com>> wrote: Hi All,
https://gist.github.com/oraclelearner/722a77ef5ebce23396d82e2835958303
- Sql monitor from long run ********
Global Information
Status : EXECUTING Instance ID : 1 SQL Execution ID : 16777216 Execution Started : 11/27/2023 03:30:16 First Refresh Time : 11/27/2023 03:30:19 Last Refresh Time : 11/27/2023 10:06:13 Duration : 23759s PLSQL Entry Ids (Object/Subprogram) : 161298,9 PLSQL Current Ids (Object/Subprogram) : 161298,15
Global Stats
| Elapsed | Cpu | IO | Application | Concurrency | Cluster | PL/SQL | Other | Buffer | Read | Read | Uncompressed | Offload | Offload | Cell | | Time(s) | Time(s) | Waits(s) | Waits(s) | Waits(s) | Waits(s) | Time(s) | Waits(s) | Gets | Reqs | Bytes | Bytes | Elig Bytes | Returned Bytes | Offload |
===========================================================================================================================================================================
| 23758 | 23570 | 4.88 | 1.28 | 4.78 | 58 | 41 | 119 | 18G | 1M | 719GB | 359GB | 715GB | 4GB | 99.42% |
===========================================================================================================================================================================
SQL Plan Monitoring Details (Plan Hash Value=557779869)
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Read | Read | Mem | Activity | Activity Detail | Progress | | | | | (Estim) | | Active(s) | Active | | (Actual) | Reqs | Bytes | | (%) | (# samples) | |
==================================================================================================================================================================================================================================
| -> 0 | INSERT STATEMENT | | | | 23761 | +3 | 1 | 0 | | | . | 0.16 | Cpu (35) | | | | | | | | | | | | | | | | cell smart table scan (2) | | | -> 1 | LOAD TABLE CONVENTIONAL | PBDRA_DTL | | | 23762 | +2 | 1 | 0 | 499K | 4GB | . | 98.42 | gc current block 2-way (4) | | | | | | | | | | | | | | | | gc current grant 2-way (23) | | | | | | | | | | | | | | | | gc current grant busy (18) | | | | | | | | | | | | | | | | latch: cache buffers chains (5) | | | | | | | | | | | | | | | | log file switch completion (1) | | | | | | | | | | | | | | | | undo segment extension (2) | | | | | | | | | | | | | | | | Cpu (22695) | | | | | | | | | | | | | | | | cell single block physical read: RDMA (8) | | | | | | | | | | | | | | | | cell single block physical read: xrmem cache (34) | | | | | | | | | | | | | | | | enq: FB - contention (1) | | | | | | | | | | | | | | | | ges message buffer allocation (2) | | | | | | | | | | | | | | | | cell single block physical read: flash cache (3) | | | -> 2 | SEQUENCE | PBDRA_SEQ | | | 23761 | +3 | 1 | 18M | | | . | 0.50 | Cpu (109) | | | | | | | | | | | | | | | | reliable message (6) | | | -> 3 | HASH JOIN | | 68259 | 1M | 23761 | +3 | 1 | 18M | | | 5MB | 0.02 | Cpu (5) | | | 4 | TABLE ACCESS STORAGE FULL | PRFS | 78 | 2 | 1 | +3 | 1 | 63 | 1 | 40960 | . | | | | | -> 5 | PARTITION RANGE ITERATOR | | 152K | 1M | 23761 | +3 | 1 | 18M | | | . | | | | | -> 6 | TABLE ACCESS STORAGE FULL | PBABR_DTL | 152K | 1M | 23761 | +3 | 215 | 18M | 740K | 715GB | 7MB | 0.33 | Cpu (73) | 100% | | | | | | | | | | | | | | | gcs drm freeze in enter server mode (1) | | | | | | | | | | | | | | | | reliable message (1) | | | | | | | | | | | | | | | | cell smart table scan (1) | |
==================================================================================================================================================================================================================================
********* Quick Run ****************
Global Information
Status : DONE Instance ID : 1 SQL Execution ID : 16777216 Execution Started : 11/24/2023 04:39:04 First Refresh Time : 11/24/2023 04:39:07 Last Refresh Time : 11/24/2023 04:55:37 Duration : 993sPLSQL Entry Ids (Object/Subprogram) : 161298,9 PLSQL Current Ids (Object/Subprogram) : 161298,15
Global Stats
| Elapsed | Cpu | IO | Application | Concurrency | Cluster | PL/SQL | Other | Buffer | Read | Read | Uncompressed | Offload | Offload | Cell | | Time(s) | Time(s) | Waits(s) | Waits(s) | Waits(s) | Waits(s) | Time(s) | Waits(s) | Gets | Reqs | Bytes | Bytes | Elig Bytes | Returned Bytes | Offload |
===========================================================================================================================================================================
| 993 | 942 | 5.27 | 0.05 | 0.01 | 0.02 | 68 | 46 | 316M | 2M | 867GB | 443GB | 861GB | 7GB | 99.21% |
===========================================================================================================================================================================
SQL Plan Monitoring Details (Plan Hash Value=557779869)
| 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 | INSERT STATEMENT | | | | 991 | +3 | 1 | 0 | | | . | | | | 1 | LOAD TABLE CONVENTIONAL | PBDRA_DTL | | | 991 | +3 | 1 | 0 | 874K | 7GB | . | | | | 2 | SEQUENCE | PBDRA_SEQ | | | 992 | +2 | 1 | 30M | | | . | | | | 3 | HASH JOIN | | 66851 | 1M | 991 | +3 | 1 | 30M | | | 5MB | | | | 4 | TABLE ACCESS STORAGE FULL | PRFS | 78 | 2 | 1 | +3 | 1 | 63 | 2 | 49152 | 1MB | | | | 5 | PARTITION RANGE ITERATOR | | 149K | 1M | 991 | +3 | 1 | 32M | | | . | | | | 6 | TABLE ACCESS STORAGE FULL | PBABR_DTL | 149K | 1M | 991 | +3 | 286 | 32M | 892K | 861GB | 7MB | | |
=====================================================================================================================================================================================
-- http://www.freelists.org/webpage/oracle-lReceived on Tue Nov 28 2023 - 12:27:18 CET