Re: Insert running long
Date: Fri, 3 Apr 2020 07:39:31 +0000
Message-ID: <LNXP265MB1562A27C7E68B9075F9469C3A5C70_at_LNXP265MB1562.GBRP265.PROD.OUTLOOK.COM>
To calculate disk reads and buffer gets per row are you taking a couple of snapshots a couple of minutes apart and finding the difference; or just looking at the current valuese ?
The figures are very high, but if you've just taken a snapshot it may be because a cursor has been partially flushed and you could be looking at a running total where some stats are since first load and some are only for most recent reloads.
If the numbers are really what's going on there are two main possibilities a) something about the inserts is making Oracle read a lot of undo records for each insert b) there's a lot of leaf-blocks in the index that Oracle thinks are "empty" which turn out to be unusable when Oracle wants to do a leaf block split and find an empty block, and the search is doing a lot of work.
A (delta) snapshot the session stats that's doing a lot inserts would help identify what type of activity those block accesses are about.
The segstat figures look like roughly 4 buffer gets per block change (which looks about right for basic index inserts) and one physical read per block change (which looks like very randomly positioned inserts). The clustering_factor of the index doesn't tell us a great deal, but it is very close to the rowcount, so may be a hint that the inserts are very widely scattered. With only 3.3M distinct keys and 2.5B rows that's an average of 750 rpws per key, so your index is probably running at about 50% space utilisation which may explain the 92GB vs. 70GB (having done lots of 50/50 leaf block splits). What's the avg_col_len and num_nulls of the column, by the way.
What can you tell us about the column that's indexed in terms of what the table represents and what the column means.
Regards
Jonathan Lewis
From: Bhavani Dhulipalla <bhavanidba6_at_gmail.com> Sent: 02 April 2020 22:24
To: Jonathan Lewis
Cc: Oracle L
Subject: Re: Insert running long
Thank you Jonathan - Please find below
So, how many indexes have to be maintained as a row is inserted.
We have 5 indexes on the table and table has 2.6 B rows and it is Paritioned.one index is local and 4 are global and index UM_DWH_NXT.XIF3MEMBER_BANK_BALANCE is Global. Each Index Blevel is 3
Will any (many) of the indexes find that 400 rows inserted turns into 400 different leaf blocks being updated?
I am not sure how to find this but I have put statistics of the Index from the dba_hist_seg_stat below
How many buffer gets per row, disk_reads per row.
From gv$sql , Buffer gets per row is 3131 and disk_reads per row is 198.
Is there any reason why index UM_DWH_NXT.XIF3MEMBER_BANK_BALANCE stands out so much?
I am not sure , this index is 92GB while other indexes are 70GB , all are single column indexes. Below is information about this Index
INDEX_TYPE BLEVEL LEAF_BLOCKS DISTINCT_KEYS CLUSTERING_FACTOR STATUS NUM_ROWS_FROM_TABLE
- ---------- ----------- ------------- ----------------- -------- ---------------
NORMAL 3 11371694 3378432 2216919296 VALID 2643162455 what does v$segstat tell you about the work done on that index in an interval?
dhulipa_at_ebisprd2>select /*+ parallel(8) */ snap_id,LOGICAL_READS_DELTA,DB_BLOCK_CHANGES_DELTA,PHYSICAL_READS_DELTA,PHYSICAL_WRITES_DELTA,
2 SPACE_USED_DELTA,PHYSICAL_READ_REQUESTS_DELTA,PHYSICAL_WRITE_REQUESTS_DELTA 3 from dba_hist_seg_stat
4 where snap_id between 97106 and 97117
5 and OBJ#=215163
6 ORDER BY SNAP_ID 7 /
SNAP_ID LOGICAL_READS_DELTA DB_BLOCK_CHANGES_DELTA PHYSICAL_READS_DELTA PHYSICAL_WRITES_DELTA SPACE_USED_DELTA PHYSICAL_READ_REQUESTS_DELTA PHYSICAL_WRITE_REQUESTS_DELTA
- ------------------- ---------------------- -------------------- --------------------- ---------------- ---------------------------- -----------------------------
97107 101376 28304 32271 17558 3095100 32271 14983 97108 236880 64848 64368 54818 2096742 64368 48919 97109 358400 98240 88657 80712 5438670 88657 69689 97110 394416 108432 95699 93032 5502702 95699 81243 97111 480544 132032 113761 112782 5261164 113761 96141 97112 585520 160768 137968 139199 8704388 137968 116044 97113 714592 196096 166009 164001 8041066 166009 135602 97114 1003936 275968 229062 221835 14961466 229062 173816 97115 1399760 384512 315269 324627 18910386 315269 218620 97116 1755744 482192 394582 399826 24212094 394582 258966 97117 2028272 556176 445315 559226 27080352 445315 448986
On Thu, Apr 2, 2020 at 3:39 PM Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk<mailto:jonathan_at_jlcomp.demon.co.uk>> wrote: 400 rows inserted per call, 1.5 seconds per call. Now you need to decide if that's reasonable or not.
So, how many indexes have to be maintained as a row is inserted. Will any (many) of the indexes find that 400 rows inserted turns into 400 different leaf blocks being updated.
How many buffer gets per row, disk_reads per row.
Is there any reason why index UM_DWH_NXT.XIF3MEMBER_BANK_BALANCE stands out so much - what does v$segstat tell you about the work done on that index in an interval. Does the size of the index look unreasonable large for the number of entries it should hold .... etc.
Regards
Jonathan Lewis
From: Bhavani Dhulipalla <bhavanidba6_at_gmail.com<mailto:bhavanidba6_at_gmail.com>> Sent: 02 April 2020 18:43
To: Jonathan Lewis
Cc: oracle-l_at_freelists.org<mailto:oracle-l_at_freelists.org> Subject: Re: Insert running long
Hi Jonathan
it seems like 400 is the array size and I see that query got executed many more times today than previous . Each execution is taking 1.5 sec avg
bdhulipa_at_ebisprd2>select 21984327/54964 from dual;399.976839
bdhulipa_at_ebisprd2>select 3769805/9425 from dual; 399.97931
select trunc(cast(BEGIN_INTERVAL_TIME as date)),sum(executions_delta)
from
dba_hist_snapshot sn
, dba_hist_sqlstat st
WHERE
sn.snap_id = st.snap_id
AND sn.dbid = st.dbid
AND sn.instance_number = st.instance_number
AND sql_id = 'aqs7g5aj9s44d'
GROUP BY
trunc(cast(BEGIN_INTERVAL_TIME as date))
order by 1
/Date SUM(EXECUTIONS_DELTA)
------------------ --------------------- 03-MAR-20 00:00:00 10367 04-MAR-20 00:00:00 10479 05-MAR-20 00:00:00 10461 06-MAR-20 00:00:00 10434 07-MAR-20 00:00:00 10418 10-MAR-20 00:00:00 10405 11-MAR-20 00:00:00 10379 12-MAR-20 00:00:00 10294 13-MAR-20 00:00:00 10280 14-MAR-20 00:00:00 10307 17-MAR-20 00:00:00 10354 18-MAR-20 00:00:00 10400 19-MAR-20 00:00:00 10429 20-MAR-20 00:00:00 10481 21-MAR-20 00:00:00 10541 24-MAR-20 00:00:00 10606 25-MAR-20 00:00:00 10640 26-MAR-20 00:00:00 10643 27-MAR-20 00:00:00 10674 28-MAR-20 00:00:00 10717 31-MAR-20 00:00:00 10807
01-APR-20 00:00:00 10862
02-APR-20 00:00:00 10964 [image.png]
On Thu, Apr 2, 2020 at 1:17 PM Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk<mailto:jonathan_at_jlcomp.demon.co.uk><mailto:jonathan_at_jlcomp.demon.co.uk<mailto:jonathan_at_jlcomp.demon.co.uk>>> wrote:
If you want to check whether that statement is using single row processing or array processing then select executions, and rows_processed from v$sql for the SQL_ID. Do it a couple of times over a few minutes and the deltas should allow you to work out the arraysize (with a little error, possibly).
Regards
Jonathan Lewis
From: oracle-l-bounce_at_freelists.org<mailto:oracle-l-bounce_at_freelists.org><mailto:oracle-l-bounce_at_freelists.org<mailto:oracle-l-bounce_at_freelists.org>> <oracle-l-bounce_at_freelists.org<mailto:oracle-l-bounce_at_freelists.org><mailto:oracle-l-bounce_at_freelists.org<mailto:oracle-l-bounce_at_freelists.org>>> on behalf of Bhavani Dhulipalla <bhavanidba6_at_gmail.com<mailto:bhavanidba6_at_gmail.com><mailto:bhavanidba6_at_gmail.com<mailto:bhavanidba6_at_gmail.com>>> Sent: 02 April 2020 18:04
To: oracle-l_at_freelists.org<mailto:oracle-l_at_freelists.org><mailto:oracle-l_at_freelists.org<mailto:oracle-l_at_freelists.org>> Subject: Insert running long
Hello
DB Version 11.2.0.4 OS Linux
one of the insert process is running from 6 hours today and getting executed so many times - Each Execution is roughly taking a sec -
its plain insert -I suspect it is is being done in pl/sql loop row by row processing -
How can I validate it ? ask for the pl/sql procedure and check the code -
this is the insert query -
INSERT INTO MEMBER_BANK_BAL(MEMBER_BANK_BAL_ID,MEM BER_BANK_ID,INTERNAL_ACCT_ID,MEMBER_BANK_BAL_AMT,A CCRUED_INT_AMT,FROM_DT,TO_DT,CREATE_TS,LAST_UPDT_T S,RT_RECRD_NUM,RT_TIER_BAL,BATCH_JOB_EXECUTION_ID) VALUES ( :1, :2, :3, :4, :5, :6, :7, :8, :9, :10 , :11, :12)
Wait events:
bdhulipa_at_ebisprd2>@ash/ashtop event2 sql_id='aqs7g5aj9s44d' sysdate-4/24 sysdate
Total Distinct
Seconds AAS %This EVENT2 FIRST_SEEN LAST_SEEN Execs Seen
- ------- ------- ------------------------------------------ ------------------- ------------------- ----------
14192 1.0 99% | db file sequential read 2020-04-02 04:40:04 2020-04-02 08:40:03 6352
149 .0 1% | ON CPU 2020-04-02 04:41:51 2020-04-02 08:39:30 149 2 .0 0% | enq: FB - contention [mode=6] 2020-04-02 04:51:41 2020-04-02 07:34:04 2
2 .0 0% | gc current multi block request 2020-04-02 08:15:22 2020-04-02 08:15:29 2
1 .0 0% | gc current block 2-way 2020-04-02 07:44:19 2020-04-02 07:44:19 1
1 .0 0% | gc current grant 2-way 2020-04-02 06:32:56 2020-04-02 06:32:56 1
1 .0 0% | local write wait 2020-04-02 08:37:47 2020-04-02 08:37:47 1
It seems like db file sequential reads are generating from Index
bdhulipa_at_ebisprd2>@ash/ashtop objt "sql_id='aqs7g5aj9s44d' and event2='db file sequential read'" sysdate-4/24 sysdate
Total Distinct
Seconds AAS %This OBJT FIRST_SEEN LAST_SEEN Execs Seen
- ------- ------- -------------------------------------------------- ------------------- ------------------- ----------
13854 1.0 100% | UM_DWH_NXT.XIF3MEMBER_BANK_BALANCE [INDEX] 2020-04-02 05:24:16 2020-04-02 09:19:46 8054 4 .0 0% | UM_DWH_NXT.XIF5MEMBER_BANK_BALANCE [INDEX] 2020-04-02 06:22:53 2020-04-02 07:06:51 4 3 .0 0% | UM_DWH_NXT.XPKMEMBER_BANK_BALANCE [INDEX] 2020-04-02 07:12:04 2020-04-02 07:26:29 3 Thanks
Bhavani
-- http://www.freelists.org/webpage/oracle-l -- http://www.freelists.org/webpage/oracle-lReceived on Fri Apr 03 2020 - 09:39:31 CEST