Re: High number of created consistent read blocks when inserting into a LOB column from dblink

  • From: Jonathan Lewis <jonathan@xxxxxxxxxxxxxxxxxx>
  • To: ORACLE-L <oracle-l@xxxxxxxxxxxxx>
  • Date: Wed, 21 Dec 2016 19:31:33 +0000

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@xxxxxxxxxxxxx <oracle-l-bounce@xxxxxxxxxxxxx> on behalf 
of Jure Bratina <jure.bratina@xxxxxxxxx>
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@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@loopback, t_rn@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
--
//www.freelists.org/webpage/oracle-l


Other related posts: