13 Replies Latest reply on Mar 7, 2017 9:13 AM by Jonathan Lewis

    Slow conventional Insert statement consuming a lot of CPU time (Exadata)

    Ahmed AANGOUR

      Hi,

       

      We have an insert statement that started to run very slowly during the last days (several hours instead of less than 1 hour)

      The analysis of the ASH says that the problem is on the LOAD TABLE CONVENTIONAL operation, so that let me guess that the problem is located inthe INSERT part.

      The SQL_ID is running several times during the night for different execution (use of bind variables) but it is always the same execution that is facing the issue.

      The statement inserts about 300k of rows in several hours (last night it took 6h) but we have other inserts (same sql_id) inserting 900K rows which complete in a few minutes every night.

      The problem is not repoducible during the day.

      I'm triying to understand:

      - Where is spending the CPU time during the  LOAD TABLE CONVENTIONAL operation?

      - Why other executions for the same SQl_ID are completing in a few minutes ?

       

       

      The database is running on Exadata (X3 db node) and on a 11.2.0.4 database.

      Here is the query:

      INSERT

        /*+ ignore_row_on_dupkey_index(tgt OTC_DAT_TV_PROC_STATUS_UK) */

      INTO OTC_DAT_TV_PROC_STATUS TGT

        (

          SK_TRADE_STATUS ,

          SK_TRADE_VERSION ,

          SK_STATUS_TYPO ,

          SK_STATUS_DURATION ,

          STATUS_START_TIMESTAMP ,

          STATUS_END_TIMESTAMP ,

          STATUS_MEDIA_TYPE ,

          STATUS_SENDER_PARTY_ID ,

          STATUS_SENDER_PARTY_ID_SC ,

          STATUS_RECEIVER_PARTY_ID ,

          STATUS_RECEIVER_PARTY_ID_SCH ,

          STATUS_TIMESTAMP ,

          CLEARING_PARTY_ID ,

          CLEARING_PARTY_ID_SCH ,

          CLEARING_SYSTEM_TYPE ,

          CHECKSUM_PROC_STATUS ,

          DT_LOAD ,

          DT_LOAD_TRADE_VERSION ,

          SEQ_PROC_STATUS

        )

      SELECT

        /*+ parallel(8) */

        OTC_DAT_TV_PROC_STATUS_SEQ.NEXTVAL ,

        TV.SK_TRADE_VERSION ,

        PST.SK_STATUS_TYPO ,

        PSD.SK_STATUS_DURATION ,

        PS.STATUS_START_TIMESTAMP ,

        PS.STATUS_END_TIMESTAMP ,

        PS.STATUS_MEDIA_TYPE ,

        PS.STATUS_SENDER_PARTY_ID ,

        PS.STATUS_SENDER_PARTY_ID_SC ,

        PS.STATUS_RECEIVER_PARTY_ID ,

        PS.STATUS_RECEIVER_PARTY_ID_SCH ,

        PS.STATUS_TIMESTAMP ,

        PS.CLEARING_PARTY_ID ,

        PS.CLEARING_PARTY_ID_SCH ,

        PS.CLEARING_SYSTEM_TYPE ,

        PS.CHECKSUM_PROC_STATUS ,

        :B3 ,

        TV.DT_LOAD ,

        SEQ_AND_CHECKSUM.SEQ_PROC_STATUS

      FROM TPS_STG$OWNER.OTC_DAT_TV_PROC_STATUS PS

      JOIN

        (SELECT PS.CHECKSUM_PROC_STATUS,

          PS.SEQ_TRADE,

          MAX (PS.SEQ_PROC_STATUS) SEQ_PROC_STATUS

        FROM TPS_STG$OWNER.OTC_DAT_TV_PROC_STATUS PS

        WHERE PS.PARTITION_ID = :B2

        AND PS.TRADESET_ID    = :B1

        GROUP BY CHECKSUM_PROC_STATUS,

          PS.SEQ_TRADE

        ) SEQ_AND_CHECKSUM

      ON SEQ_AND_CHECKSUM.SEQ_PROC_STATUS = PS.SEQ_PROC_STATUS

      JOIN REF_DAT_STATUS_TYPOLOGY PST

      ON PST.STATUS_TYPE                    = PS.STATUS_TYPE

      AND PST.STATUS_SUB_TYPE               = PS.STATUS_SUB_TYPE

      AND PST.STATUS_SUB_TYPE_CODING_SCHEME = 'NA'

      JOIN REF_DAT_STATUS_DURATION PSD

      ON PSD.DURATION_CODE        = PS.STATUS_DURATION_CODE

      AND PSD.DURATION_COD_SCHEME = PS.STATUS_DURATION_COD_SCH

      JOIN TPS_STG$OWNER.OTC_DAT_TRADE_VERSION STG

      ON STG.PARTITION_ID = PS.PARTITION_ID

      AND STG.TRADESET_ID = PS.TRADESET_ID

      AND STG.SEQ_TRADE   = PS.SEQ_TRADE

      JOIN OTC_DAT_TRADE_VERSION TV

      ON TV.ID                      = STG.ID

      AND TV.CHECKSUM_TRADE_VERSION = STG.CHECKSUM_TRADE_VERSION

      WHERE PS.PARTITION_ID         = :B2

      AND PS.TRADESET_ID            = :B1 ;

       

      -- ASH analysis

      select  sql_plan_line_id,sql_plan_operation, count(*) from DBA_HIST_active_sess_history  ash

      where sample_time  >   to_timestamp('2017-03-02 23:21:00.000','YYYY-MM-DD HH24:MI:SSXFF')

        AND sample_time <= to_timestamp('2017-03-03 06:11:00.000','YYYY-MM-DD HH24:MI:SSXFF')

      and sql_id='6y6yg646zr315' and QC_SESSION_ID=1425

      group by sql_plan_line_id,sql_plan_operation

      order by  3 desc;

       

       

      SQL_PLAN_LINE_ID SQL_PLAN_OPERATION                                                 COUNT(*)

      ---------------- ---------------------------------------------------------------- ----------

                     1 LOAD TABLE CONVENTIONAL                                                2277    => PB is due to the INSERT part

                     5 HASH JOIN                                                               272

                    39 TABLE ACCESS                                                             62

                     2 SEQUENCE                                                                 60

                    15 HASH JOIN                                                                52

                                                                                                29

                       INSERT STATEMENT                                                         27

                     7 PX SEND                                                                  21

                    21 TABLE ACCESS                                                             20

                     3 PX COORDINATOR                                                           18

                     6 PX RECEIVE                                                               15

                     4 PX SEND                                                                  14

                    10 PX SEND                                                                  12

                     8 HASH JOIN                                                                 9

                    37 TABLE ACCESS                                                              8

                    12 PX RECEIVE                                                                7

                    13 PX SEND                                                                   7

                    14 HASH JOIN                                                                 3

                    19 SORT                                                                      2

                    38 PX BLOCK                                                                  2

                    17 PX SEND                                                                   2

                    14 PX SEND                                                                   1

                    26 TABLE ACCESS                                                              1

                     9 PX RECEIVE                                                                1

                    12 HASH JOIN                                                                 1

                    16 PX RECEIVE                                                                1

       

      The same query ran in less than a hour the night before and this time the ASH analysis shows that the time has been spent in the SELECT part:

      SQL_PLAN_LINE_ID SQL_PLAN_OPERATION                                                 COUNT(*)

      ---------------- ---------------------------------------------------------------- ----------

                    15 HASH JOIN                                                              1281

                    21 TABLE ACCESS                                                            500

                     1 LOAD TABLE CONVENTIONAL                                                 328

                     2 SEQUENCE                                                                  4

                                                                                                 2

                     3 PX COORDINATOR                                                            1

       

       

      When the problem occurs I have noticed that the CURRENT_OBJ# = 0 or -1:

      select  current_obj#, count(*) from DBA_HIST_active_sess_history  ash

      where sample_time  >   to_timestamp('2017-03-02 23:21:00.000','YYYY-MM-DD HH24:MI:SSXFF')

        AND sample_time <= to_timestamp('2017-03-03 06:11:00.000','YYYY-MM-DD HH24:MI:SSXFF')

      and sql_id='6y6yg646zr315' and QC_SESSION_ID=1425

      group by current_obj#

      order by 2 desc;

       

       

      CURRENT_OBJ#   COUNT(*)

      ------------ ----------

                 0        659

                -1        625

           5309346         46

           5309335         46

       

       

      I have also noticed that the p1TEXT is mainly on "cache id" and "cellhash" when sql_plan_operation='LOAD TABLE CONVENTIONAL' and CURRENT_OBJ#<1:

      SQL> select  p1text,count(*) from DBA_HIST_active_sess_history  ash

        2  where sample_time  >   to_timestamp('2017-03-02 23:21:00.000','YYYY-MM-DD HH24:MI:SSXFF')

        3    AND sample_time <= to_timestamp('2017-03-03 06:11:00.000','YYYY-MM-DD HH24:MI:SSXFF')

        4  and sql_id='6y6yg646zr315' and QC_SESSION_ID=1425 and sql_plan_operation='LOAD TABLE CONVENTIONAL' and CURRENT_OBJ#<1

        5  group by p1text

        6  order by 2 desc;

       

      P1TEXT                                                             COUNT(*)

      ---------------------------------------------------------------- ----------

      cache id                                                                526

      cellhash#                                                               340

      sleeptime/senderid                                                      159

      address                                                                  52

      handle address                                                           30

      file#                                                                    28

      name|mode                                                                23

      idn                                                                       2

       

      SQL> select  p1,p2,p3,count(*) from DBA_HIST_active_sess_history  ash

        2  where sample_time  >   to_timestamp('2017-03-02 23:21:00.000','YYYY-MM-DD HH24:MI:SSXFF')

        3    AND sample_time <= to_timestamp('2017-03-03 06:11:00.000','YYYY-MM-DD HH24:MI:SSXFF')

        4  and sql_id='6y6yg646zr315' and QC_SESSION_ID=1425 and sql_plan_operation='LOAD TABLE CONVENTIONAL'

        5  group by p1,p2,p3

        6  order by 4 desc;

       

       

              P1         P2         P3   COUNT(*)

      ---------- ---------- ---------- ----------

              13          0          5        723

               0          0          0        228

      4215650800 1532286858       8192         31

      1397817350    5308686          0         31

      2973322368 5435300368 2.2801E+16         21

      1610823616        299          0         21

               1    1295744   33554433         19

      3391883262 1935226483       8192         18

      3701283688 3717488454       8192         18

      2480893931  247570295       8192         17

      3391883262 1702723751       8192         17

      3391883262 1723529083       8192         17

      2480893931 1427725789       8192         17

      2106104525 3532961050       8192         17

      6.4459E+10        115          0         16

      4215650800 3591178946       8192         16

               1    1295744          1         16

      2774995862 2268391603       8192         16

      2774995862 1767183701       8192         16

      2973322368 6.5671E+10 2.2801E+16         15

      2774995862 2333714537       8192         15

       

      The table is partitioned by MONTH (DT_LOAD column) and there is 3 indexes on it. There is no TRIGGER.

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

        TABLE STATISTICS

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

      Owner         : tps_dwh$owner

      Table name    : otc_dat_tv_proc_status

      Tablespace    :

      Cluster name  :

      Partitioned   : yes

      Last analyzed : 02/01/2017 13:59:28

      Sample size   : 849474791

      Degree        : 1

      IOT Type      :

      IOT name      :

      # Rows        : 849474791

      # Blocks      : 1243278

      Empty Blocks  : 0

      Avg Space     : 0

      Avg Row Length: 66

      Monitoring?   : yes

      Elapsed: 00:00:00.04

       

       

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

        PARTITION INFORMATION

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

      Elapsed: 00:00:00.02

       

       

      Part# Partition Name                     Sample Size          # Rows        # Blocks Partition Bound                                                                                                          Last Analyzed

      ------ ------------------------------ --------------- --------------- --------------- ------------------------------------------------------------------------------------------------------------------------ -------------------

           1 PMINI                          .                             0               0 TIMESTAMP' 1900-01-01 00:00:00'                                                                                          09/22/2016 19:31:39

           2 SYS_P778163                            1504467         1504467            1704 TIMESTAMP' 2015-04-01 00:00:00'                                                                                          09/22/2016 19:34:25

           3 SYS_P787248                            7018114         7018114            7448 TIMESTAMP' 2015-05-01 00:00:00'                                                                                          09/22/2016 19:34:27

           4 SYS_P843336                           22057768        22057768           22144 TIMESTAMP' 2015-06-01 00:00:00'                                                                                          09/22/2016 19:34:33

           5 SYS_P910767                           31032596        31032596           28608 TIMESTAMP' 2015-07-01 00:00:00'                                                                                          09/22/2016 19:34:40

           6 SYS_P987062                           38605939        38605939           35120 TIMESTAMP' 2015-08-01 00:00:00'                                                                                          09/22/2016 19:34:49

           7 SYS_P1055366                          36682048        36682048           35312 TIMESTAMP' 2015-09-01 00:00:00'                                                                                          09/22/2016 19:31:49

           8 SYS_P1120003                          34947472        34947472           35392 TIMESTAMP' 2015-10-01 00:00:00'                                                                                          09/22/2016 19:31:59

           9 SYS_P1186673                          39591670        39591670           39208 TIMESTAMP' 2015-11-01 00:00:00'                                                                                          09/22/2016 19:32:10

          10 SYS_P1265684                          32391927        32391927           29456 TIMESTAMP' 2015-12-01 00:00:00'                                                                                          09/22/2016 19:32:19

          11 SYS_P1340470                          34716827        34716827           32608 TIMESTAMP' 2016-01-01 00:00:00'                                                                                          09/22/2016 19:32:31

          12 SYS_P1388682                          39997458        39997458           40056 TIMESTAMP' 2016-02-01 00:00:00'                                                                                          09/22/2016 19:32:42

          13 SYS_P1433080                          40138343        40138343           39488 TIMESTAMP' 2016-03-01 00:00:00'                                                                                          09/22/2016 19:32:53

          14 SYS_P1480473                          42412720        42412720           41248 TIMESTAMP' 2016-04-01 00:00:00'                                                                                          09/22/2016 19:33:05

          15 SYS_P1531264                          41607977        41607977           40736 TIMESTAMP' 2016-05-01 00:00:00'                                                                                          09/22/2016 19:33:16

          16 SYS_P1574276                          40811459        40811459           40080 TIMESTAMP' 2016-06-01 00:00:00'                                                                                          09/22/2016 19:33:27

          17 SYS_P1619633                          42935485        42935485           42408 TIMESTAMP' 2016-07-01 00:00:00'                                                                                          09/22/2016 19:33:39

          18 SYS_P1665727                          41300996        41300996           41128 TIMESTAMP' 2016-08-01 00:00:00'                                                                                          09/22/2016 19:33:58

          19 SYS_P1715065                          46290708        46290708           45616 TIMESTAMP' 2016-09-01 00:00:00'                                                                                          09/22/2016 19:34:12

          20 SYS_P1765027                          44209306        44209306           44864 TIMESTAMP' 2016-10-01 00:00:00'                                                                                          10/16/2016 08:37:33

          21 SYS_P1814453                          46319442        46319442           49400 TIMESTAMP' 2016-11-01 00:00:00'                                                                                          11/06/2016 06:09:20

          22 SYS_P1884838                          46782453        46782453           48160 TIMESTAMP' 2016-12-01 00:00:00'                                                                                          12/04/2016 07:08:23

          23 SYS_P1941375                          49778327        49778327           50208 TIMESTAMP' 2017-01-01 00:00:00'                                                                                          01/01/2017 05:40:21

          24 SYS_P1987976                          47734893        47734893          447344 TIMESTAMP' 2017-02-01 00:00:00'                                                                                          02/01/2017 14:00:53

          25 SYS_P2033672                          41766799        41766799          388521 TIMESTAMP' 2017-03-01 00:00:00'                                                                                          02/28/2017 14:03:32

          26 SYS_P2073160                   .               .               .               TIMESTAMP' 2017-04-01 00:00:00'                                                                                          .

      Elapsed: 00:00:00.16

       

       

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

        COLUMN STATISTICS

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

      Name                          Analyzed             Null?  NDV           Density  # Nulls     # Buckets   Sample      AvgLen  Lo-Hi Values

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

      checksum_proc_status           02/01/2017 13:56:09  N      166166528     .000000  0           1        849474791   7     3 | 4294967230

      clearing_party_id              02/01/2017 13:56:09  Y      0             .000000  849474791   0          0              |

      clearing_party_id_sch          02/01/2017 13:56:09  Y      0             .000000  849474791   0          0              |

      clearing_system_type           02/01/2017 13:56:09  Y      2             .000003  849317707   2        6920           2          CCILMUM | MKS

      dt_load                        02/01/2017 13:56:09  N      719744        .000001  0           1        849474791   11    UNKNOWN DATATYPE

      dt_load_trade_version          02/01/2017 13:56:09  N      719744        .000001  0           1        849474791   11    UNKNOWN DATATYPE

      seq_proc_status                02/01/2017 13:56:09  N      325681152     .000001  0           254      20984       6     -1 | 1418836207

      sk_status_duration             02/01/2017 13:56:09  N      1             .000000  0           1        20984       3     1 | 1

      sk_status_typo                 02/01/2017 13:56:09  N      79            .000000  0           36       20985       4     1 | 1221

      sk_trade_status                02/01/2017 13:56:09  N      849474791     .000000  0           1        849474791   7     1 | 1675688151

      sk_trade_version               02/01/2017 13:56:09  N      805240832     .000000  0           1        849474791   7     1 | 1556212297

      status_end_timestamp           02/01/2017 13:56:09  Y      0             .000000  849474791   0          1             UNKNOWN DATATYPE

      status_media_type              02/01/2017 13:56:09  Y      19780         .000226  849349200   254      5467           2          00000101 | 00713502

      status_receiver_party_id       02/01/2017 13:56:09  Y      1             .000004  849349200   1        5467           2          Party | Party

      status_receiver_party_id_sch   02/01/2017 13:56:09  Y      2             .000004  849349200   2        5468           2          0.000000000000000 | 0.959500000000000

      status_sender_party_id         02/01/2017 13:56:09  Y      1             .000004  849349200   1        5467           2          PTS | PTS

      status_sender_party_id_sc      02/01/2017 13:56:09  Y      1             .000004  849349200   1        5467           2          Other | Other

      status_start_timestamp         02/01/2017 13:56:09  Y      478           .002208  849447077   254      5542           2          UNKNOWN DATATYPE

      status_timestamp               02/01/2017 13:56:09  Y      8451072       .000002  723473206   254      8833           3          UNKNOWN DATATYPE

       

      Index Name                      BLevel       Leaf Blks          # Rows   Distinct Keys Avg Lf/Blks/Key Avg Dt/Blks/Key Clustering Factor     Sample Size Uniq? Type     Status   Deg Part? Vis? Last Analyzed

      ------------------------------ ------- --------------- --------------- --------------- --------------- --------------- ----------------- --------------- ----- -------- -------- --- ----- ---- -------------------

      OTC_DAT_TV_PROC_STATUS_IX1           2           23018          726577          719744               1               1            726577           36459 NO    BITM     N/A      1   YES   .    02/01/2017 14:00:38

      OTC_DAT_TV_PROC_STATUS_PK            2         2532878       845757696       845757696               1               1         187638614          374315 YES   NORM     N/A      1   YES   .    02/01/2017 14:00:04

      OTC_DAT_TV_PROC_STATUS_UK            2         3580793       853618729       853618729               1               1         275078004          270809 YES   NORM     N/A      1   YES   .    02/01/2017 14:00:32

      Elapsed: 00:00:00.04

       

       

      Index Name                           Pos# Order Column Name

      ------------------------------ ---------- ----- ------------------------------

      otc_dat_tv_proc_status_ix1              1 ASC   dt_load

       

      OTC_DAT_TV_PROC_STATUS_PK               1 ASC   sk_trade_status

       

      otc_dat_tv_proc_status_uk               1 ASC   sk_trade_version

                                              2 ASC   checksum_proc_status

        • 1. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
          ddf_dba

          Your plan format does us little, if any, good.  Post the output from

           

          select * From table(dbms_xplan.display_cursor());

           

          to provide a formatted version with the proper details.  You also need to see what else is executing on the node at the time these inserts slow down, as well as what may be running from node 1 (such as database backups, etc.).  You have provided a lot of  information but without a properly formatted execution plan no one can help you decipher this problem.

           

           

          David Fitzjarrell

          • 2. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
            Ahmed AANGOUR

            Here is the executiion plan

            Plan hash value: 328905351

             

             

            ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------

            | Id  | Operation                                        | Name                       | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |

            ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------

            |   0 | INSERT STATEMENT                                 |                            |       |       |   235K(100)|          |       |       |        |      |            |

            |   1 |  LOAD TABLE CONVENTIONAL                         |                            |       |       |            |          |       |       |        |      |            |

            |   2 |   SEQUENCE                                       | OTC_DAT_TV_PROC_STATUS_SEQ |       |       |            |          |       |       |        |      |            |

            |   3 |    PX COORDINATOR                                |                            |       |       |            |          |       |       |        |      |            |

            |   4 |     PX SEND QC (RANDOM)                          | :TQ10007                   |     1 |  6523 |   235K  (2)| 00:47:06 |       |       |  Q1,07 | P->S | QC (RAND)  |

            |   5 |      HASH JOIN                                   |                            |     1 |  6523 |   235K  (2)| 00:47:06 |       |       |  Q1,07 | PCWP |            |

            |   6 |       PX RECEIVE                                 |                            |     1 |  6481 | 78212   (1)| 00:15:39 |       |       |  Q1,07 | PCWP |            |

            |   7 |        PX SEND BROADCAST                         | :TQ10006                   |     1 |  6481 | 78212   (1)| 00:15:39 |       |       |  Q1,06 | P->P | BROADCAST  |

            |   8 |         HASH JOIN                                |                            |     1 |  6481 | 78212   (1)| 00:15:39 |       |       |  Q1,06 | PCWP |            |

            |   9 |          PX RECEIVE                              |                            |     1 |  6307 | 14734   (1)| 00:02:57 |       |       |  Q1,06 | PCWP |            |

            |  10 |           PX SEND BROADCAST                      | :TQ10005                   |     1 |  6307 | 14734   (1)| 00:02:57 |       |       |  Q1,05 | P->P | BROADCAST  |

            |  11 |            HASH JOIN BUFFERED                    |                            |     1 |  6307 | 14734   (1)| 00:02:57 |       |       |  Q1,05 | PCWP |            |

            |  12 |             PX RECEIVE                           |                            |     1 |  6270 | 14732   (1)| 00:02:57 |       |       |  Q1,05 | PCWP |            |

            |  13 |              PX SEND HASH                        | :TQ10003                   |     1 |  6270 | 14732   (1)| 00:02:57 |       |       |  Q1,03 | P->P | HASH       |

            |  14 |               HASH JOIN                          |                            |     1 |  6270 | 14732   (1)| 00:02:57 |       |       |  Q1,03 | PCWP |            |

            |  15 |                HASH JOIN                         |                            |     1 |  6261 | 14730   (1)| 00:02:57 |       |       |  Q1,03 | PCWP |            |

            |  16 |                 PX RECEIVE                       |                            |  2654 | 34502 |  7366   (1)| 00:01:29 |       |       |  Q1,03 | PCWP |            |

            |  17 |                  PX SEND BROADCAST               | :TQ10001                   |  2654 | 34502 |  7366   (1)| 00:01:29 |       |       |  Q1,01 | P->P | BROADCAST  |

            |  18 |                   VIEW                           |                            |  2654 | 34502 |  7366   (1)| 00:01:29 |       |       |  Q1,01 | PCWP |            |

            |  19 |                    SORT GROUP BY                 |                            |  2654 |   168K|  7366   (1)| 00:01:29 |       |       |  Q1,01 | PCWP |            |

            |  20 |                     PX RECEIVE                   |                            |  2654 |   168K|  7366   (1)| 00:01:29 |       |       |  Q1,01 | PCWP |            |

            |  21 |                      PX SEND HASH                | :TQ10000                   |  2654 |   168K|  7366   (1)| 00:01:29 |       |       |  Q1,00 | P->P | HASH       |

            |  22 |                       SORT GROUP BY              |                            |  2654 |   168K|  7366   (1)| 00:01:29 |       |       |  Q1,00 | PCWP |            |

            |  23 |                        PX BLOCK ITERATOR         |                            |  2654 |   168K|  7365   (1)| 00:01:29 |   KEY |   KEY |  Q1,00 | PCWC |            |

            |  24 |                         TABLE ACCESS STORAGE FULL| OTC_DAT_TV_PROC_STATUS     |  2654 |   168K|  7365   (1)| 00:01:29 |   KEY |   KEY |  Q1,00 | PCWP |            |

            |  25 |                 PX BLOCK ITERATOR                |                            |  2654 |    15M|  7365   (1)| 00:01:29 |   KEY |   KEY |  Q1,03 | PCWC |            |

            |  26 |                  TABLE ACCESS STORAGE FULL       | OTC_DAT_TV_PROC_STATUS     |  2654 |    15M|  7365   (1)| 00:01:29 |   KEY |   KEY |  Q1,03 | PCWP |            |

            |  27 |                BUFFER SORT                       |                            |       |       |            |          |       |       |  Q1,03 | PCWC |            |

            |  28 |                 PX RECEIVE                       |                            |     1 |     9 |     2   (0)| 00:00:01 |       |       |  Q1,03 | PCWP |            |

            |  29 |                  PX SEND BROADCAST               | :TQ10002                   |     1 |     9 |     2   (0)| 00:00:01 |       |       |  Q1,02 | P->P | BROADCAST  |

            |  30 |                   PX BLOCK ITERATOR              |                            |     1 |     9 |     2   (0)| 00:00:01 |       |       |  Q1,02 | PCWC |            |

            |  31 |                    TABLE ACCESS STORAGE FULL     | REF_DAT_STATUS_DURATION    |     1 |     9 |     2   (0)| 00:00:01 |       |       |  Q1,02 | PCWP |            |

            |  32 |             PX RECEIVE                           |                            |   101 |  3737 |     2   (0)| 00:00:01 |       |       |  Q1,05 | PCWP |            |

            |  33 |              PX SEND HASH                        | :TQ10004                   |   101 |  3737 |     2   (0)| 00:00:01 |       |       |  Q1,04 | P->P | HASH       |

            |  34 |               PX BLOCK ITERATOR                  |                            |   101 |  3737 |     2   (0)| 00:00:01 |       |       |  Q1,04 | PCWC |            |

            |  35 |                TABLE ACCESS STORAGE FULL         | REF_DAT_STATUS_TYPOLOGY    |   101 |  3737 |     2   (0)| 00:00:01 |       |       |  Q1,04 | PCWP |            |

            |  36 |          PX BLOCK ITERATOR                       |                            |  3075 |   522K| 63477   (1)| 00:12:42 |   KEY |   KEY |  Q1,06 | PCWC |            |

            |  37 |           TABLE ACCESS STORAGE FULL              | OTC_DAT_TRADE_VERSION      |  3075 |   522K| 63477   (1)| 00:12:42 |   KEY |   KEY |  Q1,06 | PCWP |            |

            |  38 |       PX BLOCK ITERATOR                          |                            |   848M|    33G|   156K  (3)| 00:31:23 |     1 |1048575|  Q1,07 | PCWC |            |

            |  39 |        TABLE ACCESS STORAGE FULL                 | OTC_DAT_TRADE_VERSION      |   848M|    33G|   156K  (3)| 00:31:23 |     1 |1048575|  Q1,07 | PCWP |            |

            ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------

             

             

            Note

            -----

               - dynamic sampling used for this statement (level=5)

               - automatic DOP: Computed Degree of Parallelism is 8

            • 3. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
              Andrew Sayer

              It's strange (IMO wrong) that you've looked at p1text in one query and then the actual p values in another but without seeing what they relate to.

               

              You should be looking at event, then use p1,p2 and p3 to see the specifics about that event - their meanings change for each event so be sure to look them up or also pull through p1text p2text etc to see what the values mean.

              • 4. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
                Jonathan Lewis

                If you take note of the ignore_row_on_dupkey_index() hint then the obvious guess is that the slow runs appear when you have a data error and are trying to insert lots of rows that fail the uniqueness constraint.

                 

                I had to look up (in v$event_name) the event that has "cache id" as their parameter1 - it's "row cache lock" and "row cache read". That helps to confirm the guess - every time you get a duplicate row Oracle has to rollback the row and go through the work of reporting the constraint, and that's consistent with those two waits.

                 

                Regards

                Jonathan Lewis

                • 5. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
                  Ahmed AANGOUR

                  Jonathan you are amazing.

                  Every thing is clear for me now. Indeed, when the problem occured the first time I tested the select part of the query and I noticed that it returned twice the number of rows.

                  I am sure that when the problem does not occur the SELECT must return a number of rows close to the number of rows inserted.

                  I am not at the office right now so I will validate this on monday but i'm sure you have pointed out the root cause of my problem.

                  I will post a message in this discussion to confirm that.

                  Many many thanks Jonathan for having answered me.

                  • 6. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
                    Ahmed AANGOUR

                    Hi Jonathan,

                     

                    I have been told that the problem occured again last night but this time the production team have traced the session during the insert (10046 tracefile).

                    The query took 3h to complete. The tracing have been enabled during 20min for the QC session.

                    I have generated a OraSRP report.  what is surprising is to see 0 rollbacks and 92% for "unaccounted for time"

                     

                    Session Summary

                    Instance Name: I2RP012

                    Node Name: dbmprd1db02-adm.fr.world.socgen

                    Oracle Release: 11.2.0.4.0

                    Session ID: 2088.43357

                    Total SQL Statements: 22 (3 user statements, 19 internal statements)

                    Total Transactions: 0 (0 rollback(s), 0 read-only)

                     

                     

                    Event Name

                    % Time Seconds Calls - Time per Call -
                    Avg Min Max
                    unaccounted-for time 92.0% 1,082.6993s            
                    cell single block physical read 3.0%  35.3608s 26,647 0.0013s 0.0000s 0.1563s
                    PX Deq: Execute Reply 2.1%  25.1553s 2,266 0.0111s 0.0000s 9.4171s
                    EXEC calls [CPU] 1.3%  14.8427s 115,625 0.0001s 0.0000s 0.0290s
                    row cache lock 0.7%  8.1333s 6,467 0.0013s 0.0000s 0.3605s
                    FETCH calls [CPU] 0.4%  4.7333s 108,817 0.0000s 0.0000s 0.0190s
                    PARSE calls [CPU] 0.4%  4.5264s 108,696 0.0000s 0.0000s 0.0270s
                    gc current grant 2-way 0.0%  0.2792s 716 0.0004s 0.0000s 0.0206s
                    enq: SQ - contention 0.0%  0.2171s 64 0.0034s 0.0000s 0.1619s
                    latch free 0.0%  0.2018s 110 0.0018s 0.0000s 0.0129s
                    buffer busy waits 0.0%  0.1561s 356 0.0004s 0.0000s 0.0163s
                    latch: redo allocation 0.0%  0.1561s 62 0.0025s 0.0000s 0.0124s
                    library cache pin 0.0%  0.1558s 269 0.0006s 0.0000s 0.0110s
                    PX Deq: Parse Reply 0.0%  0.1429s 16 0.0089s 0.0000s 0.1413s
                    log file switch completion 0.0%  0.0888s 4 0.0222s 0.0136s 0.0315s
                    enq: PS - contention 0.0%  0.0525s 10 0.0052s 0.0001s 0.0504s
                    latch: row cache objects 0.0%  0.0505s 26 0.0019s 0.0000s 0.0120s
                    cell multiblock physical read 0.0%  0.0454s 14 0.0032s 0.0004s 0.0306s
                    gc current block 2-way 0.0%  0.0329s 219 0.0002s 0.0001s 0.0035s
                    enq: KO - fast object checkpoint 0.0%  0.0321s 3 0.0107s 0.0001s 0.0318s
                    enq: FB - contention 0.0%  0.0260s 41 0.0006s 0.0001s 0.0079s
                    gc current block 3-way 0.0%  0.0178s 50 0.0004s 0.0001s 0.0037s
                    latch: object queue header operation 0.0%  0.0131s 3 0.0044s 0.0001s 0.0130s
                    PX Deq: Join ACK 0.0%  0.0121s 16 0.0008s 0.0000s 0.0088s
                    gc cr multi block request 0.0%  0.0109s 12 0.0009s 0.0001s 0.0078s
                    cursor: pin S 0.0%  0.0104s 1 0.0104s 0.0104s 0.0104s
                    latch: messages 0.0%  0.0099s 1 0.0099s 0.0099s 0.0099s
                    latch: cache buffers chains 0.0%  0.0070s 7 0.0010s 0.0000s 0.0029s
                    latch: ges resource hash list 0.0%  0.0065s 4 0.0016s 0.0001s 0.0047s
                    gc cr grant 2-way 0.0%  0.0065s 42 0.0002s 0.0000s 0.0021s

                     

                    I have generated 2 AWR report of 1hour each. One report when the query was running and another one when it was not running but still with a lot of activity in the DB.

                    The USER ROLLBACKS statistic in the AWR shows that there was 2.43 rollback by second when the query was running (total=8763 ) and only 0.21 per second when the query was not running (total=759).

                    Another info: the DB CPU(s) is at 28 during the night , and the number of cores available is 16.

                    • 7. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
                      Jonathan Lewis

                      Zero rollbacks is not a surprise - your insert is not rolling back any statements. You may find, though, that the statistic  (from Instance Activity) "rollback changes - undo records applied" is (much) larger than normal.

                       

                      The 92.8% unaccounted means one of 2 things: orasrp may be out of date with respect to the current version of Oracle and therefore reporting incorrectly, or there may be some uninstrumented wait events in this part of the code - there probably aren't a lot of people using the "ignore dup key" feature at present so you may,  in effect, be an early user-acceptance tester uncovering the bugs.

                       

                      It's worth noting that you're running parallel - so you really need the PX slave trace files as well to get the full picture; and you need to check that the trace file shows the same plan as the one you've previously reported (that's just a cautionary point, looking as the "PX Deq: Execute reply" waits I don't think anything significantly different is likely to have happened). The detail I do note is that the ASH data indicated (by sampling) lots of time on "row cache lock/read", while this report shows very little time on those two.  This may be corroborating the "uninstrumented" wait - viz: the "row cache lock/read" changes to something different but the session information is not modified correctly, leaving ASH able to sample and find the wrong description.

                       

                      In your case I would look at the raw trace file, extracting the tim= values and looking for the "big" jumps to see what happened just before and just after as that might give you a clue to what's going wrong.

                       

                      Regards

                      Jonathan Lewis

                      • 8. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
                        Ahmed AANGOUR

                        Hi Jonathan,

                         

                        1) Christian Antognini says in his book that UNACCOUNTED-FOR TIME can be due to CPU starvation. Since the different AWR reports are showing that the DB CPU(s) is at 28 all night long and that we have only 16 cores available in the DB node, I thought that CPU waits could be an explaination of the high percentage of UNACCOUNTED-FOR TIME. What do you think?

                         

                        2) I had a discussion yesterday with Mohamed Houri and he told me as well that I should indeed look at "rollback changes - undo records applied" instead of "user rollbacks", so I asked the PROD guy to send me these statistics and I was surprised to see that the "rollback changes - undo records applied" are lower between 00h and 1h (the query was running from 23h41 until 2h46) than between 3h and 4h (when the insert was not running):

                        -- 0h/1h

                        leaf node 90-10 splits                  221,568        61.51      4.16

                        leaf node splits                        422,338        117.25    7.93

                        rollback changes - undo records applied        1,155,990    320.92    21.71

                        rollbacks only - consistent read gets          257,247        71.42      4.83

                         

                        -- 3h/4h

                        leaf node 90-10 splits                  200,988        55.93      6.24

                        leaf node splits                        419,575        116.76        13.02

                        rollback changes - undo records applied    7,767,958      2,161.73  241.00

                        rollbacks only - consistent read gets          528,990        147.21    16.41

                         

                        3) You're right to say that indeed there is no PX slave traces but the ASH shows that most of the time is spending on the INSERT part that is not running in parallel. 80% of the rows in DBA_HIST_ACTIVE_SESS_HISTORY  corresponding to the execution of the query have the SESSION_ID equal to 2088 which is the QC session ID.

                         

                        4) I have noticed something bizarre too: for the execution of the query that ran from 23h41 to 2h46 I find 8 different SQL_EXEC_ID. I thought that there can be only one SQL_EXEC_ID by execution:

                        select ash.SQL_EXEC_START,sql_exec_id, count(*) as "NB" from DBA_HIST_active_sess_history  ash

                        where sample_time  >  to_timestamp('2017-03-03 23:41:56.000','YYYY-MM-DD HH24:MI:SSXFF')

                        AND sample_time <= to_timestamp('2017-03-04 02:56:13.000','YYYY-MM-DD HH24:MI:SSXFF')

                        and sql_id='6y6yg646zr315'

                        and (QC_SESSION_ID = 2088 or session_ID=2088)

                        group by SQL_EXEC_START,sql_exec_id

                        order by 1;

                         

                        "SQL_EXEC_START"        "SQL_EXEC_ID"         "NB"

                        2017-03-03 23:41:55        33557504            241

                        2017-03-04 00:15:50        33557534            222

                        2017-03-04 00:45:28        33557558            175

                        2017-03-04 01:09:27        33557578            82

                        2017-03-04 01:20:38        33557590            73

                        2017-03-04 01:28:58        33557598            59

                        2017-03-04 01:34:32        33557604            10

                        2017-03-04 01:35:04        33557607            500

                         

                        5) I am not able right now to run a TKPROF report to see if I would find the 98% of the UNACCOUNTED-FOR TIME. I will run it tomorrow.

                        • 9. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
                          Jonathan Lewis

                          1) Do the arithmetic - to get 92% unaccounted for from CPU starvation it means that for every 8 seconds you used CPU you were waiting 92 seconds, in other words 11.5 seconds in the CPU queue for 1 second usage - your "DB CPU usage per second" (which I assume is quoted from the summary stats - it would be better to show the section of the report than force people to guess which number you were quoting) would have to be in the ballpark of 180, not 28.

                           

                          2) Telling us about 4 numbers from a completely different hour when YOUR insert wasn't running doesn't tell us anything about whether it's a reasonable comparison. As it is you might note that you've shown us that the other hour shows a similar number of leaf node splits (which could well indicate a similar volume of inserts) and a similar number of 90/10 leaf node split which is, nevertheless differs by about 20,000 rather than the 3,000 difference in the leaf node splits total - which means fewer "high value" insertions which suggests fewer sequence or time-based inserts.  Without knowing what you're doing (or at least seeing lots of other statistics and guessing) we can't say anything about the difference in undo records applied: you haven't even shown us the corresponding numbers for user rollbacks and transaction rollbacks.

                           

                          3) The reason why you should look for, or at, the PX trace files is because the trace file you've shown is NOT CONSISTENT with the original results - so you need to know whether or not this run is behaving the same way as the original you reported; AND you need to check that the QC trace is consistent with the PX traces because part of the problem could (if we do some imaginative thinking) be time reported in the wrong trace file.  Maxim: "When you don't know what's wrong don't assume that Oracle is telling you the truth, the whole truth and nothing but the truth."

                           

                          4) The sorts of questions you have to ask yourself are these: (a) could the driving mechanism have some code in it that caused it to restart, (b) could a PX slave possibly get a different SQL_EXEC_ID from the QC, (c) would I get some insight by aggregating by session_id and sql_exec_id

                           

                          5) I didn't say run a tkprof, I said look at the trace file.

                           

                          Regards

                          Jonathan Lewis

                           

                           

                          P.S.  I've just had a quick look at the trace file you emailed me.

                           

                          First point little detail I noted - your sequence has a cache size of 20 (you were running at level 12, so I could read the binds for the update seq$ statement), and Oracle ran the update roughly 6,800 time (136,000 attempted insertions); and the call to check constraint definitions appeared roughly 108,000 times for the same (index-based) constraint  - that's the failure count for duplicate key. You spent far more time failing inserts than you did succeeding.  I haven't tried looking for the unaccounted time yet.

                          • 10. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
                            Jonathan Lewis

                            Follow-up on the trace file:

                             

                            By extracting the tim= values for closing the cursor that checks the constraint name and the close of the cursor that updates seq$, and thanks to a little bit of luck (and a lot of failures and the fact that your sequence cache size is 20) it looks like 20 successful inserts take approximately 4 milliseconds while 20 consecutive failures takes approximately 200 milliseconds - and if you do the arithmetic that adds up very nicely to your total time:  108,000 * 200 / 20 ms = 1080 seconds, that's most of your lost time.

                             

                            There's very little in the trace file to show the details of the CPU usage in that 200,000 milliseconds beyond the CPU time for the various steps, but since the CPU usage is only recorded on the O/S tick rounded to the millisecond it's possible that there are so many very small operations outside the instrumented that we're losing a lot of time because of granularity effects. I suspect, though, that it's the basic calls that relate to applying undo, generating redo, and mutex spin time across the board.

                             

                            One other thought has crossed my mind regarding failure on duplicate inserts - might we end up doing redundant leaf node splits and could some strange side effects appear when we unwind the duplicated key values.  I'm not going to pursue that idea - but you might tell us how many indexes you have on this table, and what the Instance Activity statistic looks like for "recursive aborts on index block reclamation".

                             

                            Regards

                            Jonathan Lewis

                             

                             

                            ADDENDUM:  For most of the last 20 years I've pointed out that a PL/SQL loop that does row by row inserts from a cursor with an exception to capture duplicate key and do an update instead is likely to be slower than a loop that uses an update and checks for "zero rows updated" and does an insert instead - unless the number of updates that miss would be around 20 times the number inserts that would error. It looks like it's now more like 50 times according to your figures.

                            • 11. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
                              Mohamed Houri

                              Hello Ahmed

                               

                              Although you don't know why this performance penalty kicked off today and not the last couple of weeks where you were still trying to insert duplicate rows, it is probably the  ignore_row_on_dupkey_index() hint which is causing this performance degradation as already pointed out by Jonathan Lewis

                               

                              Why not change this hint by using DML Error logging for which I have not seen yet an issue, like the one you are confronted to, reported somewhere.

                               

                              But bear in mind as well that DML Error logging has several restrictions which I have already gathered in an article you can find in my blog (first google hit using : dml error logging hourim)

                               

                              Best regards

                              Mohamed Houri

                              • 12. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
                                Ahmed AANGOUR

                                Thank you Jonathan and Mohamed for your replies.

                                 

                                We removed yesterday the hint from the query and added a NOT EXISTS clause for not trying to insert rows already present in the table.

                                The result is spectacular: 2 minutes only to insert more than 300k rows against less than 1h in the past and between 3h and 6h since last week.

                                It's sure now that the problem was caused by the hint.

                                Nevertheless, It's a pity that we could not be able to reproduce the issue. I would have liked to get a complete trace (with PX servers traces) to get the whole picture and understand to what the 92% of unaccounted-for time was corresponding to.

                                Many thanks Jonathan, as always I learnt a lot from your posts.

                                • 13. Re: Slow conventional Insert statement consuming a lot of CPU time (Exadata)
                                  Jonathan Lewis

                                  The other benefit of not using the hint (and using a NOT EXISTS) is that the insert can execute in parallel. If you use the "ignore duplicates" hint then the select part can run parallel but the insert part has to be serialised through the QC.

                                   

                                  I can't actually remember if that's true for DML error logging and don't seem to have a test for it in my library - but, off the top of my head, I think it has to be the case for "obvious" reasons.

                                   

                                  Regards

                                  Jonathan Lewis