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.
316M compared to 18G - only a few of which require actual physical reads.
But the answer should be in the session statistics for the two respective sessions.
5 minutes sample stats is not a lot from 6.5 hours.
I would be looking at AWR, ASH and application logging to see if there's any correlation to any other processing involving the same objects beforehand some times.
Otherwise it's the full session stats for the session which is going to tell you the WHY. Although statistics are only part of the answer. If you could snap before/after execution of this SQL (from the code for example), that should help you find out the high level category of what is being done.
An extended sql trace for this sql id would also help answer.
Which version of Oracle?
There are two possible places suggested by what you've told us that might be where the excess CPU is used.
Regards
On Mon, 27 Nov 2023 at 20:15, Lok P <loknath.73_at_gmail.com<mailto:loknath.73_at_gmail.com>> wrote:
Hi All,
The insert query normally runs for <15minutes somedays runs for ~6-7hrs with exactly the same plan and approx same volume. And all the resources seem to be spent on step "LOAD TABLE CONVENTIONAL" and its "ON CPU". Wondering where it's spending time during the long execution?
While the long run was happening , we tried to fetch the stats from v$sesstat for a ~5minutes duration and collected the non zero stats. Not able to find out anything odd. Could you please guide me here, what must be the cause of this sudden long execution on some days for this same query with almost the same volume?
I have posted the sql monitors from both the runs below and also in the below github linc. And also published the nonzero output from the v$sesstat for the long execution for a ~5 minutes delta duration.We do see some stats like "KTFB alloc**" , is that normal or some issue is causing these stats to pop up?
https://gist.github.com/oraclelearner/722a77ef5ebce23396d82e2835958303
Global Stats
SQL Plan Monitoring Details (Plan Hash Value=557779869)
Global Information
Global Stats
SQL Plan Monitoring Details (Plan Hash Value=557779869)
I would think this is probably a side-effect of some other processing.
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
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?
Jonathan Lewis
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
| 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% |
===========================================================================================================================================================================
| 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 ****************
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 : 993s
PLSQL Entry Ids (Object/Subprogram) : 161298,9
PLSQL Current Ids (Object/Subprogram) : 161298,15
| 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% |
===========================================================================================================================================================================
| 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-l
Received on Tue Nov 28 2023 - 12:27:18 CET