Re: Huge plain inserts response time bad with db file sequential read wait event.

  • From: Rakesh Ra <rakeshra.tr@xxxxxxxxx>
  • To: oracle-l@xxxxxxxxxxxxx
  • Date: Thu, 20 Dec 2018 23:18:57 +0530

Forgot to mention the database is of version 11.2.0.4 and a 2 node RAC
system.

Regards,
RRA

On Thu, Dec 20, 2018 at 11:18 PM Rakesh Ra <rakeshra.tr@xxxxxxxxx> wrote:

Hi All,

I have an issue where the below query response time is bad when there is
huge number of concurrent executions.

SQL_ID        SQL_FULLTEXT
                     PARSING_SCHEMA_NAME
-------------
--------------------------------------------------------------------------------
------------------------------
g4cf65js6kjf0 INSERT /*+ RESTRICT_ALL_REF_CONS */ INTO
"DR_CORE09"."ITEM_M                     GGS
              ETADATA_PROPERTY" ("ITEM_METADATA_PROPER
              TY_SID","CREATED_BY","CREATED_DATE","MOD
              IFIED_BY","MODIFIED_DATE","CHANGED","ITE
              M_EXTERNAL_ID","PROPERTY_NAME","PROPERTY
              _TYPE","BOOLEAN_VALUE","INT_VALUE","TIME
              STAMP_VALUE","CUSTOMER_STORAGE_ID","STRI
              NG_VALUE","APP_CREATED_DATE","APP_MODIFI
              ED_DATE","VARCHAR_VALUE","CLOB_VALUE","R
              ESOURCE_STATUS") VALUES (:a0,:a1,:a2,:a3
              ,:a4,:a5,:a6,:a7,:a8,:a9,:a10,:a11,:a12,
              :a13,:a14,:a15,:a16,:a17,:a18)

When I check gv$ash and 10046 trace I see that the query is waiting on db
file sequential read for PK index as below.

EVENT                                SQL_ID        CURRENT_OBJ# MODULE
                           PCT
------------------------------------ ------------- ------------
------------------------------------
------------------------------------------------------------------------
db file sequential read              g4cf65js6kjf0       410319
OGG-R1_825B-OPEN_DATA_SOURCE         33.5%<<<<<<<<<
db file sequential read              gabtdu60mta41       410432
OGG-R1_825B-OPEN_DATA_SOURCE         3.6%
db file sequential read              g4cf65js6kjf0       699497
OGG-R1_825B-OPEN_DATA_SOURCE         2.5%
db file sequential read              g4cf65js6kjf0       410320
OGG-R1_825B-OPEN_DATA_SOURCE         2.3%


Name                                  Null?    Type
------------------------------------- --------
--------------------------------
ITEM_METADATA_PROPERTY_SID            NOT NULL VARCHAR2(32)
CREATED_BY                            NOT NULL VARCHAR2(75 CHAR)
CREATED_DATE                          NOT NULL TIMESTAMP(6)
MODIFIED_BY                           NOT NULL VARCHAR2(75 CHAR)
MODIFIED_DATE                                  TIMESTAMP(6)
CHANGED                               NOT NULL TIMESTAMP(6)
ITEM_EXTERNAL_ID                      NOT NULL VARCHAR2(36 CHAR)
PROPERTY_NAME                         NOT NULL VARCHAR2(500 CHAR)
PROPERTY_TYPE                         NOT NULL NUMBER
BOOLEAN_VALUE                                  NUMBER(1)
INT_VALUE                                      NUMBER
TIMESTAMP_VALUE                                TIMESTAMP(6)
CUSTOMER_STORAGE_ID                   NOT NULL VARCHAR2(32)
STRING_VALUE                                   CLOB
APP_CREATED_DATE                               TIMESTAMP(6)
APP_MODIFIED_DATE                              TIMESTAMP(6)
VARCHAR_VALUE                                  VARCHAR2(1000 CHAR)
CLOB_VALUE                                     CLOB
RESOURCE_STATUS                       NOT NULL VARCHAR2(3 CHAR)

OWNER               OBJECT_ID OBJECT_NAME
------------------ ---------- ---------------------------
DR_CORE09              410319 ITEM_METADATA_PROPERTY_PK<<<<<<<<<<<<

Please note that this query is being executed by the Oracle GoldenGate
replicat process.

I have attached snapper details and below is the execution plan. Also I am
not sure why the CPU costing is off for the plan. This is observed only for
OGG queries. Other application related JDBC queries I see all the plan
table related columns.

PLAN_TABLE_OUTPUT

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  g4cf65js6kjf0, child number 0
-------------------------------------
INSERT /*+ RESTRICT_ALL_REF_CONS */ INTO
"DR_CORE09"."ITEM_METADATA_PROPERTY"
("ITEM_METADATA_PROPERTY_SID","CREATED_BY","CREATED_DATE","MODIFIED_BY",
"MODIFIED_DATE","CHANGED","ITEM_EXTERNAL_ID","PROPERTY_NAME","PROPERTY_T
YPE","BOOLEAN_VALUE","INT_VALUE","TIMESTAMP_VALUE","CUSTOMER_STORAGE_ID"
,"STRING_VALUE","APP_CREATED_DATE","APP_MODIFIED_DATE","VARCHAR_VALUE","
CLOB_VALUE","RESOURCE_STATUS") VALUES
(:a0,:a1,:a2,:a3,:a4,:a5,:a6,:a7,:a8,:a9,:a10,:a11,:a12,:a13,:a14,:a15,:
a16,:a17,:a18)

-----------------------------------------------
| Id  | Operation                | Name | Cost  |
-------------------------------------------------
|   0 | INSERT STATEMENT         |      |     1 |
|   1 |  LOAD TABLE CONVENTIONAL |      |       |
-------------------------------------------------

Note
-----
   - cpu costing is off (consider enabling it)

Can someone guide as to,

a) Why INSERT is spending more time on db file sequential reads for PK
index?
b) Why CPU costing is showing as off in the execution plan for OGG queries
only?

Regards,
RRA

Other related posts: