个人总结

(原来itput的文档标题不能超过80个字符)在任意系统平台,RAC版本从10.2版本升级到11.2.0.2.一个回还 包含lob的insert语句hang住.如果不是XA事务,则可通过修改参数"_clusterwide_global_transactions"=false解决,重启rac服务解决,如是XA事务,则需要创建一个DTP服务,以确保所有的事务都在一个instance上.

Insert hangs after Upgrading to 11202 when using a Loopback Database Link in a RAC cluster [ID 1350157.1]
		Modified 18-AUG-2011     Type PROBLEM     Status MODERATED

In this Document
  Symptoms
  Cause
  Solution
  References

---

This document is being delivered to you via Oracle Support's Rapid Visibility (RaV) process and therefore has not been subject to an independent technical review.

Applies to:

Oracle Server - Enterprise Edition - Version: 11.2.0.1 to 11.2.0.2 - Release: 11.2 to 11.2
Oracle Server - Enterprise Edition - Version: 11.2.0.1 to 11.2.0.2   [Release: 11.2 to 11.2]
Information in this document applies to any platform.

Symptoms

After upgrade from 10.2 to 11.2.0.2 an

INSERT INTO table1 SELECT * FROM table2@DBLINK WHERE value =x ;

is hanging.

The database is a RAC cluster, the database link DBLINK is a loopback database link and the table being selected from contains LOB columns.

Cause

This problem is under investigation in Bug 10282287.

Solution

Assuming that XA is not in use on this system the workaround is to disable cluster wide transactions which is XA functionality which has been available since 11.1

1.

connect / a sysdba

alter system set "_clusterwide_global_transactions"=false scope=spfile;

2. Restart the entire 11.2 RAC cluster.

If XA is in use then DTP services would need to be created to ensure that all the XA transaction branches are handled within a single instance.

References

BUG:10282287 - RAC / LOOPBACK CONNECTION / LOB ACCESS / HANG : SQL*NET MORE DATA TO CLIENT
BUG:11736004 - INSERT BY SELECTING CLOB DATA LARGER THAN 32K OVER LOOKBACK DATABASE LINK HANGS

Related Products Oracle Database Products > Oracle Database > Oracle Database > Oracle Server - Enterprise Edition Oracle Database Products > Oracle Database > Oracle Database > Oracle Server - Enterprise Edition Keywords AFTER UPGRADE; DATABASE LINK; DBLINK; HANGING; LOB; LOOPBACK; RAC; UPGRADE

上面文档中列出的参考bug信息

Bug 10282287: RAC / LOOPBACK CONNECTION / LOB ACCESS / HANG : SQL*NET MORE DATA TO CLIENT

Bug Attributes

Related Products

Hdr: 10282287 11.2.0.1 RDBMS 11.2.0.1 TXN MGMT DIST PRODID-5 PORTID-23
Abstract: RAC / LOOPBACK CONNECTION / LOB ACCESS / HANG : SQL*NET MORE DATA TO CLIENT

*** 11/11/10 03:43 am *** (CHG: RDBMS Ver.-> NULL -> 11.2.0.1)
*** 11/11/10 03:43 am ***
----
3-2275494831

PROBLEM:
--------
Performing insert of lob data using a d/b loopback link 
to an 11.2.0.1 RAC database results in a hang. 
This issue has been reproduced by Support and a testcase is
uploaded . The supporting details /file are from the cluster
referenced. 
Files were generated once it was clear that the test was never going
to complete. Refer to the readme.txt file for details of how to 
connect to test env , testcase, etc.

When we have the issue , the server process which has been created by
loopback is waiting : SQL*Net more data from dblink

The shadow server process is waits appear to change (refer below) however
the short of it is a hang. 

==============
Relevant files uploaded are : 

alert log files : 
Node 1 / alert_H1121.log
Node 2 / alert_H1122.log

Node 1 / H1121_ora_16113.trc - server process associated with sqlplus 
connection

Note : this process is inserting into DSTTAB

...
WAIT #8: nam='SQL*Net more data from dblink' ela= 24278 driver id=675562835 
#bytes=78 p3=0 obj#=-1 tim=4991494290706
WAIT #8: nam='asynch descriptor resize' ela= 2 outstanding #aio=0 current aio 
limit=0 new aio limit=12288 obj#=-1 tim=4991494290796
Ioctl ASYNC_CONFIG error, errno = 1
Ioctl ASYNC_CONFIG error, errno = 1
WAIT #8: nam='asynch descriptor resize' ela= 5 outstanding #aio=0 current aio 
limit=0 new aio limit=12288 obj#=-1 tim=4991494299096
Ioctl ASYNC_CONFIG error, errno = 1
Ioctl ASYNC_CONFIG error, errno = 1

Node 1 / H1121_ora_16115.trc - server process referenced over d/b link 

Note : this process is getting the data from SRCTAB ; this is the 
process spawned as a result of d/b link access

...
WAIT #0: nam='SQL*Net more data to client' ela= 24076 driver id=1413697536 
#bytes=8164 p3=0 obj#=75232 tim=4991494625550
2010-11-11 10:03:46.447364 : nioqsn:entry
2010-11-11 10:03:46.447391 : nsbasic_bsd:entry
2010-11-11 10:03:46.447413 : nsbasic_bsd:tot=0, plen=8155.

The affect of the above , is that processes are waiting on each other 
and we have a hang. 

============
System states :
Note 1 / systemstate : H1121_ora_16864.trc
Node 2 / systemstate : H1122_ora_435.trc

DIAGNOSTIC ANALYSIS:
--------------------
relevant stacks  / waits  / H1121_ora_16864.trc :

PROCESS 32:

    O/S info: user: haclu, term: UNKNOWN, ospid: 16113 
    OSD pid info: Unix process pid: 16113, image: oracle@ceitclu1 (TNS V1-V3)

*** 10:12:15.616
    Short stack dump: WAIT #0: nam='ksdxexeotherwait' ela= 2932051 p1=0 p2=0 
p3=0 obj#=-1 tim=4992003772581
itctx()+304<-kjuscv()+5200<-ksipcon_v()+1136<-k2qcon()+1408<-K2GTElock1()+2368
<-K2GTElock()+64<-k2gUpdateUbaAndScn()+1104<-$cold_ktcucb()+768<-ktuchg2()+284
8<-ktuchg()+256<-ktbchg2nt()+128<-ktspfbchg()+2704<-ktspfupdst()+2000<-ktsplbm
f()+864<-ktspfsrch()+1376<-ktspscan_bmb()+592<-ktspgsp_main()+1376<-kdlgsp_ini
t()+704<-kdl_write1()+4640<-kdlf_write()+368<-koklccb()+624<-$cold_kpulbcr()+3
264<-ttcdrv()+36816<-nioqwa()+176<-upirtrc()+3744<-kpurcsc()+256<-kpulfrdarr()
+4432<-kpulfrd()+272<-OCILobRead2()+208<-koklicrl()+1424<-$cold_koklcre()+1200
<-kokleva()+1568<-evaopn2()+960<-qesltcEvalOutofLineCols()+800<-qesltcBeforeRo
wProcessing()+736<-qerltcNoKdtBufferedInsRowCBK()+448<-qerltcLoadStateMachine(
)+464<-qerltcInsertSelectRop()+480<-qerstRowP()+768<-qerstRowP()+768<-qerrmFFB
()+448<-qerrmFetch()+288<-qerstFetch()+720<-rwsfcd()+320<-qerstFetch()+720<-qe
rltcFetch()+1584<-qerstFetch()+720<-insexe()+2080<-opiexe()+10800<-opipls()+41
60<-opiodr()+2368<-rpidrus()+416<-skgmstack()+224<-rpidru()+224<-rpiswu2()+105
6<-rpidrv()+2208<-psddr0()+1040<-psdnal()+1088<-pevm_EXECC()+896<-pfrinstr_EXE
CC()+144<-pfrrun_no_tool()+192<-pfrrun()+1744<-plsql_run()+1392<-peicnt()+608<
-kkxexe()+1120<-opiexe()+18224<-kpoal8()+5088<-opiodr()+2368<-ttcpip()+2368<-o
pitsk()+2848<-opiino()+1680<-opiodr()+2368<-opidrv()+1264<-sou2o()+256<-opimai
_real()+256<-ssthrdmain()+432<-main()+464<-main_opd_entry()+80

   Current Wait Stack:
     0: waiting for 'DFS lock handle'
        type|mode=0x44580005, id1=0x2152ca67, id2=0x0
        wait_id=7588 seq_num=7590 snap_id=1
        wait times: snap=8 min 29 sec, exc=8 min 29 sec, total=8 min 29 sec
        wait times: max=infinite, heur=8 min 29 sec
        wait counts: calls=996 s=996
        in_wait=1 iflags=0x15a2
    There is at least one session blocking this session.
      Dumping 1 direct blocker(s):
        inst: 1, sid: 94, ser: 11
      Dumping final blocker:
        inst: 1, sid: 94, ser: 11
    Wait State:
      fixed_waits=0 flags=0x22 boundary=0x0000000000000000/-1
    Session Wait History:
        elapsed time of 0.006595 sec since current wait
     0: waited for 'asynch descriptor resize'
        outstanding #aio=0x0, current aio limit=0x0, new aio limit=0x3000
        wait_id=7587 seq_num=7589 snap_id=1
        wait times: snap=0.000005 sec, exc=0.000005 sec, total=0.000005 sec
        wait times: max=307445734561 min 49 sec
        wait counts: calls=0 s=0
        occurred after 0.008295 sec of elapsed time
     1: waited for 'asynch descriptor resize'
        outstanding #aio=0x0, current aio limit=0x0, new aio limit=0x3000
        wait_id=7586 seq_num=7588 snap_id=1
        wait times: snap=0.000002 sec, exc=0.000002 sec, total=0.000002 sec
        wait times: max=307445734561 min 49 sec
        wait counts: calls=0 s=0
        occurred after 0.000088 sec of elapsed time
     2: waited for 'SQL*Net more data from dblink'

