Re: Huge plain inserts response time bad with db file sequential read wait event.
Date: Fri, 21 Dec 2018 10:39:22 +0000
Message-ID: <CWXP265MB14930C6EA7884714797C4CDFA5B80_at_CWXP265MB1493.GBRP265.PROD.OUTLOOK.COM>
From the snapper output you're db file sequential read times are in the order of 16ms which is clearly a bit slow (I'd expect to see something between 1 and 2 ms) - suggesting that the disks are overloaded. It's not just the PK index, of course - your first set of stats show that you've got at least 2 other indexes on the objects which are affected. When you insert data into a table the number of index leaf blocks you have to update is usually larger (sometime much larger) than the number of table blocks and you often have to find and read the right index leaf block to insert into it whereas inserting "the next row" into a table simply means adding one more row to a block that you've been using in the last few milliseconds. Why the PK index should require more reads than any other index - could simply be related to the definition of the index; perhaps the other two indexes you report are very small (lots of nulls), or are based on columns which are well-ordered relative to the inserts so need only suffer a single read for every couple of dozen inserts.
Apart for the indications of "slow read time" however, there are various clues about CPU overload. As Mark Farnham points out you are doing a lot of work negotiating current grants to data blocks - and some of the blocks you are interested in are busy: the negotiations can burn up CPU. We can also see a lot of waits for library cache locks and pins - you really shouldn't be seeing many of those waits at all - and that's another clue that there's a lot of CPU disappearing (not necessarily in your session) in an over active library cache. Inference - not only might your disks be overloaded, you may be suffering from CPU starvation, which would exaggerate all wait times because "wait" time can include time spent in the CPU queue but unable to use the CPU.
The note about "cpu costing is off" could simply be a bug - I've just run a quick test on 11.2.0.4 for "insert (values)" for a table with object stats, an up to date plan_table, system stats set, and I've just got the same note on the plan. It doesn't matter for "insert (values)" because there is no plan to be costed anyway, and Oracle wouldn't give you a clue about the cost of maintaining all the indexes anyway.
Regards
Jonathan Lewis
From: oracle-l-bounce_at_freelists.org <oracle-l-bounce_at_freelists.org> on behalf of Rakesh Ra <rakeshra.tr_at_gmail.com> Sent: 20 December 2018 17:48
To: oracle-l_at_freelists.org
Subject: Huge plain inserts response time bad with db file sequential read wait event.
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%
--
http://www.freelists.org/webpage/oracle-l
Received on Fri Dec 21 2018 - 11:39:22 CET