Re: Same query with no plan change or volume but runs for hours vs minutes
Date: Tue, 28 Nov 2023 10:11:31 +0000
Message-ID: <CAGtsp8nOAG2GfQ+rxmK6VudAD2=YBp8X95rjEokSL+sEZjDLoA_at_mail.gmail.com>
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> 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
> | | |
>
> =====================================================================================================================================================================================
>
-- http://www.freelists.org/webpage/oracle-lReceived on Tue Nov 28 2023 - 11:11:31 CET