解决RAC节点因cursor: pin S wait on X无法登陆案例一则
OS: Sunos 5.9
DB:两节点RAC 10.2.0.2
症状：开发人员报告无法连接第二个节点
首先登陆第二个节点，尝试以sysdba登陆，果然一直hang在那里
justin19.prod2> sqlplus / as sysdba
SQL*Plus: Release 10.2.0.2.0 - Production on Thu May 3 11:18:32 2012
Copyright (c) 1982, 2005, Oracle. All Rights Reserved.
登陆第一个节点，查看gv$session
SQL> select event,count(*) from gv$session where INST_ID=2 group by event order by 2;
EVENT COUNT(*)
---------------------------------------------------------------- ----------
DIAG idle wait 1
PX Deq: reap credit 1
Streams AQ: waiting for time management or cleanup tasks 1
pmon timer 1
ges remote message 1
smon timer 1
Streams AQ: qmn coordinator idle wait 1
Streams AQ: qmn slave idle wait 1
gcs remote message 2
jobq slave wait 2
rdbms ipc message 13
SQL*Net message from client 24
cursor: pin S wait on X 38
13 rows selected.
发现第二个节点正在经历严重的cursor: pin S wait on X，
Dedicated模式下用户连接数据库的时候需要一系列递归调用，倘若系统此时正在经历严重的latch contention，则会一直hang在那里。
现在初步怀疑由于cursor: pin S wait on X导致新的数据库连接无法完成authentication所致
重新回到第二个节点进行hanganglyze分析
justin19.prod2> sqlplus -prelim / as sysdba
SQL*Plus: Release 10.2.0.2.0 - Production on Thu May 3 11:03:32 2012
Copyright (c) 1982, 2005, Oracle. All Rights Reserved.
SQL> oradebug setmypid
Statement processed.
SQL> oradebug hanganalyze 3
Hang Analysis in /oralog/prod/dump/prod2_ora_2258.trc
==============
HANG ANALYSIS:
==============
Open chains found:
Other chains found:
Chain 1 :
<1/259/531/0xb14b86a0/3794/cursor: pin S wait on X>
Chain 2 :
<1/261/188/0xb14b7eb8/21153/cursor: pin S wait on X>
Chain 3 :
<1/263/17/0xb14b76d0/6030/cursor: pin S wait on X>
Chain 4 :
<1/265/9/0xb14b6700/2878/cursor: pin S wait on X>
Chain 5 :
<1/267/735/0xb14b6ee8/3981/cursor: pin S wait on X>
Chain 6 :
<1/269/25/0xb14b5f18/14917/cursor: pin S wait on X>
Chain 7 :
<1/271/447/0xb14b5730/14151/cursor: pin S wait on X>
Chain 8 :
<1/273/36/0xb14b4f48/7907/cursor: pin S wait on X>
Chain 9 :
<1/275/16/0xb14b4760/5699/cursor: pin S wait on X>
Chain 10 :
<1/277/1916/0xb14b3790/740/cursor: pin S wait on X>
Chain 11 :
<1/280/11476/0xb14b3f78/3879/cursor: pin S wait on X>
Chain 12 :
<1/282/1130/0xb14b27c0/17264/cursor: pin S wait on X>
Chain 13 :
<1/283/7025/0xb14b2fa8/28329/cursor: pin S wait on X>
Chain 14 :
<1/285/568/0xb14b1fd8/2203/cursor: pin S wait on X>
Chain 15 :
<1/287/42/0xb14b17f0/16978/cursor: pin S wait on X>
Chain 16 :
<1/289/47/0xb14b0820/14427/cursor: pin S wait on X>
Chain 17 :
跟踪文件显示该instance正在经历严重的cursor: pin S wait on X，和上一步的检查结果吻合。
随便挑两个process验证一下
SQL> oradebug setospid 3981
Oracle pid: 84, Unix process pid: 3981, image: oracleprod2@justin19
SQL> oradebug dump errorstack 3
Statement processed.
SQL> oradebug tracefile_name
/oralog/prod/dump/prod2_ora_3981.trc
SQL> oradebug setospid 14917
Oracle pid: 82, Unix process pid: 14917, image: oracleprod2@justin19
SQL> oradebug dump errorstack 3
Statement processed.
SQL> oradebug tracefile_name
/oralog/prod/dump/prod2_ora_14917.trc
/oralog/prod/dump/prod2_ora_3981.trc
=====================
PARSING IN CURSOR #1 len=564 dep=1 uid=0 ct=2 lid=0 tim=5636868599224 hv=1232072917 ad='ab10b7e8'
insert into sys.aud$( sessionid,entryid,statement,ntimestamp#, userid,userhost,terminal,action#,returncode, obj$creator,obj$name,auth$privileges,auth$grantee, new$owner,new$name
,ses$actions,ses$tid,logoff$pread, logoff$lwrite,logoff$dead,comment$text,spare1,spare2, priv$used,clientid,sessioncpu,proxy$sid,user$guid, instance#,process#,xid,scn,auditid,s
qlbind,sqltext) values(:1,:2,:3,SYS_EXTRACT_UTC(SYSTIMESTAMP), :4,:5,:6,:7,:8, :9,:10,:11,:12, :13,:14,:15,:16,:17, :18,:19,:20,:21,:22, :23,:24,:25,:26,:27,
:28,:29,:30,:31,:32,:33,:34)
END OF STMT
PARSE #1:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=5636868599220
EXEC #1:c=10000,e=1843,p=0,cr=1,cu=4,mis=0,r=1,dep=1,og=4,tim=5636868604632
=====================
PARSING IN CURSOR #4 len=488 dep=1 uid=5 ct=42 lid=5 tim=5636868608097 hv=888628443 ad='a2b62b78'
ALTER SESSION SET NLS_LANGUAGE= 'AMERICAN' NLS_TERRITORY= 'AMERICA' NLS_CURRENCY= '$' NLS_ISO_CURRENCY= 'AMERICA' NLS_NUMERIC_CHARACTERS= '.,' NLS_CALENDAR= 'GREGORIAN' NLS_DATE_FORMAT= 'DD-MON-RR' NLS_DATE_LANGUAGE= 'AMERICAN' NLS_SORT= 'BINARY' TIME_ZONE= '+08:00' NLS_COMP= 'BINARY' NLS_DUAL_CURRENCY= '$' NLS_TIME_FORMAT= 'HH.MI.SSXFF AM' NLS_TIMESTAMP_FORMAT= 'DD-MON-RR HH.MI.SSXFF AM' NLS_TIME_TZ_FORMAT= 'HH.MI.SSXFF AM TZR' NLS_TIMESTAMP_TZ_FORMAT= 'DD-MON-RR HH.MI.SSXFF AM TZR'
END OF STMT
PARSE #4:c=0,e=3017,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=5636868608093
EXEC #4:c=0,e=329,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=5636868608512
*** 2012-05-03 11:04:21.573
Received ORADEBUG command 'dump errorstack 3' from process Unix process pid: 2258, image:
*** 2012-05-03 11:04:21.575
ksedmp: internal or fatal error
No current SQL statement being executed.
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
ksedmp()+716 CALL ksedst() FFFFFFFF7FFEFCC0 ?
000000000 ? 0FFFFFFFF ?
FFFFFFFF7FFEEE68 ?
FFFFFFFF7FFF05C0 ?
000000008 ?
ksdxfdmp()+2224 PTR_CALL 0000000000000000 000000002 ? 10638A8CC ?
000000001 ? 000000000 ?
10638A000 ? 10638A8CC ?
ksdxcb()+2452 PTR_CALL 0000000000000000 000105400 ? 100E55E00 ?
106385298 ?
FFFFFFFF7FFF45A8 ?
1055F0750 ? 100E55E00 ?
/oralog/prod/dump/prod2_ora_14917.trc
PARSING IN CURSOR #1 len=564 dep=1 uid=0 ct=2 lid=0 tim=5635354056881 hv=1232072917 ad='ab10b7e8'
insert into sys.aud$( sessionid,entryid,statement,ntimestamp#, userid,userhost,terminal,action#,returncode, obj$creator,obj$name,auth$privileges,auth$grantee, new$owner,new$name
,ses$actions,ses$tid,logoff$pread, logoff$lwrite,logoff$dead,comment$text,spare1,spare2, priv$used,clientid,sessioncpu,proxy$sid,user$guid, instance#,process#,xid,scn,auditid,s
qlbind,sqltext) values(:1,:2,:3,SYS_EXTRACT_UTC(SYSTIMESTAMP), :4,:5,:6,:7,:8, :9,:10,:11,:12, :13,:14,:15,:16,:17, :18,:19,:20,:21,:22, :23,:24,:25,:26,:27,
:28,:29,:30,:31,:32,:33,:34)
END OF STMT
PARSE #1:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=5635354056877
EXEC #1:c=0,e=17196,p=1,cr=2,cu=6,mis=0,r=1,dep=1,og=4,tim=5635354077836
=====================
PARSING IN CURSOR #4 len=83 dep=1 uid=37 ct=42 lid=37 tim=5635354078496 hv=3678277859 ad='aa71c630'
ALTER SESSION SET TIME_ZONE='+0:00' NLS_LANGUAGE='AMERICAN' NLS_TERRITORY='AMERICA'
END OF STMT
PARSE #4:c=0,e=142,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=5635354078488
EXEC #4:c=0,e=258,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=5635354078866
*** 2012-05-03 11:05:15.100
Received ORADEBUG command 'dump errorstack 3' from process Unix process pid: 2258, image:
*** 2012-05-03 11:05:15.102
ksedmp: internal or fatal error
No current SQL statement being executed.
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
ksedmp()+716 CALL ksedst() FFFFFFFF7FFEFCC0 ?
000000000 ? 0FFFFFFFF ?
FFFFFFFF7FFEEE68 ?
FFFFFFFF7FFF05C0 ?
000000008 ?
ksdxfdmp()+2224 PTR_CALL 0000000000000000 000000002 ? 10638A8CC ?
000000001 ? 000000000 ?
10638A000 ? 10638A8CC ?
ksdxcb()+2452 PTR_CALL 0000000000000000 000105400 ? 100E55E00 ?
106385298 ?
FFFFFFFF7FFF45A8 ?
1055F0750 ? 100E55E00 ?
进一步验证了先前的推测
问题是现在该怎么办，总共有37个session在等待cursor: pin S wait on X，难道要全部kill？
应该没这么麻烦，只需找到最早登陆的session，它应该是一系列latch等待的blocker
--节点1
SQL> select sid,serial#,LOGON_TIME from gv$session where INST_ID=2 and event='cursor: pin S wait on X' order by 3;
SID SERIAL# LOGON_TIME
---------- ---------- -------------------
333 22715 2012-04-26 04:44:07
327 24054 2012-04-26 04:49:34
330 38061 2012-04-26 05:02:38
324 53 2012-04-26 05:11:26
323 94 2012-04-26 05:15:00
321 338 2012-04-26 05:29:31
318 1047 2012-04-26 06:43:49
315 1160 2012-04-26 10:09:18
316 2792 2012-04-26 10:41:45
311 5712 2012-04-26 23:55:39
309 1578 2012-04-27 03:06:40
305 13682 2012-04-29 14:28:03
313 34990 2012-04-30 09:23:34
307 40237 2012-04-30 09:54:48
301 924 2012-04-30 13:35:33
295 13199 2012-05-02 05:11:36
298 11061 2012-05-02 10:03:51
294 596 2012-05-02 11:02:06
303 5906 2012-05-02 11:09:54
293 148 2012-05-02 11:16:02
291 162 2012-05-02 11:23:27
289 47 2012-05-02 11:25:20
287 42 2012-05-02 11:26:44
285 568 2012-05-02 11:50:23
282 1130 2012-05-02 12:47:26
283 7025 2012-05-03 04:43:21
277 1916 2012-05-03 09:12:35
280 11476 2012-05-03 09:14:18
275 16 2012-05-03 09:15:32
273 36 2012-05-03 09:16:28
271 447 2012-05-03 09:35:40
269 25 2012-05-03 09:36:00
265 9 2012-05-03 10:01:15
267 735 2012-05-03 10:01:51
263 17 2012-05-03 10:02:55
261 188 2012-05-03 10:10:48
259 531 2012-05-03 10:33:02
256 449 2012-05-03 11:18:32
--节点2
justin19.prod2> ps -ef | grep 1021
ora102 17697 28975 0 11:28:13 pts/10 0:00 more /oralog/prod/dump/prod2_ora_10212.trc
ora102 21136 11932 0 11:30:04 pts/12 0:00 grep 1021
ora102 10212 1 0 Apr 26 ? 0:03 oracleprod2 (LOCAL=NO)
justin19.prod2> kill -9 10212
过了几秒钟，所有cursor: pin S wait on X消失，节点2可以正常登陆
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/15480802/viewspace-722658/ ，如需转载，请注明出处，否则将追究法律责任。
