library cache pin,cursor: pin S wait on X死锁等待案例分析
监控平台自昨天下午7点开始突然dbtime告警，我们从监控平台开基本保持在20000多的dbtime,出于习惯我们生成了一个15分钟的ash报告，从报告看严重的等待事件为
并发cursor: pin S wait on X等待，涉及的SQL如下：
sql_id 96d0kw768b94d :
BEGIN my_proc(:1 , :2 , :3 , :4 ); END;
看来是调用存储过程my_proc时，被阻塞了从等待事件cursor: pin S wait on X看应该是有用户在持有对象my_proc的X锁
我尝试做个统计，看看到底那个BLOCKING_SESSION造成了阻塞
SQL> select sql_id,event,blocking_session ,count(*) from v$active_session_history where sample_time>to_date('202107080900','yyyymmddhh24miss')
and event like 'cursor%' group by sql_id,event,blocking_session order by count(*);
SQL_ID EVENT BLOCKING_SESSION COUNT(*)
------------- ------------------------------ ---------------- ----------
7vxbjpbngxjyx cursor: pin S wait on X 493 1
96d0kw768b94d cursor: pin S wait on X 1314 249365
96d0kw768b94d cursor: pin S wait on X 2915 399464
从上述看 1314和2915阻塞了559个会话，用户等待事件为cursor: pin S wait on X，下面看1314和2915在等什么？我们的目的是找到阻塞源
SQL> select username,sid,program ,machine,sql_id,event,blocking_session,status from v$session where sid in (1314,2915)
USERNAME SID PROGRAM MACHINE SQL_ID EVENT BLOCKING_SESSION STATUS
---------- ---------- -------------------- -------------------- ------------- ------------------------------ ---------------- --------
QLXXH 1314 JDBC Thin Client GCJS-YY-T097091 96d0kw768b94d library cache pin 1098 ACTIVE
QLXXH 2915 JDBC Thin Client GCJS-YY-T097091 96d0kw768b94d cursor: pin S wait on X 1314 ACTIVE
这里发现1314被1098阻塞，而2915被1314阻塞，继续查1089
select sid, sql_id,event,blocking_session,status from v$session where sid in (1098);
SQL> select username,sid,program ,machine,sql_id,event,blocking_session,status from v$session where sid in(1098);
USERNAME SID PROGRAM MACHINE SQL_ID EVENT BLOCKING_SESSION STATUS
---------- ---------- -------------------- -------------------- ------------- ------------------------------ ---------------- --------
QLXXH 1098 JDBC Thin Client GCJS-YY-T097091 96d0kw768b94d cursor: pin S wait on X 1314 ACTIVE
1098阻塞1034此时1034等待library cache pin，1034阻塞1098此时1098等待cursor: pin S wait on X，说明此时1034会话于1098会话发生了死锁，进而导致
1034阻塞了2915， 1034和2915阻塞了其他559个会话。
我们不断调用如下查询，kill相关阻塞会话。
select 'alter system kill session '''||sid||','||serial#||''';' from v$session where sid in (select blocking_session from v$session where
blocking_session is not null and event like 'cursor: pin S%');
从等待事件分析，应该是1098会话持有X锁，正常应该是改会话编译存储过程，也就是存储过程可能失效了，下面我们从改存储过程涉及的对象，看看有没有对象导致改
存储过程失效。
SQL> select object_name,owner,object_type,status from dba_objects where object_name='my_proc';
OBJECT_NAME OWNER OBJECT_TYPE STATUS
---------------------------------------- -------------------- ----------------------- -------
my_proc QLXXH PROCEDURE INVALID
上述查询说明存储过程失效，我们尝试重新编译改存储过程，依然被卡住，由于当时业务需要，我们先建议重新创建一个存储过程，修改应用，这个操作大概30分钟就完成
经过应用测试发现此时的连接正常，dbtime基本保持在1000左右，但是为什么依然有阻塞呢？ 我们建议用户停止所有调用之前老的存储过程的模块和所有直连，或者我们直接
从数据库层面kill，当用户同意时，我们还是从数据库层面有杀了一遍相关进程。但是随后我们发现用户的操作是不靠谱的，依然会有用户调用之前的存储过程，阻塞跟之前一样
这里问题已经不严重了，毕竟大量用户使用了新的存储过程，其实对于复杂应用或者长期运行的系统，找个十分熟悉业务模块的人确实很难我们DBA就是在这种环境下尽量用自己
的判断不断去推进解决问题。
我们继续分析编译过程的阻塞，会话执行编译指令卡主，现象如下所示。
SQL> alter procedure QLXXH.my_proc compile;
新开会话查询1318会话等待事件为library cache lock
SQL> select sid,saddr,event,status from v$session where sid=1318
SID SADDR EVENT STATUS
---------- ---------------- ------------------------------ --------
1318 00000003017D2808 library cache lock ACTIVE
查询申请锁的对象和申请状态以及handle address
SQL> select kgllkhdl Handle,kgllkreq Request, kglnaobj Object from x$kgllk where kgllkses ='00000003017D2808' and kgllkreq > 0;
HANDLE REQUEST OBJECT
-------------------- ------- ----------------------------------------------------------------------
0000000504CFE0C8 3 my_proc
这里REQUEST > 0说明是申请过程，对象为my_proc，就是我们编译的存储过程。
下面通过HANDLE 地址看谁持有library cache lock，
select kgllkses saddr,kgllkhdl handle,kgllkmod mod,kglnaobj object
from x$kgllk lock_a
where kgllkmod > 0
and exists (select lock_b.kgllkhdl from x$kgllk lock_b
where kgllkses = '00000003116AE880' /* blocked session */
and lock_a.kgllkhdl = lock_b.kgllkhdl
and kgllkreq > 0);
下面我们依然看到用户连接旧的存储过程。这个问题我们没有必要跟用户纠结了，告诉他们就可以，这里还是要分析阻塞源，终编译好旧的存储过程，这样复杂应用
的问题旧解决了，这也是用户愿意看到的问题。
SQL>select sid,username,terminal,program,status from v$session where saddr in (select kgllkses from x$kgllk lock_a
2* where kgllkmod > 0 and kglnaobj like '%my_proc%')
SID USERNAME TERMINAL PROGRAM STATUS
---------- ---------- ---------- ----------------------------------- --------
1318 SYS pts/6 sqlplus@n-pc-sr850-305 (TNS V1-V3) ACTIVE
2468 QLXXH unknown JDBC Thin Client ACTIVE
1732 QLXXH unknown JDBC Thin Client ACTIVE
2091 QLXXH unknown JDBC Thin Client ACTIVE
1035 QLXXH unknown JDBC Thin Client ACTIVE
2506 QLXXH unknown JDBC Thin Client ACTIVE
2705 QLXXH unknown JDBC Thin Client ACTIVE
1389 QLXXH unknown JDBC Thin Client ACTIVE
629 QLXXH unknown JDBC Thin Client ACTIVE
2405 QLXXH unknown JDBC Thin Client ACTIVE
10 rows selected.
查询更详细的等待信息
SQL> select sid,username,terminal,program,status,event,blocking_session from v$session where saddr in (select kgllkses from x$kgllk lock_a
where kgllkmod > 0 and kglnaobj like '%my_proc%')
SID USERNAME TERMINAL PROGRAM STATUS EVENT BLOCKING_SESSION
---------- ---------- ---------- ----------------------------------- -------- ------------------------------ ----------------
1318 SYS pts/6 sqlplus@n-pc-sr850-305 (TNS V1-V3) ACTIVE library cache pin 1098
2468 QLXXH unknown JDBC Thin Client ACTIVE cursor: pin S wait on X 2405
1732 QLXXH unknown JDBC Thin Client ACTIVE cursor: pin S wait on X 2405
2091 QLXXH unknown JDBC Thin Client ACTIVE cursor: pin S wait on X 2405
1035 QLXXH unknown JDBC Thin Client ACTIVE cursor: pin S wait on X 2405
2506 QLXXH unknown JDBC Thin Client ACTIVE cursor: pin S wait on X 2405
2705 QLXXH unknown JDBC Thin Client ACTIVE cursor: pin S wait on X 2405
1389 QLXXH unknown JDBC Thin Client ACTIVE cursor: pin S wait on X 2405
629 QLXXH unknown JDBC Thin Client ACTIVE cursor: pin S wait on X 2405
2405 QLXXH unknown JDBC Thin Client ACTIVE library cache lock 1318
10 rows selected.
发现1098阻塞了1318,1318阻塞了2405,2405阻塞了其他会话，终又看到了1098会话（怀疑开始这个会话没有kill成功）
逐步kill会话
SQL> select sid,username,terminal,program,status,event,blocking_session,blocking_session_status from v$session where saddr in (select kgllkses from x$kgllk lock_a where kgllkmod > 0 and kglnaobj like '%my_proc%')
SID USERNAME TERMINAL PROGRAM STATUS EVENT BLOCKING_SESSION BLOCKING_SESSION_STATUS
---------- ---------- ---------- -------------------- -------- ------------------------------ ---------------- ------------------------------
2091 QLXXH unknown JDBC Thin Client ACTIVE library cache pin 1098 VALID
后发现1098会话是阻塞源，状态为valid，而其造成阻塞的等待事件为 library cache pin 说明1098会话持有pin锁，阻塞了1318也就是我们尝试编译存储过程的会话，
2045会话向持有library cache lock，被1318阻塞，其他会话被2045阻塞等待事件为cursor: pin S wait on X ，此时的阻塞源就是1098，其持有pin锁，一直没有释放。
说明：library cache lock是保护对象的handle , library cache pin是保护对象的heap.
下面尝试kill会话1098，发现不在本实例
SQL> alter system kill session '1098,40291';
alter system kill session '1098,40291'
*
ERROR at line 1:
ORA-00030: User session ID does not exist.
分析1098会话被阻塞
SQL> select sql_id,event,blocking_session,count(*) from dba_hist_active_sess_history where session_id=1098 and user_id=151
2 group by sql_id,event,blocking_session order by count(*);
SQL_ID EVENT BLOCKING_SESSION COUNT(*)
------------- ------------------------------ ---------------- ----------
96d0kw768b94d cursor: pin S wait on X 366 198
96d0kw768b94d cursor: pin S wait on X 1314 436
96d0kw768b94d cursor: pin S wait on X 838 539
96d0kw768b94d cursor: pin S wait on X 1354 539
96d0kw768b94d cursor: pin S wait on X 1448 539
96d0kw768b94d cursor: pin S wait on X 2915 539
96d0kw768b94d cursor: pin S wait on X 265 540
7 rows selected.
这里我们可以确定又发生了死锁，这里并发导致的行为，下面kill阻塞会话。
SQL> select sid,serial#,sql_id ,status,event,username from v$session where sid in (366,1314,838,1354,1448,2915,265)
SID SERIAL# SQL_ID STATUS EVENT USERNAME
---------- ---------- ------------- -------- ------------------------------ ------------------------------
838 2575 INACTIVE SQL*Net message from client JJJCHENJIANG
1314 760 INACTIVE SQL*Net message from client DFQLXXH
1354 20618 INACTIVE SQL*Net message from client DFGGZX
SQL> alter system kill session '1354,20618';
System altered.
SQL> select kgllkses saddr,kgllkhdl handle,kgllkmod mod,kglnaobj object from x$kgllk lock_a where kgllkmod > 0 and kglnaobj like '%my_proc%';
SADDR HANDLE MOD OBJECT
---------------- -------------------- ---------- ----------------------------------------------------------------------
00000003018D3760 0000000504CFE0C8 3 my_proc
00000003018D3760 0000000107C99878 1 BEGIN my_proc(:1 , :2 , :3 , :4 ); END;
00000003018D3760 0000000103CC48A0 1 BEGIN my_proc(:1 , :2 , :3 , :4 ); END;
后来我们发现在第二个实例上该会话为ACTIVE，发现1098会话始终没有退出，我们在第二个实例上kill改会话。
SQL> select sid,serial#,status,blocking_session,event,sql_id,INST_ID,username,program,saddr from gv$session where sid=1098
SID SERIAL# STATUS BLOCKING_SESSION EVENT SQL_ID INST_ID USERNAME PROGRAM SADDR
---------- ---------- -------- ---------------- -------------------- ------------- ---------- ---------- -------------------- ----------------
1098 24452 ACTIVE single-task message 16v5r29vjusvn 2 QLXXH JDBC Thin Client 00000003116AE880
此时改会话已经没有阻塞会话
下面查询连接信息，以供业务用户查询，阵列os用户是admin不是oracle所以应该还是有其他业务模块连接到了数据库，执行查询但是不断发生死锁。
SQL> select s.sid,p.spid,osuser,s.program from v$session s,v$process p where s.paddr=p.addr and s.sid=1098
SID SPID OSUSER PROGRAM
---------- ------------------------ -------------------- ------------------------------
1098 275591 admin JDBC Thin Client
后我们编译，编译成功。
SQL> alter procedure QLXXH.my_proc compile;
Procedure altered.
分析总结：按照理论存储过程重新编译肯定是又失效对象，即用户在存储过程涉及的表上又ddl操作，如增减字段，修改数据类型，在反复追问下，用户承认
从昨晚7点开始增加了一个字段，之后就造成的dbtime超过阈值的告警。即死锁造成队列锁，而每一个用户连接数据库需要首先调用改存储过程，而DDL造成存储
过程失效，并发用户访问时又需要重新编译，造成死锁导致，虽然我们在个节点kill所有会话，但是发现依然无法编译成功，因为第二个节点的用户依然因为死锁
持有pin锁，这是典型的并发操作造成，也就是不断的有用户上来，或者其他模块调用上来，造成死锁一直有，终我们在一，二节点kill所有会话，PIN锁释放，
旧的存储过程编译成功，用户后续修改回旧的存储过程，至此问题解决！
相关文章