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.
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.
________________________________
From: oracle-l-bounce@xxxxxxxxxxxxx <oracle-l-bounce@xxxxxxxxxxxxx> on behalf
of Jonathan Lewis <jlewisoracle@xxxxxxxxx>
Sent: 28 November 2023 10:11
To: Oracle L <oracle-l@xxxxxxxxxxxxx>
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.
1) 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
2) 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@xxxxxxxxx<mailto:loknath.73@xxxxxxxxx>> 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
******** 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 : 993s
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 |
===========================================================================================================================================================================
| 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 |
| |
=====================================================================================================================================================================================
