Re: High number of created consistent read blocks when inserting into a LOB column from dblink
Date: Wed, 21 Dec 2016 19:31:33 +0000
Message-ID: <MMXP123MB09112B076654F7A3B918CEC7A5930_at_MMXP123MB0911.GBRP123.PROD.OUTLOOK.COM>
I have some notes about remote CLOBs and securefiles with a comment about the number of "messages" used to transfer data.
The most significant comment, perhaps, is that the message size was 8KB - which means the code may be allocating and then extending the LOB 8KB at a time; this could lead to the persistent read-consistency check and update of the current LOB mapping area as a single LOB is processed.
You could investigate this idea by make all your LOBs the same size - starting with something like 6KB, then repeating the test with a larger LOB size (e.g. 32KB), then a much larger size (e.g. 256KB) and checking to see if the transaction and CR stats and seem to be related to the size of the LOBs.
Regards
Jonathan Lewis
From: oracle-l-bounce_at_freelists.org <oracle-l-bounce_at_freelists.org> on behalf of Jure Bratina <jure.bratina_at_gmail.com> Sent: 21 December 2016 17:01:55
To: ORACLE-L
Subject: High number of created consistent read blocks when inserting into a LOB column from dblink
Hi,
I'm experiencing a high number of consistent gets when reading data from a dblink and inserting it into a local table with a LOB column, and thought to ask if anyone else has experienced that or has any comment about that behaviour. I'm on 12.1.0.2 Linux x86-64. There are actually some bugs reported with similar, but not same, symptoms (e.g. "Bug 20555404 : INSERT VIA DBLINK SLOW AFTER UPGRADE TO 11.2.0.4" or "Bug 13641076 : HIGH AMOUNT OF BUFFER GETS FOR INSERT STATEMENT - REJECTION LIST DOES NOT FIRE"), however not for 12.1.
Brief description: When performing an "insert /*+append*/ into .. select from table_at_dblink" and data insertion progresses, the CPU usage of the session gradually increases to 90% of the session's activity, as does the number of consistent reads, particularly the statistic "CR blocks created" (7,36k/second) and, by a similar figure, the statistic "consistent gets examination". Interestingly there's no change in "data blocks consistent reads - undo records applied". So it seems the session is consuming most of its time creating consistent read copies of blocks by reading and applying undo blocks. What's also interesting is "transaction rollbacks" is approx 1/second. There's also a sustainable number of gets on the "lob segment dispenser latch" latch and quite some undo generated (more details below), even though I'm doing a direct path insert. Checking some of UNDO blocks' dump, the content is mostly about space management of LOB chunks, e.g.:
KTSL - LOB Persistent Undo Block (PUB) undo record:
bdba: 0x0180168b class: 10
KTSL - PUA redo record:
1: On disk rollback of 1 chunks
On disk rollback: mark chunk free: 0x18f110b
Also, the object in v$bh that has the most blocks in 'cr' mode is the LOB segment (not LOB index).
Problem reproduction, using the default USERS tablespace (locally managed, ASSM):
create table t1(
id number,
c1 clob
)
lob (c1)
store as securefile
(
disable storage in row
chunk 8k
retention
nocache
tablespace users
)
tablespace users
;
Then create table "t2" with exactly the same properties and structure as t1. Next, create some sample data:
declare
c clob;
begin
for i in 1..200 loop
insert into t1 values (i, empty_clob() )
returning c1 into c;
for j in 1 .. i loop
dbms_lob.writeappend(c,2048,rpad(to_char(i),2048,'x'));
end loop;
end loop;
commit;
end;
/
And a dummy table, to avoid using any expressions, like ROWNUM, in the remote statement, and to have a "clean" remote SQL: SQL> create table t_rn as select rownum rn from dual connect by level <= 100;
Then using a loopback database link (connecting to the same user on the same database) I execute the INSERT:
SQL> insert /*+append*/ into t2 (id, c1) 2 select id, c1 from t1_at_loopback, t_rn_at_loopback 3 where t1.id<http://t1.id> >= 0;
Because of the length of the mail, I'll try to report just the session statistics, latches and enqueues I think are relevant. I'll also spare you the statistics from the actual system where I encountered the issue. Figures are deltas per second:
TYPE, STATISTIC , HDELTA/SEC ------------------------------------------------------------- ENQG, DX - Distributed Transaction , 159,06 ENQG, TX - Transaction , 1,36k LATG, lob segment dispenser latch , 11,76k STAT, session logical reads , 297,32k STAT, db block gets , 293,13k STAT, consistent gets , 4,19k STAT, consistent gets examination , 466,53 STAT, db block changes , 4,99k STAT, consistent changes , 481,36 STAT, CR blocks created , 481,69 STAT, transaction rollbacks , 1,11 STAT, commit batch/immediate performed , 1,15 STAT, segment dispenser allocations , 650,29 STAT, segment chunks allocation from disepnser , 654,43 STAT, KTFB alloc space (block) , 222,55k ---------------------------------------------------------------------- ActSes %Thread | SQL_ID | SQL_CHILD | EVENT ----------------------------------------------------------------------
.60 (60%) | akbww745v7jav | 0 | direct path write
.32 (32%) | akbww745v7jav | 0 | ON CPU
SQL> select used_ublk, used_urec, log_io, phy_io, cr_get, cr_change from v$transaction;
USED_UBLK USED_UREC LOG_IO PHY_IO CR_GET CR_CHANGE ---------- ---------- ---------- ---------- ---------- ----------
3990 247241 113280741 1031760 1589403 191702
Contrast that with a locally executed INSERT, after recreating t2:
SQL> insert /*+append*/ into t2 (id, c1)
2 select id, c1 from t1, t_rn
3 where t1.id<http://t1.id> >= 0;
TYPE, STATISTIC , HDELTA/SEC ------------------------------------------------------------- ENQG, TX - Transaction , 74,85 LATG, lob segment dispenser latch , 478,27 STAT, session logical reads , 2,18k STAT, db block gets , 543,15 STAT, consistent gets , 1,64k STAT, consistent gets examination , 1,59k STAT, db block changes , 178,52 STAT, consistent changes , 4,05 STAT, CR blocks created , 4,05 STAT, transaction rollbacks , ,06 STAT, commit batch/immediate performed , ,32 STAT, segment dispenser allocations , 27,65 STAT, segment chunks allocation from disepnser , 27,65 STAT, KTFB alloc space (block) , 104,2k -------------------------------------------------------------------- ActSes %Thread | SQL_ID | SQL_CHILD | EVENT --------------------------------------------------------------------
.87 (87%) | 9ydka790v3qh3 | 0 | direct path write
.13 (13%) | 9ydka790v3qh3 | 0 | ON CPU
SQL> select used_ublk, used_urec, log_io, phy_io, cr_get, cr_change from v$transaction;
USED_UBLK USED_UREC LOG_IO PHY_IO CR_GET CR_CHANGE ---------- ---------- ---------- ---------- ---------- ----------
29 1723 44718 2063335 101146 252
Tracing with events 10200 and 10201 shows there's some activity on blocks related to the data dictionary objects (LINK$, IDL_UB1$) although from the number of entries I'm not sure how reliable this trace is (or me analyzing it). Considering all above, it seems there's some LOB space management activity going on and it also seems, based on the statistic "transaction rollbacks" and "commit batch/immediate performed", there are some kind of recursive/autonomous transactions going on, although I didn't notice them in the 10046 trace (no XCTEND lines). Maybe they are performed by some other space management background process, although if that's so, I'm not sure why would they be reported in this session's statistics.
A possible workaround seems to be to perform the insert from a PL/SQL loop and commit in between inserts, however I still have to check that approach.
Any thoughts on how to find out the root cause of that behaviour?
Thank you in advance and regards,
Jure Bratina
-- http://www.freelists.org/webpage/oracle-lReceived on Wed Dec 21 2016 - 20:31:33 CET