Probably one of the first things i would do in such situation -
doublecheck, whether the sql from the function -
select count(*) into dicount from pmtd td
where td.did = pnum AND td.cid in (999999);
always runs with the same execution plan.
Regards
Maxim
On Tue, Nov 28, 2023 at 1:55 PM Lok P <loknath.73@xxxxxxxxx> wrote:
Thank you for the response.
My Apology. I forgot to mention its version 19C (19.19.0.0.0) of oracle on
exadata.
There exists only one composite (TXN_ID, WOD_DT) primary key index on this
table-PBDRA_DTL. This table is daily range partitioned on a date column.
And also the sequence -PBDRAD_SEQ does fed into the leading column(TXN_ID)
of the PK index.
The AVG_ROW_LEN i see in dba_tab_partition for last few of the partitions
are showing ~198 and similar for others too.
PARTITION_NAME NUM_ROWS BLOCKS AVG_ROW_LEN COMPRESSION
PBDRA_DTL_11272023_P 33734616 1487844 197 DISABLED
PBDRA_DTL_11262023_P 33469912 980070 198 DISABLED
PBDRA_DTL_11252023_P 33527112 994892 198 DISABLED
PBDRA_DTL_11242023_P 33948522 991827 198 DISABLED
PBDRA_DTL_11232023_P 32667974 993492 198 DISABLED
PBDRA_DTL_11222023_P 34653004 1529017 198 DISABLED
PBDRA_DTL_11212023_P 33233838 968435 198 DISABLED
PBDRA_DTL_11202023_P 32870086 1472631 198 DISABLED
PBDRA_DTL_11192023_P 32485084 947193 198 DISABLED
Select list doesnt have any plsql function.
Today I have captured the sql monitor and related stats from v$sesstat for
a ~5minutes delta period for a quick/good run in which the complete query
finished in ~15minutes. I have posted the sql monitor and stats in same
github link, The session stats i have posted as comments to the same github
linc.
https://gist.github.com/oraclelearner/722a77ef5ebce23396d82e2835958303
When you mentioned "*some catastrophic activity on the base table might
cause the ASSM related stats*", are you pointing to delete or anything?
Because we normally dont performa DELETE but just use partition DROP for
data purge on these tables. Below is the stats specific to ASSM i do
observe , and those i have not noticed in past frequently. And also as we
encounter this slow run intermittently, so not sure if we are encountering
any bugs related to ASSM here?
***** BAD RUN******
ASSM cbk:blocks examined 184273393
ASSM cbk:blocks marked full 4610
ASSM gsp:bump HWM 2
ASSM gsp:get free block 46150
ASSM gsp:good hint 36942
ASSM gsp:L1 bitmaps examined 42601388
ASSM gsp:L2 bitmap full 2
ASSM gsp:L2 bitmaps examined 151006
ASSM gsp:Optimized index block rejects 438092544
ASSM gsp:Optimized reject DB 36692008
ASSM gsp:Optimized reject l1 1150
ASSM gsp:reject db 622315351
ASSM gsp:reject L1 462672
ASSM gsp:Search all 2
ASSM gsp:Search hint 35
ASSM gsp:Search steal 2
blocks decrypted 41626
branch node splits 8
buffer is not pinned count 1424244
buffer is pinned count 296
calls to get snapshot scn: kcmgss 1429118
***** GOOD RUN*****
ASSM cbk:blocks examined 12188141
ASSM cbk:blocks marked full 214458
ASSM gsp:bump HWM 37
ASSM gsp:get free block 405327
ASSM gsp:good hint 405308
ASSM gsp:L1 bitmaps examined 21220340
ASSM gsp:L2 bitmap full 64
ASSM gsp:L2 bitmaps examined 9006
ASSM gsp:L3 bitmaps examined 54
ASSM gsp:Optimized reject DB 185267698
ASSM gsp:Optimized reject l1 124657
ASSM gsp:Optimized reject l2 27
ASSM gsp:reject db 11568356
ASSM gsp:reject L1 13730
ASSM gsp:reject L2 27
ASSM gsp:Search all 37
ASSM gsp:Search hint 402
ASSM gsp:Search steal 37
blocks decrypted 125480
branch node splits 77
buffer is not pinned count 12752925
buffer is pinned count 2643
calls to get snapshot scn: kcmgss 12796284
*******
The tablespaces holding the table and index partitions are all TDE
encrypted.
The logic inside FUN1 looks something as below. It does execute sql inside
it but we have not changed anything in this logic recently. The table pmtd
having ~1.8million rows and having size ~497MB. Its using index for
accessing that table inside this function. Dont see a change in input data
pattern for this function in both the days.
FUNCTION Fun1 (cnum IN VARCHAR2, pnum IN VARCHAR2)
RETURN VARCHAR2
IS
ret VARCHAR2(20) := 'XX';
dicount NUMBER := null;
BEGIN
IF (cnum = '1111')
THEN
ret := 'XX';
ELSE IF (cnum is null)
THEN
select count(*) into dicount from pmtd td
where td.did = pnum AND td.cid in (999999);
IF(dicount > 0) THEN ret := 'Y';
ELSE
ret := 'N';
END IF;
END IF;
END IF;
RETURN ret;
END;
On Tue, 28 Nov, 2023, 4:58 pm Dominic Brooks, <dombrooks@xxxxxxxxxxx>
wrote:
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> 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 | | |
=====================================================================================================================================================================================