(sid : 94 maps to process - 16115)  


WORKAROUND:
-----------
verified that cluster_database= false avoids issue . Not a suitable 
workaround.

RELATED BUGS:
-------------

REPRODUCIBILITY:
----------------
Every time 

TEST CASE:
----------
uploaded . Refer to readme.txt file

STACK TRACE:
------------
as above

SUPPORTING INFORMATION:
-----------------------

24 HOUR CONTACT INFORMATION FOR P1 BUGS:
----------------------------------------

DIAL-IN INFORMATION:
--------------------

IMPACT DATE:
------------

*** 11/11/10 03:44 am ***
continued ...

PROCESS 41:

    O/S info: user: haclu, term: UNKNOWN, ospid: 16115 
    OSD pid info: Unix process pid: 16115, image: oracle@ceitclu1
    Short stack dump: WAIT #0: nam='ksdxexeotherwait' ela= 975420 p1=0 p2=0 
p3=0 obj#=-1 tim=4992009792513
ksedsts()+480<-ksdxfstk()+48<-ksdxcb()+3040<-sspuser()+688<-<-_write_s
ioqsn()+4112<-opikndf2()+2080<-ttcclr()+6832<-ttciovconv()+1888<-kpolobPutData
()+464<-kpolcbLobRead()+336<-kdlrdb()+928<-kdlprl()+352<-kdl_read1()+18704<-kd
lf_read()+448<-koklOutlineRead1()+976<-koklread1()+640<-kpolob()+1472<-opiodr(
)+2368<-ttcpip()+2368<-opitsk()+2848<-opiino()+1680<-opiodr()+2368<-opidrv()+1
264<-sou2o()+256<-opimai_real()+256<-ssthrdmain()+432<-main()+464<-main_opd_en
try()+80

    Current Wait Stack:
     0: waiting for 'SQL*Net more data to client'
        driver id=0x54435000, #bytes=0x1fe4, =0x0
        wait_id=4511 seq_num=4512 snap_id=1
        wait times: snap=8 min 35 sec, exc=8 min 35 sec, total=8 min 35 sec
        wait times: max=infinite, heur=8 min 35 sec
        wait counts: calls=0 s=0
        in_wait=1 iflags=0x5a0
    There are 1 sessions blocked by this session.
    Dumping one waiter:
      inst: 1, sid: 7, ser: 7
      wait event: 'DFS lock handle'
        p1: 'type|mode'=0x44580005
etc.


=========
related similar issues : 

