Oracle 12.1.0.2环境nclob类型使用dblink远程插入hang住案例

一、场景简介

在某个项目Oracle 12.1.0.2 RAC环境中，需要执行一个存储过程，此存储过程作用是通过dblink将当前业务数据插入到历史数据中。然而万万没想到将参数传入存储过程之后就被hang住，数据无法插入到历史用户内。实际上当前用户数据很少，只有几条，并不会因为数据行太多被卡住。

二、trace追踪

alter system set events '10046 trace name context forever, level 12';
oradebug unlimit
oradebug hanganalyze 10--等一分钟后再次执行hanganalyze分析
oradebug hanganalyze 10oradebug tracefile_name
alter system set events '10046 trace name context off';

trace文件如下：

=====================
PARSING IN CURSOR #140197126683160 len=438 dep=1 uid=110 oct=2 lid=110 tim=68676545655 hv=2945033387 ad='63c3e560' sqlid='2m2nwyfrsm95b'
insert into ept_XINJI_PB_HISTORY.pb_BAOZHENJIN@ept_XINJI_PB_H2019_LINK(BELONGXIAQUCODE, OPERATEUSERNAME, OPERATEDATE, YEARFLAG, ROWGUID, BIAODUANGUID, DANWEIGUID, DANWEINAME, INACCT, INAMOUNT, INTIME) select BELONGXIAQUCODE, OPERATEUSERNAME, OPERATEDATE, YEARFLAG, ROWGUID, BIAODUANGUID, DANWEIGUID, DANWEINAME, INACCT, INAMOUNT, INTIME from pb_BAOZHENJIN where BiaoDuanGuid ='8782ec0f-1c42-455a-94a0-b99b51718673'
END OF STMT
PARSE #140197126683160:c=705,e=2264,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=0,tim=68676545655
WAIT #140197126683160: nam='SQL*Net message to dblink' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676545785
WAIT #140197126683160: nam='SQL*Net message from dblink' ela= 170 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676545965
CLOSE #140197124265280:c=9,e=26,dep=2,type=1,tim=68676546031
=====================
PARSING IN CURSOR #140197127936976 len=53 dep=2 uid=110 oct=3 lid=110 tim=68676546075 hv=2077297917 ad='60b4f9e8' sqlid='5zk72kdxx237x'
SELECT /*+ FULL(P) +*/ * FROM "pb_BAOZHENJIN" P
END OF STMT
PARSE #140197127936976:c=0,e=18,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=401889764,tim=68676546075
WAIT #140197127936976: nam='SQL*Net message to dblink' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676546110
WAIT #140197126683160: nam='SQL*Net message from dblink' ela= 73 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676546198
WAIT #140197127936976: nam='row cache lock' ela= 36 cache id=16 mode=0 request=3 obj#=-1 tim=68676546284
……省略CLOSE #140197127936976:c=0,e=11,dep=2,type=1,tim=68676548059
=====================
PARSING IN CURSOR #140197126294320 len=240 dep=2 uid=110 oct=3 lid=110 tim=68676548157 hv=2656435952 ad='6c919168' sqlid='70g9412g5bzrh'
SELECT "BELONGXIAQUCODE","OPERATEUSERNAME","OPERATEDATE","YEARFLAG","ROWGUID","BIAODUANGUID","DANWEIGUID","DANWEINAME","INACCT","INAMOUNT","INTIME" FROM "pb_BAOZHENJIN" "A2" WHERE "BIAODUANGUID"=U'8782ec0f-1c42-455a-94a0-b99b51718673'
END OF STMT
省略……
CLOSE #140197126683160:c=0,e=5,dep=1,type=3,tim=68676569733

从这里开始，存储过程就卡在下面insert操作

