Jonathan, Sayan,
Thank you very much for the comments. I'll try to experiment with your
suggestions and see what emerges. The original problem of data transfer was
solved with a workaround, now I'm investigating this issue just because I'd
like to understand and possibly find out its root cause.
What bothers me, regardless of the outcome of the tests, is why the session
has to create more and more consistent read copies of datablocks and apply
more and more undo as the INSERT progresses. If there's actually the need
to manage space for LOBs in 8k increments, shouldn't be the buffers for the
LOB mapping area accessed in current and not consistent mode?
To get a feeling of what's happening, here are the "dynamics" of how the
system behaves, those are figures from the problematic database, source is
10.2.0.3 on z/OS, target (where the data is inserted) 12.1.0.2 Linux x86_64:
(t1) A few seconds into the transaction:
- Check v$bh for blocks belonging to objects affected by the INSERT
statement:
SQL> with objs
2 as (select object_id, object_name
3 from dba_objects
4 where object_name = 'TMP_BLOB'
5 union all
6 select object_id, object_name
7 from dba_objects
8 where object_name in (select segment_name
9 from dba_lobs
10 where table_name = 'TMP_BLOB'
11 union all
12 select index_name
13 from dba_lobs
14 where table_name = 'TMP_BLOB')
15 union all
16 select 4294967295, 'UNDO' from dual)
17 select h.objd,
18 objs.object_name,
19 h.status,
20 count (*)
21 from v$bh h, objs
22 where h.objd = objs.object_id
23 group by h.objd, objs.object_name, h.status
24 order by 1, 2;
OBJD OBJECT_NAME STATUS COUNT(*)
---------- ------------------------- ---------- ----------
4294967295 UNDO cr 1
4294967295 UNDO xcur 91
---------------------------------------------------------
STATISTIC , HDELTA/SEC,
---------------------------------------------------------
session logical reads , 79,66k,
db block gets , 78,85k,
consistent gets , 810,65,
db block changes , 2,25k,
consistent changes , 265,69,
free buffer requested , 285,47,
CR blocks created , 265,69,
physical writes direct (lob) , 1,57k,
calls to kcmgcs , 2,67k
calls to kcmgas , 530,18
calls to get snapshot scn: kcmgss , 1,68k
redo entries , 2,55k,
redo size , 533,21k,
undo change vector size , 129,28k,
segment dispenser allocations , 420,31,
segment chunks allocation from disepnser , 428,7,
securefile allocation bytes , 12,7M,
securefile allocation chunks , 428,7,
securefile direct write bytes , 12,89M,
bytes sent via SQL*Net to dblink , 8,29k,
bytes received via SQL*Net from dblink , 12,44M,
SQL*Net roundtrips to/from dblink , 46,95,
-------------------------------------------------------------------
ActSes %Thread | SQL_ID | EVENT
-------------------------------------------------------------------
.52 (52%) | 9g8dgs8j3zh51 | SQL*Net more data from dblink
.25 (25%) | 9g8dgs8j3zh51 | SQL*Net message from dblink
.15 (15%) | 9g8dgs8j3zh51 | direct path write
.08 (8%) | 9g8dgs8j3zh51 | ON CPU
(t2) Half an hour into the transaction:
Query from v$bh:
OBJD OBJECT_NAME STATUS COUNT(*)
---------- ------------------------------ ---------- ----------
103068 TMP_BLOB xcur 16
103069 SYS_LOB0000103068C00001$$ free 12
103069 SYS_LOB0000103068C00001$$ xcur 5414
103069 SYS_LOB0000103068C00001$$ cr 2146
103070 SYS_IL0000103068C00001$$ xcur 4
4294967295 UNDO xcur 22801
4294967295 UNDO cr 1
---------------------------------------------------------
STATISTIC , HDELTA/SEC
---------------------------------------------------------
session logical reads , 920,5k
db block gets , 900,12k
consistent gets , 20,37k
db block changes , 10,43k
consistent changes , 577,79
free buffer requested , 599,37
CR blocks created , 577,79
physical writes direct (lob) , 1,13k
calls to kcmgcs , 26,26k
calls to kcmgas , 1,3k
calls to get snapshot scn: kcmgss , 1,6k
redo entries , 9,54k
redo size , 1,55M
undo change vector size , 115,56k
transaction rollbacks , 1,73 <-- those were
absent in the previous snapshot
commit batch/immediate requested , 1,73
segment dispenser allocations , 222,74
segment chunks allocation from disepnser , 223,17
securefile allocation bytes , 6,46M
securefile allocation chunks , 223,17
securefile direct write bytes , 9,29M
bytes received via SQL*Net from dblink , 9,12M
SQL*Net roundtrips to/from dblink , 10,14
------------------------------------------------------------------
ActSes %Thread | SQL_ID | EVENT
------------------------------------------------------------------
.43 (43%) | 9g8dgs8j3zh51 | ON CPU
.36 (36%) | 9g8dgs8j3zh51 | SQL*Net more data from dblink
.18 (18%) | 9g8dgs8j3zh51 | direct path write
.02 (2%) | 9g8dgs8j3zh51 | SQL*Net message from dblink
(t3) 50 minutes or so into the transaction a breakpoint happens - CPU usage
spikes, as do other statistics related to data block management. It's also
interesting to note that calls to kcmgcs and kcmgas increse, it seems like
SCN is increasing rapidly (commits/rollbacks?). Allocation of chunks to
LOBs slows down considerably as does writing data to them:
OBJD OBJECT_NAME STATUS COUNT(*)
---------- ------------------------------ ---------- ----------
103068 TMP_BLOB xcur 20
103069 SYS_LOB0000103068C00001$$ free 16
103069 SYS_LOB0000103068C00001$$ cr 16806
103069 SYS_LOB0000103068C00001$$ xcur 7966
103070 SYS_IL0000103068C00001$$ xcur 4
4294967295 UNDO cr 1
4294967295 UNDO xcur 54410
---------------------------------------------------------
STATISTIC , HDELTA/SEC
---------------------------------------------------------
session logical reads , 1,3M
db block gets , 779,73k
consistent gets , 516,71k
db block changes , 6,94k
consistent changes , 155,76k
free buffer requested , 155,78k
CR blocks created , 155,76k
physical writes direct (lob) , 53,89
calls to kcmgcs , 212,11k
calls to kcmgas , 156,11k
calls to get snapshot scn: kcmgss , 496,07
redo entries , 6,48k
redo size , 994,67k
undo change vector size , 98,26k
transaction rollbacks , ,45
commit batch/immediate requested , ,45
segment dispenser allocations , 10,42
segment chunks allocation from disepnser , 10,42
securefile allocation bytes , 293,06k
securefile allocation chunks , 10,42
securefile direct write bytes , 441,44k
bytes received via SQL*Net from dblink , 434,61k
SQL*Net roundtrips to/from dblink , ,45
------------------------------------------------------------------
ActSes %Thread | SQL_ID | EVENT
------------------------------------------------------------------
.93 (93%) | 9g8dgs8j3zh51 | ON CPU
.02 (2%) | 9g8dgs8j3zh51 | SQL*Net more data from dblink
.02 (2%) | 9g8dgs8j3zh51 | local write wait
.02 (2%) | 9g8dgs8j3zh51 | direct path write
At this point I repeated the test and took some stack trace samples using
Tanel Poder's oStackProf utility at the beginning of the transaction and
when the session was mostly on CPU. The stacks traces differ quite
considerably. The "CPU bound" stack trace starts to differ from the
"normally performing" trace at this function calls: "
->ksupop()->kssdel()->kss_del_cb()->ksudlc()>ktcrsp1()->kturRbkToSvpt()->kturDiskRbkToSvpt()->kturCurrBackoutOneChg()->ktundo()->
kcoubk()->ktslpuundo()->ktsla_rbk_ins_chunk()->ktsla_clean_fsb()->....".
Searching MOS on this stack trace, Doc ID 2135629.1 points out a problem
with distributed transactions and temporary undo. I tried to set
"temp_undo_enabled=FALSE" and it seems (it might be a coincidence) the
problem of the session spiking on CPU doesn't reproduce anymore.
I'll try to experiment further based on the suggestions you made.
Regards,
Jure Bratina
On Wed, Dec 21, 2016 at 8:31 PM, Jonathan Lewis <jonathan@xxxxxxxxxxxxxxxxxx
wrote:
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