Bug 10243892: PROCESS HANGING WITH WAIT EVENT "ASYNCH DESCRIPTOR RESIZE" 
UPGRADE TO 11.2.0.2

Note : the issue was reproduced on an hp-ux itanium cluster . 
The customer has the same issue and is running on a Solaris environment . 

The issue looks 'asynch descriptor resize' related . 

In H1121_ora_16115.trc, there are multiple references to this event ; all 
have an object id which would appear reasonable. 

In H1121_ora_16115.trc , as you will see , the object id=-1 which looks
a bit odd. 

Refer to readme.txt uploaded for details of testcase, etc.
*** 11/11/10 04:50 am *** 
*** 11/11/10 05:22 am ***
*** 11/12/10 05:03 am *** (CHG: Sta->10)
*** 11/12/10 05:03 am ***
*** 11/12/10 05:03 am *** (CHG: Sta->16)
*** 11/15/10 03:18 am *** (CHG: Sta->11)
*** 11/15/10 03:18 am ***
*** 11/15/10 03:20 am *** 
*** 11/15/10 03:22 am ***
*** 11/15/10 03:23 am *** 
*** 11/15/10 03:23 am ***

Bug 11736004: INSERT BY SELECTING CLOB DATA LARGER THAN 32K OVER LOOKBACK DATABASE LINK HANGS

Bug Attributes

Related Products

Hdr: 11736004 11.2.0.1 RDBMS 11.2.0.1 TXN MGMT DIST PRODID-5 PORTID-226 10282287
Abstract: INSERT BY SELECTING CLOB DATA LARGER THAN 32K OVER LOOKBACK DATABASE LINK HANGS

*** 02/10/11 12:11 am ***
----
3-1729600561

PROBLEM:
--------
Customer is trying to insert a record into a table by selecting a record from 
another table using a loopback database link.

The loopback link connects to another user within the same database. The 
inserted record has a clob column and when the clob data 
is greater that 32K, the insert command hangs.

This issue happens only with loopback database link. This does not reproduce 
from one RAC database to another RAC database. Also 
this does not reproduce in standalone database environment

DIAGNOSTIC ANALYSIS:
--------------------
In customer case we see the wait events SQL*Net message to dblink, SQL*Net 
message from dblink, SQL*Net more data from dblink. Then gc current grant 
2-way and db file sequential read.

Finally 

DUMP LOCAL BLOCKER/HOLDER: block level 5 res [0xaf9ded7e][0x0],[DX][ext 
0x0,0x0]

In internal testing, we see the wait events SQL*Net message to dblink, 
SQL*Net message from dblink, SQL*Net more data from dblink. Then ges message 
buffer allocation, db file sequential read and db file sequential read

WORKAROUND:
-----------
No workaround available as of now

RELATED BUGS:
-------------
None

REPRODUCIBILITY:
----------------
Issue reproduced in-house

TEST CASE:
----------
Testcase is uploaded

STACK TRACE:
------------

SUPPORTING INFORMATION:
-----------------------

24 HOUR CONTACT INFORMATION FOR P1 BUGS:
----------------------------------------

DIAL-IN INFORMATION:
--------------------

IMPACT DATE:
------------

*** 02/10/11 12:12 am ***
WAIT #47880362157520: nam='Disk file operations I/O' ela= 12 FileOperation=2 
fileno=3 filetype=2 obj#=-1 tim=1290440867579561
EXEC 
#47880362157520:c=3000,e=3180,p=0,cr=2,cu=3,mis=1,r=1,dep=1,og=4,plh=193574464
2,tim=1290440867579833
STAT #47880362157520 id=1 cnt=0 pid=0 pos=1 bj=0 p='UPDATE  SEQ$ (cr=2 pr=0 
STAT #47880362157520 id=2 cnt=1 pid=1 pos=1 bj=79 p='INDEX UNIQUE SCAN 
CLOSE #47880362157520:c=0,e=3,dep=1,type=3,tim=1290440867579991
WAIT #47880361630616: nam='SQL*Net message to dblink' ela= 3 driver 
id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1290440867580579
WAIT #47880361630616: nam='SQL*Net message from dblink' ela= 8767 driver 
id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1290440867589402
WAIT #47880361630616: nam='SQL*Net more data from dblink' ela= 116 driver 
id=1413697536 #bytes=21 p3=0 obj#=-1 tim=1290440867589601
WAIT #47880361630616: nam='SQL*Net more data from dblink' ela= 10370 driver 
id=1413697536 #bytes=40 p3=0 obj#=-1 tim=1290440867600023
WAIT #47880361630616: nam='SQL*Net more data from dblink' ela= 99 driver 
id=1413697536 #bytes=59 p3=0 obj#=-1 tim=1290440867600201
WAIT #47880361630616: nam='SQL*Net more data from dblink' ela= 68 driver 
id=1413697536 #bytes=78 p3=0 obj#=-1 tim=1290440867600317
WAIT #47880361630616: nam='Disk file operations I/O' ela= 8 FileOperation=2 
fileno=73 filetype=2 obj#=-1 tim=1290440867600657
WAIT #47880361630616: nam='gc current grant 2-way' ela= 523 p1=73 p2=37513 
p3=16777220 obj#=94383 tim=1290440867601483
WAIT #47880361630616: nam='db file sequential read' ela= 5602 file#=73 
block#=37513 blocks=1 obj#=94383 tim=1290440867607247
WAIT #47880361630616: nam='gc current grant 2-way' ela= 659 p1=73 p2=37504 
p3=16777224 obj#=94383 tim=1290440867608509
WAIT #47880361630616: nam='db file sequential read' ela= 5480 file#=73 
block#=37504 blocks=1 obj#=94383 tim=1290440867614094
WAIT #47880361630616: nam='gc cr block 2-way' ela= 279 p1=73 p2=37512 p3=9 
obj#=94383 tim=1290440867614764
WAIT #47880361630616: nam='gc current grant 2-way' ela= 374 p1=73 p2=37511 
p3=16777224 obj#=94383 tim=1290440867615503
WAIT #47880361630616: nam='db file sequential read' ela= 7267 file#=73 
block#=37511 blocks=1 obj#=94383 tim=1290440867622859
WAIT #47880361630616: nam='gc current grant 2-way' ela= 392 p1=73 p2=37511 
p3=33619976 obj#=94383 tim=1290440867623519
DUMP LOCAL BLOCKER/HOLDER: block level 5 res [0xaf9ded7e][0x0],[DX][ext 
0x0,0x0]

*** 10:51:48.446
----------resource 0x4c8369c68----------------------
resname       : [0xaf9ded7e][0x0],[DX][ext 0x0,0x0]
hash mask     : x3
Local inst    : 1
dir_inst      : 2
master_inst   : 2
hv idx        : 66
hv last r.inc : 3
current inc   : 7
hv status     : 0
hv master     : 1
open options  : 
Held mode     : KJUSEREX
Cvt mode      : KJUSERNL
Next Cvt mode : KJUSERNL
msg_seq       : 0x1
res_seq       : 1
grant_bits    : KJUSERNL KJUSEREX 
count         : 2         0         0         0         0         1
val_state     : KJUSERVS_VALUE
valblk        : 0x44584e517eed9daf919ded461eac0400 DXNQ~F
access_inst   : 1
vbreq_state   : 0
state         : x8
resp          : 0x4c8369c68
On Scan_q?    : N
Total accesses: 5609
Imm.  accesses: 122
Granted_locks : 2 
Cvting_locks  : 1 
value_block:  44 58 4e 51 7e ed 9d af 91 9d ed 46 1e ac 04 00
GRANTED_Q :
lp 0x4d1da7778 gl KJUSEREX rp 0x4c8369c68 [0xaf9ded7e][0x0],[DX][ext 0x0,0x0]
  master 2 gl owner 0x4de66a4d0 possible pid 10380 xid 0000-0000-00000000 
bast 0 rseq 1 mseq 0 history 0x95551495
  open opt  KJUSERNO_XID 
CONVERT_Q: 
lp 0x4d3914440 gl KJUSERNL rl KJUSEREX rp 0x4c8369c68 
[0xaf9ded7e][0x0],[DX][ext 0x0,0x0]
  master 2 gl owner 0x4de1ed590 possible pid 10239 xid 0000-0000-00000000 
bast 0 rseq 1 mseq 0 history 0x5555555a
  convert opt KJUSERGETVALUE KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK  
----------enqueue 0x4d1da7778------------------------
lock version     : 43
Owner inst       : 1
grant_level      : KJUSEREX
req_level        : KJUSEREX
bast_level       : KJUSERNL
notify_func      : (nil)
resp             : 0x4c8369c68
procp            : 0x4d592b4a8
pid              : 10380
proc version     : 0
oprocp           : (nil)
opid             : 10380
group lock owner : 0x4de66a4d0
possible pid     : 10380
xid              : 0000-0000-00000000
dd_time          : 0.0 secs
dd_count         : 0
timeout          : 0.0 secs
On_timer_q?      : N
On_dd_q?         : N
lock_state       : GRANTED
ast_flag         : 0x0
Open Options     :  KJUSERNO_XID
Convert options  : KJUSERGETVALUE KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK 
History          : 0x95551495
Msg_Seq          : 0x0
res_seq          : 1
valblk           : 0x44584e517eed9daf919ded461eac0400 DXNQ~F
user session for deadlock lock 0x4d1da7778
  sid: 3478 ser: 1 audsid: 1879390 user: 109/ZZ0001
    flags: (0x45) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
    flags2: (0x8) -/-
  pid: 57 O/S info: user: oracle, term: UNKNOWN, ospid: 10380
    image: oracle@ed016-ftrc1an01.amer.epiqcorp.com
  client details:
    O/S info: user: oracle, term: , ospid: 10239
    machine: ed016-ftrc1an01.amer.epiqcorp.com program: 
oracle@ed016-ftrc1an01.amer.epiqcorp.com (TNS V1
    application name: oracle@ed016-ftrc1an01.amer.epiqcorp.com (TNS V1, hash 
value=3363753737
  current SQL:
  SELECT "A1"."DOCUMENT_ID","A1"."DOCUMENT_TEXT",1 FROM "ZZ0001"."DS_DOT" 
"A1" WHERE "A1"."DOCUMENT_ID"=5578 AND LENGTH("A1"."DOCUMENT_TEXT")>=32768
DUMP LOCAL BLOCKER: initiate state dump for TIMEOUT
  possible owner[57.10380] on resource DX-AF9DED7E-00000000

*** 10:51:48.448
Submitting asynchronized dump request [28]. summary=[ges process stack dump 
(kjdglblkrdm1)].

*** 10:55:07.862
WAIT #47880361630616: nam='DFS lock handle' ela= 4040238464 
type|mode=1146617861 id1=2946362750 id2=0 obj#=94383 tim=1290444907862341
*** 02/10/11 12:13 am *** (CHG: Sta->16)
*** 02/10/11 12:20 am ***
*** 02/10/11 01:43 am ***
*** 02/10/11 02:18 am *** 
*** 02/10/11 09:03 am ***
*** 02/10/11 09:16 am *** (CHG: Sta->10)
*** 02/10/11 09:16 am ***
*** 02/10/11 09:26 am ***
*** 02/10/11 09:27 am *** (CHG: Base Bug-> NULL -> 10282287)
*** 02/23/11 09:20 pm *** (CHG: Sta->16)
*** 02/23/11 09:20 pm ***
*** 02/24/11 07:33 am *** (CHG: Sta->10)
*** 02/24/11 07:33 am ***
*** 02/24/11 08:01 pm *** (CHG: Sta->16)
*** 02/24/11 08:01 pm ***
*** 03/10/11 07:31 am ***
*** 03/10/11 07:33 am ***
*** 03/10/11 07:42 am *** (CHG: Sta->11)
*** 03/10/11 07:42 am ***
*** 03/10/11 07:42 am *** 
*** 03/10/11 07:42 am ***
*** 05/31/11 11:23 pm *** (CHG: Sta->36)
*** 05/31/11 11:23 pm ***
*** 05/31/11 11:24 pm *** 
*** 05/31/11 11:24 pm ***

其他参考文档

使用Oracle RAC处理两阶段提交-开发技术(4) http://www.bitscn.com/pdb/oracle/200803/130210_4.html

2PC、XA、DTP与两阶段提交 http://www.eygle.com/archives/2008/07/2pc_xa_dtp.html