=====================
PARSING IN CURSOR #140197126367360 len=372 dep=1 uid=110 oct=2 lid=110 tim=68676588685 hv=3285173653 ad='6a5a6138' sqlid='a511nab1wzjcp'
insert into ept_XINJI_PB_HISTORY.pb_BIAODUANEXT@ept_XINJI_PB_H2019_LINK(BELONGXIAQUCODE, OPERATEUSERNAME, OPERATEDATE, YEARFLAG, ROWGUID, BIAODUANGUID, KEYNAME, VALUE) select BELONGXIAQUCODE, OPERATEUSERNAME, OPERATEDATE, YEARFLAG, ROWGUID, BIAODUANGUID, KEYNAME, VALUE from pb_BIAODUANEXT where BiaoDuanGuid ='8782ec0f-1c42-455a-94a0-b99b51718673'
END OF STMT
PARSE #140197126367360:c=6637,e=12286,p=0,cr=117,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=68676588685
WAIT #140197126367360: nam='SQL*Net message to dblink' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676588779
WAIT #140197126367360: nam='SQL*Net message from dblink' ela= 249 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676589044
CLOSE #140197126294320:c=0,e=8,dep=2,type=1,tim=68676589078
=====================
PARSING IN CURSOR #140197126366264 len=54 dep=2 uid=110 oct=3 lid=110 tim=68676589120 hv=2983445332 ad='64b82348' sqlid='47dtq1asx7hun'
SELECT /*+ FULL(P) +*/ * FROM "pb_BIAODUANEXT" P
END OF STMT
PARSE #140197126366264:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=1335195241,tim=68676589119
WAIT #140197126366264: nam='SQL*Net message to dblink' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676589153
WAIT #140197126367360: nam='SQL*Net message from dblink' ela= 176 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676589345
WAIT #140197126366264: nam='row cache lock' ela= 57 cache id=16 mode=0 request=3 obj#=-1 tim=68676589452
BINDS #140197213873744:
……省略
CLOSE #140197126366264:c=0,e=11,dep=2,type=1,tim=68676590932
=====================
PARSING IN CURSOR #140197126003552 len=204 dep=2 uid=110 oct=3 lid=110 tim=68676590968 hv=999332028 ad='66d347c0' sqlid='c3ypk08xt165w'
SELECT "BELONGXIAQUCODE","OPERATEUSERNAME","OPERATEDATE","YEARFLAG","ROWGUID","BIAODUANGUID","KEYNAME","VALUE" FROM "pb_BIAODUANEXT" "A2" WHERE "BIAODUANGUID"=U'8782ec0f-1c42-455a-94a0-b99b51718673'
END OF STMT
PARSE #140197126003552:c=0,e=18,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=1628740296,tim=68676590967
EXEC #140197126003552:c=112,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=1628740296,tim=68676591006
WAIT #140197126003552: nam='SQL*Net message to dblink' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676591031
WAIT #140197126367360: nam='SQL*Net message from dblink' ela= 75 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676591122
WAIT #140197126003552: nam='SQL*Net message to dblink' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676591711
FETCH #140197126003552:c=103,e=607,p=0,cr=5,cu=0,mis=0,r=12,dep=2,og=1,plh=1628740296,tim=68676591749
STAT #140197126003552 id=1 cnt=12 pid=0 pos=1 obj=96236 op='TABLE ACCESS BY INDEX ROWID BATCHED pb_BIAODUANEXT (cr=5 pr=0 pw=0 time=588 us cost=9 size=2376 card=12)'
STAT #140197126003552 id=2 cnt=12 pid=1 pos=1 obj=97033 op='INDEX RANGE SCAN IDX_PINGNEXT_BDGUID (cr=2 pr=0 pw=0 time=551 us cost=1 size=0 card=12)'
WAIT #140197126367360: nam='SQL*Net message from dblink' ela= 12663 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676604453
WAIT #0: nam='SQL*Net message to dblink' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676604704
LOBREAD: type=PERSISTENT LOB,bytes=1,c=0,e=218,p=0,cr=1,cu=0,tim=68676604723

可以发现上面到LOBREAD这一步为止，整个存储过程就无法继续下去，其余表无法insert

下面也展示出了，被hang住的sql，与上面的一致。就是被1条insert语句hang住了

