Re: Same query with no plan change or volume but runs for hours vs minutes

  • From: Jonathan Lewis <jlewisoracle@xxxxxxxxx>
  • To: Oracle L <oracle-l@xxxxxxxxxxxxx>
  • Date: Tue, 28 Nov 2023 10:11:31 +0000

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
|          |                 |

=====================================================================================================================================================================================

Other related posts: