ORA-01114 ORA-29701一例

Liu Maclean(刘相兵

ORA-01114 ORA-29701一例


库一个前台服务进程报错 ORA-01114 ORA-29701，错误信息如下：


2013-09-06 09:40:37.257: [ CSSCLNT]clssscConnect: gipcWait failed with 16 (12)
2013-09-06 09:40:37.263: [ CSSCLNT]clsssInitNative: connect to (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_upcmdb03_)) failed, rc 16
kgxgncin: CLSS init failed with status 3
kgxgncin: return status 3 (1311719766 SKGXN not av) from CLSS
kjfmsgr: unable to connect to NM for reg in shared group

*** 2013-09-06 09:40:37.278
dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=0, mask=0x0)
----- Error Stack Dump -----
ORA-01114: 将块写入文件  时出现 IO 错误 (块 # )
ORA-01114: 将块写入文件 162 时出现 IO 错误 (块 # 249666)
ORA-29701: 无法连接到集群同步服务
ORA-29701: 无法连接到集群同步服务


Ocssd.log:

2013-09-06 09:38:19.327: [    CSSD][1029]clssgmClientConnectMsg: msg flags 0x0000
2013-09-06 09:38:19.327: [GIPCXCPT][1029] gipcInternalSend: connection not valid for send operation endp 1139caff0 [000000000c5e30fb] { gipcEndpoint : localAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_upcmdb03_)(GIPCID=0623a806-0b64b484-1901192))', remoteAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_upcmdb03_)(GIPCID=0b64b484-0623a806-1508132))', numPend 0, numReady 0, numDone 0, numDead 0, numTransfer 0, objFlags 0x0, pidPeer 1508132, flags 0x34271e, usrFlags 0x14000 }, ret gipcretConnectionLost (12)
2013-09-06 09:38:19.327: [GIPCXCPT][1029] gipcSendF [gipcmodMuxSendCLSC : gipcmodMux.c : 1438]: EXCEPTION[ ret gipcretConnectionLost (12) ]  failed to send on endp 1139caff0 [000000000c5e30fb] { gipcEndpoint : localAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_upcmdb03_)(GIPCID=0623a806-0b64b484-1901192))', remoteAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_upcmdb03_)(GIPCID=0b64b484-0623a806-1508132))', numPend 0, numReady 0, numDone 0, numDead 0, numTransfer 0, objFlags 0x0, pidPeer 1508132, flags 0x34271e, usrFlags 0x14000 }, addr 0000000000000000, buf 113745ed8, len 103, cookie 1138ab750, flags 0x4000
2013-09-06 09:38:19.327: [GIPCXCPT][1029] gipcSendF [clssgmclSendGIPC : clssgmc.c : 5539]: EXCEPTION[ ret gipcretConnectionLost (12) ]  failed to send on endp 11388c310 [000000000c5e31ee] { gipcEndpoint : localAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_upcmdb03_)(GIPCID=0623a806-0b64b484-1901192))', remoteAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_upcmdb03_)(GIPCID=0b64b484-0623a806-1508132))', numPend 0, numReady 0, numDone 0, numDead 0, numTransfer 0, objFlags 0x0, pidPeer 1508132, flags 0x13061f, usrFlags 0x10010 }, addr 0000000000000000, buf 113745ed8, len 103, cookie 113745f50, flags 0x0
2013-09-06 09:38:19.327: [    CSSD][1029]clssgmclSendGIPC: gipcSend failure - 12
2013-09-06 09:38:19.327: [    CSSD][1029]clssgmSendClient: Send failed rc 12, con (c5e31ee), client (0), proc (113bf6730)
2013-09-06 09:38:19.331: [    CSSD][1029]clssgmDeadProc: proc 113bf6730


2013-09-06 09:40:59.364: [GIPCXCPT][1029] gipcmodMuxTransferAccept: internal accept request failed endp 11125bfd0, child 1139ea710, ret gipcretAuthFail (22)
2013-09-06 09:40:59.364: [ GIPCMUX][1029] gipcmodMuxTransferAccept: EXCEPTION[ ret gipcretAuthFail (22) ]  error during accept on endp 11125bfd0
2013-09-06 09:40:59.364: [GIPCXCPT][1029] gipcmodClscCallback: async request failed req 1135c8150 [000000000c5e568c] { gipcSendRequest : addr '', data 111464750, len 48, olen 0, parentEndp 1137538b0, ret gipcretConnectionLost (12), objFlags 0x0, reqFlags 0x224 }, ret gipcretConnectionLost (12)
2013-09-06 09:40:59.365: [GIPCXCPT][1029] gipcmodMuxTransferAccept: internal accept request failed endp 11125bfd0, child 1137538b0, ret gipcretConnectionInvalid (13)
2013-09-06 09:40:59.365: [ GIPCMUX][1029] gipcmodMuxTransferAccept: EXCEPTION[ ret gipcretConnectionInvalid (13) ]  error during accept on endp 11125bfd0
2013-09-06 09:40:59.381: [    CSSD][1029]clssscSelect: cookie accept request 11098d2c0
2013-09-06 09:40:59.381: [    CSSD][1029]clssgmAllocProc: (1139ea710) allocated
2013-09-06 09:40:59.385: [    CSSD][1029]clssgmClientConnectMsg: properties of cmProc 1139ea710 - 0,1,2,3,4
2013-09-06 09:40:59.385: [    CSSD][1029]clssgmClientConnectMsg: Connect from con(c5e56d8) proc(1139ea710) pid(8454896/8454896) version 11:2:1:4, properties: 0,1,2,3,4
2013-09-06 09:40:59.385: [    CSSD][1029]clssgmClientConnectMsg: msg flags 0x0000
2013-09-06 09:40:59.398: [    CSSD][1029]clssscSelect: cookie accept request 11098d2c0
2013-09-06 09:40:59.398: [    CSSD][1029]clssgmAllocProc: (113a59df0) allocated
2013-09-06 09:40:59.402: [    CSSD][1029]clssgmClientConnectMsg: properties of cmProc 113a59df0 - 0,1,2,3,4
2013-09-06 09:40:59.402: [    CSSD][1029]clssgmClientConnectMsg: Connect from con(c5e572f) proc(113a59df0) pid(7930566/7930566) version 11:2:1:4, properties: 0,1,2,3,4
2013-09-06 09:40:59.402: [    CSSD][1029]clssgmClientConnectMsg: msg flags 0x0000
2013-09-06 09:40:59.417: [    CSSD][1029]clssscSelect: cookie accept request 1139ea710

该ORA-29701: 无法连接到集群同步服务的原因是进程无法成功注册到CSS 集群同步服务中， 对应ocssd.log中存在 2013-09-06 09:38:19.327  gipcInternalSend: connection not valid for send operation endp 1139caff0 [000000000c5e30fb] { gipcEndpoint : localAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_upcmdb03_) 的信息，这说明当时cssd.bin进程无法有效处理进程连接行为。

该症状与文档< I/O Errors in Alert log with ORA-29701, with "gipcWait failed with 16" in trace (Doc ID 1496329.1)>描述的较为一致。
当ocssd.bin进程无法有效处理进程连接行为时，可能出现上述ORA-29701错误，该错误导致进程无法成功提交IO。 Ocssd.bin进程无法有效处理该行为的可能包括 ：进程HANG、CPU或内存资源不足等。


通过orac性能监控可以看到在问题时段有较高的CPU使用率：



AWR中显示存在少量OS CPU WAIT TIME:



Statistic        Value        End Value
AVG_BUSY_TIME        59,927         
AVG_IDLE_TIME        299,582         
AVG_IOWAIT_TIME        20,336         
AVG_SYS_TIME        5,995         
AVG_USER_TIME        53,764         
BUSY_TIME        3,847,221         
IDLE_TIME        19,184,896         
IOWAIT_TIME        1,312,936         
SYS_TIME        395,156         
USER_TIME        3,452,065         
LOAD        9        10
OS_CPU_WAIT_TIME        3,736,500         
RSRC_MGR_CPU_WAIT_TIME        0         
VM_IN_BYTES        770,048         
VM_OUT_BYTES        339,587,072         
PHYSICAL_MEMORY_BYTES        206,158,430,208         
NUM_CPUS        64         
NUM_CPU_CORES        32         
NUM_LCPUS        64         
NUM_VCPUS        32         
GLOBAL_RECEIVE_SIZE_MAX        41,943,040         
GLOBAL_SEND_SIZE_MAX        41,943,040         
TCP_RECEIVE_SIZE_DEFAULT        16,384         
TCP_RECEIVE_SIZE_MAX        9,223,372,036,854,775,807         
TCP_RECEIVE_SIZE_MIN        4,096         
TCP_SEND_SIZE_DEFAULT        16,384         
TCP_SEND_SIZE_MAX        9,223,372,036,854,775,807         
TCP_SEND_SIZE_MIN        4,096       

消耗CPU 最高的几个语句如下：

CPU Time (s)        Executions        CPU per Exec (s)        %Total        Elapsed Time (s)        %CPU        %IO        SQL Id        SQL Module        SQL Text
8,624.29        7,673        1.12        26.81        9,227.52        93.46        0.00        bwzctshpb44z9
JDBC Thin Client        SELECT A.BUSIID, A.ICONTENTID,...
6,390.37        21,411,575        0.00        19.86        6,828.10        93.59        0.00        5ntdmkpwybhax
JDBC Thin Client        SELECT ID FROM CTP_BRANCH WHER...
5,150.51        16,480        0.31        16.01        5,559.22        92.65        0.84        4d060subkztnf
JDBC Thin Client        BEGIN p_pcm_wn_united_approve....
3,577.02        1,211        2.95        11.12        5,032.32        71.08        21.05        2yz5fpu6y3gpj
JDBC Thin Client        BEGIN p_pcm_ad_handlist_manage...
2,445.13        2,323        1.05        7.60        2,918.86        83.77        10.13        djt2w8tuxkyuz
JDBC Thin Client        BEGIN p_pcm_wn_united_approve....
1,189.84        1,153        1.03        3.70        1,316.04        90.41        2.70        3u1m3wfdzfas6
JDBC Thin Client        BEGIN p_pcm_bg_bill_apply.r_ap...
1,129.66        288        3.92        3.51        1,638.17        68.96        23.29        2cd6vjbqz0x3k
JDBC Thin Client        SELECT COUNT (1) FROM ( SELECT...
1,095.32        288        3.80        3.40        1,180.85        92.76        0.96        39df691a6bb9j
JDBC Thin Client        SELECT ta500251001, ta50025100...
1,039.03        274        3.79        3.23        1,525.40        68.12        23.08        4nbf95hhdqqjk
JDBC Thin Client        SELECT COUNT (1) FROM ( SELECT...
1,022.15        274        3.73        3.18        1,095.55        93.30        0.71        0hazgftgt2qu4
JDBC Thin Client        SELECT ta500251001, ta50025100...


同时我们观察oraagent.bin进程的priority 优先级发现该进程的优先级不是0，而是60:

    grid S   1901192  11272321  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  11665611  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  11731153  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  16122139   0 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  16253213  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  16449833  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  16580917  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  16712107  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid Z   1901192  16777645  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  16908755  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid Z   1901192  17039863  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid Z   1901192  20054343  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  13959817  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  14877215   0 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  14942755  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  16188071  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  16319141  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid Z   1901192  16384695  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  16515781  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  16581325  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  13108129  61 /oragrid/product/11.2.0/bin/ocssd.bin
    grid Z   1901192  13370303  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  13435839  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  13501385  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  13566927  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid Z   1901192  13829109  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid Z   1901192  15729599  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  14025881  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid Z   1901192  14156957  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid Z   1901192  14288041  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  14419137  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  14484675  60 /oragrid/product/11.2.0/bin/ocssd.bin
    grid S   1901192  14550215  60 /oragrid/product/11.2.0/bin/ocssd.bin

该现象与BUG:13940331 - VALUE FOR SETTING THREAD SCHEDULING IS INCORRECT IN SLTSTSPAWN中描述的一致：

Bug 13940331 AIX: OCSSD threads are not set to the correct priority

being affected
11.2.0.2
10.2.0.5
10.2.0.4
Platforms affected IBM AIX Power Based Systems (64bit)
Fixed:
This issue is fixed in 12.1.0.1 (Base Release)
Symptoms: Related To:
Hang (Process Hang)

Cluster Ready Services / Parallel Server Management
Description
On AIX has found that the threads created for OCSSD were not inheriting the correct priority
thie may cause evictions when the machine is running under high workload.
The processes show the functions "ntevque->netevpque->poll" in their call stack and may hang.
Without the patch the priority for OCSSD threads is 60, after the patch we can see it's zero as:
$ ps -mp <OCSSD_PID> -o THREAD
USER PID PPID TID S CP PRI SC WCHAN F TT BND COMMAND
oraclets 14090370 11206740 - A 13 0 30 * 10240103 - - /local/oracle/grid/produ
- - - 27459713 Z 0 0 1 - c00001 - - -
- - - 38141977 S 0 0 1 f1000f0a10024640 8410400 - - -
- - - 38600869 S 0 0 1 - 418400 - - -
- - - 46268633 S 0 0 1 f1000f0a1002c240 8410400 - - -
- - - 46465061 S 0 0 1 f1000f0a1002c540 8410400 - - -
- - - 46792861 S 0 0 1 f1000f0a1002ca40 8410400 - - -
- - - 47710399 S 0 0 1 f1000f0a1002d840 8410400 - - -
- - - 48562263 S 0 0 1 f1000f0a1002e540 8410400 - - -
- - - 49545223 Z 0 0 1 - c00001 - - -
...
Workaround
None

该线程priority的问题仅发生在AIX平台上，目前存在11.2.0.3上的补丁 Patch 13940331: VALUE FOR SETTING THREAD SCHEDULING IS INCORRECT IN SLTSTSPAWN。

1.3        建议

1、        考虑优化相关SQL 语句等，减少其对CPU的使用率
2、        考虑应用11.2.0.3上的补丁Patch 13940331: VALUE FOR SETTING THREAD SCHEDULING IS INCORRECT IN SLTSTSPAWN