*** 2019-11-06 16:27:12.465
Received ORADEBUG command (#2) 'DUMP HANGANALYZE_PROC 1' from process '18878'*** 2019-11-06 16:27:12.465
-------------------------------------------------------------------------------
HUNG PROCESS DIAGNOSTIC DUMP BEGIN:
-------------------------------------------------------------------------------
----- Current SQL Statement for this session (sql_id=a511nab1wzjcp) -----
insert into ept_XINJI_PB_HISTORY.pb_BIAODUANEXT@ept_XINJI_PB_H2019_LINK(BELONGXIAQUCODE, OPERATEUSERNAME, OPERATEDATE, YEARFLAG, ROWGUID, BIAODUANGUID, KEYNAME, VALUE) select BELONGXIAQUCODE, OPERATEUSERNAME, OPERATEDATE, YEARFLAG, ROWGUID, BIAODUANGUID, KEYNAME, VALUE from pb_BIAODUANEXT where BiaoDuanGuid ='8782ec0f-1c42-455a-94a0-b99b51718673'
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----object      line  objecthandle    number  name
0x63feef38        44  procedure ept_XINJI_PB.PROC_PB_MOVEDATA2HISTORYDB
0x6058d1e8         1  anonymous block

从上面的PL/SQL Call Stack可看出，匿名块在第一行调用了存储过程PROC_PB_MOVEDATA2HISTORYDB，然而存储过程在运行第44行的时候就hang住了。
查询存储过程第44行

SQL> select line, text from dba_source 
where 
owner = 'ept_XINJI_PB' and  
name = 'PROC_PB_MOVEDATA2HISTORYDB' order by line asc;

----- Call Stack Trace -----
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
skdstdst()+45        call     kgdsdst()            7FFD3A363C10 0000000037FFD3A345650 ? 7FFD3A345768 ?7FFD3A363448 ? 000000083 ?
ksedst1()+102        call     skdstdst()           7FFD3A363C10 000000001000000001 7FFD3A345768 ?7FFD3A363448 ? 000000083 ?
ksdhng_dumpcb_hung_  call     ksedst1()            000000001 000000001
proc_int()+856                                     000000001 ? 7FFD3A345768 ?7FFD3A363448 ? 000000083 ?
ksdhng_dumpcb_hung_  call     ksdhng_dumpcb_hung_  000000001 000000000
proc()+21                     proc_int()           000000001 ? 7FFD3A345768 ?7FFD3A363448 ? 000000083 ?
ksdxdmp()+1493       call     ksdhng_dumpcb_hung_  000000001 000000000 ?proc()               000000001 ? 7FFD3A345768 ?7FFD3A363448 ? 000000083 ?
ksdxfdmp()+145       call     ksdxdmp()            00E4F0B88 7FFD3A3645E8000000001 0000000007FFD3A363448 ? 000000083 ?
ksdxcb()+918         call     ksdxfdmp()           7FFD3A364E90 000000017000000003 7FFD3A364D507FFD3A364DF0 000000083 ?
sspuser()+224        call     ksdxcb()             000000002 000000017 ?000000003 ? 7FFD3A364D50 ?7FFD3A364DF0 ? 000000083 ?
__sighandler()       call     sspuser()            000000002 ? 000000017 ?000000003 ? 7FFD3A364D50 ?7FFD3A364DF0 ? 000000083 ?
read()+14            signal   __sighandler()       00000000D ? 7F822E17542E ?000002010 ?FFFFFFFFFFFFFFFF ?000000008 ? 000000000 ?
snttread()+16        call     read()               00000000D ? 7F822E17542E ?000002010 ?FFFFFFFFFFFFFFFF ?000000008 ? 000000000 ?
nttfprd()+341        call     snttread()           00000000D ? 7F822E17542E ?000002010 ?FFFFFFFFFFFFFFFF ?000000008 ? 000000000 ?
nsbasic_brc()+405    call     nttfprd()            7F8235306630 7F822E17542E000000008 7FFD3A365CD0000000008 000000000 ?
nsbrecv()+86         call     nsbasic_brc()        000000000 ? 7F823093AA287FFD3A365EA8 7FFD3A365CD0 ?000000008 ? 000000000 ?
nioqrc()+494         call     nsbrecv()            000000000 ? 7F823093AA28 ?7FFD3A365EA8 ? 7FFD3A365CD0 ?000000008 ? 000000000 ?
opikndf2()+973       call     nioqrc()             7F822FEA3638 ? 7F823093AA28 ?7FFD3A369BF6 000000001 ?7F823093A980 ? 000000000 ?
ttcdrv()+1373        call     opikndf2()           7F822FEA3638 ? 7F823093AA28 ?FFD71D347 FFD71D3477F823093A980 ? 000000000 ?
nioqwa()+73          call     ttcdrv()             7FFD3A36A410 ? 7F823093AA28 ?7F822FEA34C0 FFD71D347 ?7F823093A980 ? 000000000 ?
upirtrc()+1372       call     nioqwa()             7FFD3A36A410 ? 7F823093AA28 ?00CD4A930 ? 7FFD3A369BD8 ?7F823093A980 ? 000000000 ?
kpurcsc()+102        call     upirtrc()            7F822FEA3530 ? 7F823093AA28 ?00CD4A930 ? 7FFD3A369BD8 ?7F823093A980 ? 000000000 ?
kpuexec()+10884      call     kpurcsc()            7F822FEA3530 ? 7F823093AA28 ?00CD4A930 ? 7FFD3A369BD8 ?7F823093A980 ? 000000000 ?
kpnexe()+1471        call     kpuexec()            7FFD3A36B878 ? 7F822FCB9A08 ?7FFD3A369A48 ? 000000001000000000 7FFD3A36DBF8
opiexe()+32875       call     kpnexe()             7F822FD5CE78 7F822FE8D7907F822FCB9A08 7F8230933D90000000001 000000000
opipls()+2002        call     opiexe()             7F8235361280 ? 7F822FE8D790 ?000000000 ? 7F8230933D90 ?000000001 ? 000000000 ?
opiodr()+1165        call     opipls()             7F8235361280 ? 7F822FE8D790 ?7FFD3A370F50 7F8230933D90 ?7F822FEA6880 100000000
rpidrus()+206        call     opiodr()             000000066 0000000047FFD3A370F50 ? 7F8230933D90 ?7F822FEA6880 ? 100000001
skgmstack()+144      call     rpidrus()            7FFD3A3702D0 000000004 ?7F823532FE98 7F8230933D90 ?7F822FEA6880 ? 100000001 ?
rpiswu2()+723        call     skgmstack()          7FFD3A3702A8 ? 7F823532F7C0 ?00000F618 ? 00CBE99A0 ?7FFD3A3702D0 ? 100000001 ?
rpidrv()+1570        call     rpiswu2()            7FFD3A3702A8 ? 7F823532F7C0 ?00000F618 ? 000000008 ?7F8235361280 ? 100000001 ?
psddr0()+478         call     rpidrv()             000000004 0000000667FFD3A370F50 0000000387F8235361280 ? 100000001 ?
psdnal()+636         call     psddr0()             000000004 0000000667FFD3A370F50 0000000307F823532FE98 000000001
pevm_EXIM()+260      call     psdnal()             7FFD3A3722C8 000000066 ?000000004 7F822FBD48407F8235361280 ? 000000001 ?
pfrinstr_EXIM()+52   call     pevm_EXIM()          7F8235212DE8 7F82300373C0000000004 ? 7F822FBD4840 ?7F8235361280 ? 000000001 ?
pfrrun_no_tool()+60  call     pfrinstr_EXIM()      7F8235212DE8 ? 0671CD900 ?7F8235212E58 ? 7F822FBD4840 ?7F8235361280 ? 000000001 ?
pfrrun()+1155        call     pfrrun_no_tool()     7F8235212DE8 ? 0671CD900 ?7F8235212E58 ? 7F822FBD4840 ?7F8235361280 ? 000000001 ?
plsql_run()+708      call     pfrrun()             7F8235212DE8 0000000007F8235212E58 ? 7FFD3A3722C87F8235361280 ? 06956A280
peicnt()+285         call     plsql_run()          7F8235212DE8 000000001000000000 7FFD3A3722C8 ?000000000 06956A280 ?
kkxexe()+726         call     peicnt()             7FFD3A3722C8 7F8235212DE8000000000 ? 7F82300363C8000000000 ? 06956A280 ?
opiexe()+19492       call     kkxexe()             7F822FE374A0 7F8235212DE8 ?000000000 ? 7F82300363C8 ?000000000 ? 06956A280 ?
kpoal8()+2793        call     opiexe()             7F8235361280 ? 7F8235212DE8 ?000000000 ? 7F82300363C8 ?000000000 ? 06956A280 ?
opiodr()+1165        call     kpoal8()             00000005E 00000001F7FFD3A3772F8 7F82300363C8 ?000000000 ? 06956A280 ?
ttcpip()+2699        call     opiodr()             00000005E 00000001F7FFD3A3772F8 ? 7F82300363C8 ?000000000 ? 100000000
opitsk()+1734        call     ttcpip()             7F8235345090 ? 00000005E ?7FFD3A3772F8 000000000 ?7FFD3A376D58 7FFD3A377504
opiino()+945         call     opitsk()             000000400 0000000007FFD3A3772F8 ? 000000000 ?7FFD3A376D58 ? 7FFD3A377504 ?
opiodr()+1165        call     opiino()             00000003C 0000000047FFD3A378998 000000000 ?7FFD3A376D58 ? 7FFD3A377504 ?
opidrv()+587         call     opiodr()             00000003C 0000000047FFD3A378998 ? 000000000 ?7FFD3A376D58 ? 000000000
sou2o()+145          call     opidrv()             00000003C 0000000047FFD3A378998 000000000 ?7FFD3A376D58 ? 000000000 ?
opimai_real()+154    call     sou2o()              7FFD3A378970 00000003C000000004 7FFD3A3789987FFD3A376D58 ? 000000000 ?
ssthrdmain()+412     call     opimai_real()        000000000 7FFD3A378C80000000004 ? 7FFD3A378998 ?7FFD3A376D58 ? 000000000 ?
main()+236           call     ssthrdmain()         000000000 0000000027FFD3A378C80 000000001000000000 000000000 ?
__libc_start_main()  call     main()               7FFD3A37982F 7FFD3A37983B
+245                                               7FFD3A378C80 ? 000000001 ?000000000 ? 000000000 ?
_start()+41          call     __libc_start_main()  000BA8990 0000000027FFD3A378EB8 7F8230FC8C05 ?000000000 ? 000000000 ?

在做hang analyze的过程中，进程内trace文件可以看到也会生成call stack的过程，里面是oracle调用代码的内部函数，从最底部函数” __libc_start_main“到顶部” kgdsdst“，调用了几十个函数，没有源码这里就不再做分析。

tkprof格式化trace文件
insert hang住的sql执行计划

********************************************************************************SQL ID: a511nab1wzjcp Plan Hash: 0insert into ept_XINJI_PB_HISTORY.pb_BIAODUANEXT@ept_XINJI_PB_H2019_LINK(BELONGXIAQUCODE, OPERATEUSERNAME, OPERATEDATE, YEARFLAG, ROWGUID, BIAODUANGUID, KEYNAME, VALUE) select BELONGXIAQUCODE, OPERATEUSERNAME, OPERATEDATE, YEARFLAG, ROWGUID, BIAODUANGUID, KEYNAME, VALUE from pb_BIAODUANEXT where BiaoDuanGuid ='8782ec0f-1c42-455a-94a0-b99b51718673'call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.01          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.01          0          0          0           0Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 110     (recursive depth: 1)Elapsed times include waiting on following events:Event waited on                             Times   Max. Wait  Total Waited----------------------------------------   Waited  ----------  ------------SQL*Net message to dblink                       1        0.00          0.00SQL*Net message from dblink                     5        0.01          0.01
********************************************************************************上面”Execute“为0，也就是解析后没有执行

下面是执行成功sql的执行计划

********************************************************************************SQL ID: 8xym6qm9g5n70 Plan Hash: 0insert into ept_XINJI_PB_HISTORY.pb_BAOJIAHISTROY@ept_XINJI_PB_H2019_LINK(BELONGXIAQUCODE, OPERATEUSERNAME, OPERATEDATE, YEARFLAG, ROWGUID, BJGUID, BIAODUANGUID, DANWEIGUID, BJR_CODE, BJR_NAME, BJR_DATE, BJNUM, ISQIANZHANG, STATUS, DANWEINAME, ATTACHCONNAME, BJTOTAL, PROMISEANDINTRO, FINALBAOJIA, FILEPATH) select BELONGXIAQUCODE, OPERATEUSERNAME, OPERATEDATE, YEARFLAG, ROWGUID, BJGUID, BIAODUANGUID, DANWEIGUID, BJR_CODE, BJR_NAME, BJR_DATE, BJNUM, ISQIANZHANG, STATUS, DANWEINAME, ATTACHCONNAME, BJTOTAL, PROMISEANDINTRO, FINALBAOJIA, FILEPATH from pb_BAOJIAHISTROY where BiaoDuanGuid ='8782ec0f-1c42-455a-94a0-b99b51718673'call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.01          0         63          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.01          0         63          0           0Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 110     (recursive depth: 1)Elapsed times include waiting on following events:Event waited on                             Times   Max. Wait  Total Waited----------------------------------------   Waited  ----------  ------------SQL*Net message to dblink                       3        0.00          0.00SQL*Net message from dblink                     6        0.00          0.00
********************************************************************************

看到这里，通常会想到事务被其他会话阻塞了，随即使用脚本查看长时间未提交的会话

with ltr as ( 
select to_char(sysdate,'YYYYMMDDHH24MISS') TM, s.inst_id,s.sid,s.serial#,s.sql_id,s.sql_child_number,s.prev_sql_id,xid, to_char(t.start_date,'YYYY-MM-DD HH24:MI:SS') start_time, e.TYPE,e.block, e.ctime/3600 runtime_Hour, decode(e.CTIME, 0, (sysdate - t.start_date) * 3600*24, e.ctime) el_second  from gv$transaction t, gv$session s,gv$transaction_enqueue ewhere t.start_date <= sysdate - interval '1' secondand t.addr = s.taddr and t.addr = e.addr(+) )  select ltr.* , (select q1.sql_text from gv$sql q1 where ltr.prev_sql_id = q1.sql_id(+)and rownum = 1) prev_sql_text , (select q1.sql_text from gv$sql q1 where ltr.sql_id = q1.sql_id(+) and ltr.sql_child_number = q1.CHILD_NUMBER(+)) sql_text from ltr ltr;

可以看到我在会话sid 81执行的存储过程，在会话sid 96有生成另外一条sql插入语句，插入的都是同一个对象。

再查看会话96的trace文件

=====================
PARSING IN CURSOR #140476666452608 len=426 dep=0 uid=109 oct=2 lid=109 tim=68676590666 hv=2396442408 ad='60bd85d0' sqlid='14h815y7ddmt8'
INSERT  INTO "ept_XINJI_PB_HISTORY"."pb_BIAODUANEXT" "A1" ("BELONGXIAQUCODE","OPERATEUSERNAME","OPERATEDATE","YEARFLAG","ROWGUID","BIAODUANGUID","KEYNAME","VALUE") SELECT "A2"."BELONGXIAQUCODE","A2"."OPERATEUSERNAME","A2"."OPERATEDATE","A2"."YEARFLAG","A2"."ROWGUID","A2"."BIAODUANGUID","A2"."KEYNAME","A2"."VALUE" FROM "pb_BIAODUANEXT"@! "A2" WHERE "A2"."BIAODUANGUID"='8782ec0f-1c42-455a-94a0-b99b51718673'
END OF STMT
PARSE #140476666452608:c=260,e=1723,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1788691278,tim=68676590665
WAIT #140476666452608: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676590829
WAIT #140476666452608: nam='SQL*Net message from client' ela= 220 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676591062
WAIT #140476666452608: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676591106
WAIT #140476666452608: nam='SQL*Net message from client' ela= 699 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=68676591811
=====================

可以发现，在本地执行的dblink插入语句，数据库实际会在远端目标用户下执行插入操作

本地：insert into 
ept_XINJI_PB_HISTORY.pb_BIAODUANEXT@ept_XINJI_PB_H2019_LINK(YEARFLAG, 
ROWGUID, BIAODUANGUID, KEYNAME, VALUE) select YEARFLAG, 
ROWGUID, BIAODUANGUID, KEYNAME, 
VALUE from pb_BIAODUANEXT 
where BiaoDuanGuid ='8782ec0f-1c42-455a-94a0-b99b51718673'目标端：INSERT  INTO 
"ept_XINJI_PB_HISTORY"."pb_BIAODUANEXT" "A1" 
("YEARFLAG","ROWGUID","BIAODUANGUID","KEYNAME","VALUE") 
SELECT "A2"."YEARFLAG","A2"."ROWGUID",
"A2"."BIAODUANGUID","A2"."KEYNAME",
"A2"."VALUE" FROM "pb_BIAODUANEXT"@! "A2" 
WHERE "A2"."BIAODUANGUID"='8782ec0f-1c42-455a-94a0-b99b51718673'

并且目标端的dblink名后面会变成"!"，这与上述事务脚本查出的sql_text一致

根据上面trace跟踪，存储过程被hang住的sql最后进行的操作是lobread，如果去掉大字段会怎么样，后面经过不断测试，最后发现某个nclob类型的字段去掉之后，使用dblink插入目标端成功

另外，后面在远端用户反过来插入倒是可以。

insert into pb_BIAODUANEXT(VALUE) 
select VALUE from 
pb_BIAODUANEXT@ept_XINJI_PB_LINK 
where BiaoDuanGuid ='8782ec0f-1c42-455a-94a0-b99b51718673';

三、测试

在不同版本的数据库测试nclob类型使用dblink插入远端数据库

1、12c 12.1.0.2数据库
nclob

clob

2、11g数据库nclob测试

3、12c r2数据库nclob测试

4、18c数据库nclob测试

5、19c数据库nclob测试

测试结果可以发现，nclob类型的字段无法在12.1.0.2环境下使用dblink插入远端数据库，在11g,12c R2,18c,19c环境下正常。

来看一下在11g环境中，nclob字段通过dblink远端插入数据库的执行计划
原始sql：“insert into pb_his.TEST_NCLOB@PB_LINK(id,name) select id,name from TEST_NCLOB”
通过追踪发现递归sql以及执行计划如下：

=====================
PARSING IN CURSOR #139749061327664 len=77 dep=0 uid=85 oct=2 lid=85 tim=1573184427993380 hv=3461039180 ad='922585f8' sqlid='a0txnym74qj2c'
insert into pb_his.TEST_NCLOB@PB_LINK(id,name) select id,name from TEST_NCLOB
END OF STMT
PARSE #139749061327664:c=15423,e=172417,p=0,cr=5,cu=1,mis=1,r=0,dep=0,og=1,plh=0,tim=1573184427993379
WAIT #139749061327664: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1573184427993665
WAIT #139749061327664: nam='SQL*Net message from dblink' ela= 6857 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1573184428000554
WAIT #0: nam='DFS lock handle' ela= 922 type|mode=1146617861 id1=1599446056 id2=0 obj#=-1 tim=1573184428001691
WAIT #0: nam='KJC: Wait for msg sends to complete' ela= 12 msg=2654623728 dest|rcvr=65536 mtype=8 obj#=-1 tim=1573184428001758
=====================

=====================
PARSING IN CURSOR #139749061277864 len=44 dep=1 uid=85 oct=3 lid=85 tim=1573184428006562 hv=2040601848 ad='92c9a290' sqlid='21fzgwpwu277s'
SELECT /*+ FULL(P) +*/ * FROM "TEST_NCLOB" P
END OF STMT
PARSE #139749061277864:c=3918,e=4772,p=0,cr=8,cu=0,mis=1,r=0,dep=1,og=1,plh=387598057,tim=1573184428006561
WAIT #139749061277864: nam='SQL*Net message to dblink' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1573184428007187
WAIT #139749061327664: nam='SQL*Net message from dblink' ela= 1872 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1573184428009147
WAIT #0: nam='DFS lock handle' ela= 635 type|mode=1146617861 id1=1599446056 id2=0 obj#=-1 tim=1573184428010000
=====================
PARSING IN CURSOR #139749061360064 len=366 dep=2 uid=85 oct=3 lid=85 tim=1573184428010671 hv=3200466642 ad='a51d61b8' sqlid='93h3d6fzc6gqk'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ NO_PARALLEL("P") FULL("P") NO_PARALLEL_INDEX("P") */ :"SYS_B_2" AS C1, :"SYS_B_3" AS C2 FROM "PB"."TEST_NCLOB" "P") SAMPLESUB
END OF STMT
PARSE #139749061360064:c=80,e=83,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=1276474752,tim=1573184428010671
BINDS #139749061360064:Bind#0oacdty=02 mxl=22(01) mxlc=00 mal=00 scl=00 pre=00oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0kxsbbbfp=a51db728  bln=22  avl=01  flg=09value=0Bind#1oacdty=02 mxl=22(01) mxlc=00 mal=00 scl=00 pre=00oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0kxsbbbfp=92980800  bln=22  avl=01  flg=09value=0Bind#2oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0kxsbbbfp=92ea6170  bln=22  avl=02  flg=09value=1Bind#3oacdty=02 mxl=22(02) mxlc=00 mal=00 scl=00 pre=00oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0kxsbbbfp=92641018  bln=22  avl=02  flg=09value=1
EXEC #139749061360064:c=129,e=549,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,plh=1276474752,tim=1573184428011278
FETCH #139749061360064:c=47,e=48,p=0,cr=7,cu=0,mis=0,r=1,dep=2,og=1,plh=1276474752,tim=1573184428011399
STAT #139749061360064 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=7 pr=0 pw=0 time=53 us)'
STAT #139749061360064 id=2 cnt=1 pid=1 pos=1 obj=87695 op='TABLE ACCESS FULL TEST_NCLOB (cr=7 pr=0 pw=0 time=38 us cost=3 size=0 card=409)'
CLOSE #139749061360064:c=5,e=8,dep=2,type=0,tim=1573184428011837
WAIT #139749061277864: nam='SQL*Net message to dblink' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1573184428014084
WAIT #139749061327664: nam='SQL*Net message from dblink' ela= 10149 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1573184428024292
WAIT #0: nam='DFS lock handle' ela= 589 type|mode=1146617861 id1=1599446056 id2=0 obj#=-1 tim=1573184428025441
WAIT #0: nam='KJC: Wait for msg sends to complete' ela= 21 msg=2654623728 dest|rcvr=65536 mtype=8 obj#=-1 tim=1573184428025882
CLOSE #139749061277864:c=15,e=17,dep=1,type=0,tim=1573184428025955
=====================
PARSING IN CURSOR #139749061359008 len=370 dep=2 uid=85 oct=3 lid=85 tim=1573184428027609 hv=2857419930 ad='a50fa170' sqlid='dbd2y9kp51j4u'
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ NO_PARALLEL("A2") FULL("A2") NO_PARALLEL_INDEX("A2") */ :"SYS_B_2" AS C1, :"SYS_B_3" AS C2 FROM "PB"."TEST_NCLOB" "A2") SAMPLESUB
END OF STMT
PARSE #139749061359008:c=450,e=484,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=1,plh=0,tim=1573184428027608
……省略
EXEC #139749061359008:c=1305,e=2210,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=1,plh=1276474752,tim=1573184428029926
FETCH #139749061359008:c=75,e=75,p=0,cr=7,cu=0,mis=0,r=1,dep=2,og=1,plh=1276474752,tim=1573184428030108
STAT #139749061359008 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=7 pr=0 pw=0 time=106 us)'
STAT #139749061359008 id=2 cnt=1 pid=1 pos=1 obj=87695 op='TABLE ACCESS FULL TEST_NCLOB (cr=7 pr=0 pw=0 time=63 us cost=3 size=0 card=409)'
CLOSE #139749061359008:c=4,e=5,dep=2,type=0,tim=1573184428030206
=====================
PARSING IN CURSOR #139749061360064 len=41 dep=1 uid=85 oct=3 lid=85 tim=1573184428030584 hv=1504966119 ad='92f12600' sqlid='2c1d79jcv7xg7'
SELECT "ID","NAME" FROM "TEST_NCLOB" "A2"
END OF STMT
PARSE #139749061360064:c=3336,e=4538,p=0,cr=8,cu=0,mis=1,r=0,dep=1,og=1,plh=387598057,tim=1573184428030583
EXEC #139749061360064:c=31,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=387598057,tim=1573184428030667
WAIT #139749061360064: nam='SQL*Net message to dblink' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1573184428031117
WAIT #139749061327664: nam='SQL*Net message from dblink' ela= 7035 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1573184428038232
WAIT #0: nam='DFS lock handle' ela= 567 type|mode=1146617861 id1=1599446056 id2=0 obj#=-1 tim=1573184428039272
WAIT #0: nam='KJC: Wait for msg sends to complete' ela= 8 msg=2654623728 dest|rcvr=65536 mtype=8 obj#=-1 tim=1573184428039356
WAIT #139749061360064: nam='SQL*Net message to dblink' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1573184428039438
FETCH #139749061360064:c=78,e=79,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=1,plh=387598057,tim=1573184428039460
STAT #139749061360064 id=1 cnt=1 pid=0 pos=1 obj=87695 op='TABLE ACCESS FULL TEST_NCLOB (cr=7 pr=0 pw=0 time=45 us cost=3 size=2015 card=1)'
WAIT #139749061327664: nam='SQL*Net message from dblink' ela= 8555 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1573184428048544
WAIT #0: nam='DFS lock handle' ela= 768 type|mode=1146617861 id1=1599446056 id2=0 obj#=-1 tim=1573184428049601
WAIT #0: nam='KJC: Wait for msg sends to complete' ela= 12 msg=2654623728 dest|rcvr=65536 mtype=8 obj#=-1 tim=1573184428049685
WAIT #0: nam='SQL*Net message to dblink' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1573184428053496
LOBREAD: c=353,e=391,p=0,cr=0,cu=0,tim=1573184428053550
WAIT #139749061327664: nam='SQL*Net message from dblink' ela= 7441 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1573184428061150
WAIT #139749061327664: nam='DFS lock handle' ela= 118 type|mode=1146617861 id1=1599446056 id2=0 obj#=-1 tim=1573184428062231
EXEC #139749061327664:c=16151,e=68938,p=0,cr=31,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=1573184428062388
WAIT #139749061327664: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1573184428063108*** 2019-11-08 11:42:20.360
WAIT #139749061327664: nam='SQL*Net message from client' ela= 112297691 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1573184540360835
CLOSE #139749061327664:c=39,e=41,dep=0,type=0,tim=1573184540361080
=====================
PARSING IN CURSOR #139749061327664 len=6 dep=0 uid=85 oct=44 lid=85 tim=1573184540361324 hv=3480936638 ad='0' sqlid='23wm3kz7rps5y'
commit
END OF STMT

rkprof格式化trace文件之后如下：

可以发现在如上截图“commit”前，递归sql执行的最后一条是

SELECT "ID","NAME" FROM "TEST_NCLOB" "A2"

与hang住的sql进行比对如下：

比对12.1.0.2以及11.2.0.4两个执行计划可以知道，在12.1.0.2版本中执行计划是卡在LOBREAD: type=PERSISTENT LOB,bytes=3,c=1000,e=107888,p=0,cr=1,cu=0,tim=17521707479048。本地执行一条dblink方式的远程插入，sql解析之后，但是递归sql被卡住无法执行下去，理所当然dblink方式insert无法继续下去，这也就是解释了为什么在执行存储过程中会一直hang住。

生产环境以及测试环境均已测试，并且只有在12.1.0.2版本才会有问题，想到这是否是BUG，看下MOS

Bug 23027487 - Insert NCLOB Data Into Remote Table Hangs (文档 ID 23027487.8)

1、的确是bug，并且上面的情景与我测试的完全一致，都是nclob类型字段dblink在源端插入会hang( insert into table_remote@dblink SELECT * FROM table_local; )。在目标端，执行dblink插入正常 (insert into table_local SELECT * FROM table_remote@dblink_new;)

2、此bug在12.2.0.1以后的数据库已被修复

四、解决方案

由于存储过程中使用了dblink的方式插入数据，后来了解到源端与目标端实际都在一个实例下面，可以去除dblink并改为”模式名.对象名“就可以解决。