一次cursor: pin S wait on X事件的跟蹤
阿新 • • 發佈：2019-02-02
下午接到維護髮來的郵件，大體記憶體如下：
3月7號晚10點左右，資源管理系統資料庫 gxdb1 發生大量鎖等待，而且出現多個阻塞鎖。活動session數達到350左右， 等待事件為 cursor ： pin s wait on X 。經殺掉相關session後系統恢復正常。 希望找出問題發生的原因。 下面記錄查詢問題的過程： SQL> select * from v$version; BANNER----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bi
PL/SQL Release 10.2.0.4.0 - Production
CORE 10.2.0.4.0 Production
TNS for IBM/AIX RISC System/6000: Version 10.2.0.4.0 - Productio
NLSRTL Version 10.2.0.4.0 - Production SQL> 由於hist_active_sess_history表的資料比較大，把'2011030717' ~ '2011030722' 這個時間段裡的session資料提取出來 SQL> create table temp_hist_active_sess_history nologging as
2 select * from dba_hist_active_sess_history
3 where to_char(sample_time, 'yyyymmddhh24') between '2011030717' and '2011030722'; alter table temp_hist_active_sess_history add record_time varchar2(50);
update temp_hist_active_sess_history set record_time = to_char(sample_time,'yyyy-mm-dd hh24:mi:ss');
commit; ...省略建立index的過程 SQL>col p2 format 9999999999999999 SQL> select distinct session_id,session_serial#,p1,p2
2 from temp_hist_active_sess_history
3 where event ='cursor: pin S wait on X'
4 and rownum<=50; SESSION_ID SESSION_SERIAL# P1 P2
---------- --------------- ---------- -----------------
2861 52370 668057193 19387482374144
4173 62920 668057193 19155554140160
517 28649 3522657913 21333102559232
533 16512 3522657913 21333102559232
606 39602 3522657913 21333102559232
626 14637 3522657913 21333102559232
855 53933 3522657913 21333102559232
1062 46600 3522657913 21333102559232
1249 63282 3522657913 21333102559232
528 35867 3522657913 21333102559232
691 41082 3522657913 21333102559232 SESSION_ID SESSION_SERIAL# P1 P2
---------- --------------- ---------- -----------------
976 56788 3522657913 21333102559232
1196 41756 3522657913 21333102559232
1514 45826 3522657913 21333102559232
1525 16156 3522657913 21333102559232
1633 9783 3522657913 21333102559232
1677 52748 3522657913 21333102559232
933 13220 3522657913 21333102559232
942 17109 3522657913 21333102559232
979 33487 3522657913 21333102559232
1341 14797 3522657913 21333102559232
1398 15817 3522657913 21333102559232 SESSION_ID SESSION_SERIAL# P1 P2
---------- --------------- ---------- -----------------
1441 10065 3522657913 21333102559232
1566 7846 3522657913 21333102559232
1667 62940 3522657913 21333102559232
3794 41447 668057193 19155554140160
549 36165 3522657913 21333102559232
631 9934 3522657913 21333102559232
812 42615 3522657913 21333102559232
934 18908 3522657913 21333102559232
1365 5812 3522657913 21333102559232
1491 41510 3522657913 21333102559232
1539 9132 3522657913 21333102559232 SESSION_ID SESSION_SERIAL# P1 P2
---------- --------------- ---------- -----------------
851 35281 3522657913 21333102559232
1597 48481 3522657913 21333102559232
2824 37947 668057193 19155554140160
2961 17626 668057193 19155554140160
660 30581 3522657913 21333102559232
472 6095 3522657913 21333102559232
881 54009 3522657913 21333102559232
889 14408 3522657913 21333102559232
1098 36953 3522657913 21333102559232
1675 4908 3522657913 21333102559232
1720 46180 3522657913 21333102559232 SESSION_ID SESSION_SERIAL# P1 P2
---------- --------------- ---------- -----------------
640 61791 3522657913 21333102559232
817 13269 3522657913 21333102559232
951 20788 3522657913 21333102559232
970 57853 3522657913 21333102559232
1423 22083 3522657913 21333102559232
1709 10839 3522657913 21333102559232 50 rows selected. 我們來分析p2=21333102559232,前兩個位元組資料為 4967 SQL> select session_id,
2 session_serial#,
3 event,
4 blocking_session,
5 blocking_session_serial#
6 from temp_hist_active_sess_history
7 where session_id = 4967
8 order by record_time; SESSION_ID SESSION_SERIAL# EVENT BLOCKING_SESSION BLOCKING_SESSION_SERIAL#
---------- --------------- ---------------------------------------------------------------- ---------------- ------------------------
4967 12169 library cache pin 2704 36420
4967 12169 library cache pin 2704 36420
4967 12169 library cache pin 2704 36420
4967 12169 library cache pin 2704 36420
4967 12169 library cache pin 2704 36420
4967 12169 library cache pin 2704 36420
4967 12169 library cache pin 2704 36420
4967 12169 library cache pin 2704 36420
4967 12169 library cache pin 2704 36420
4967 12169 library cache pin 2704 36420
4967 12169 library cache pin 2704 36420 ..... SQL> select session_id,
2 session_serial#,
3 event,
4 blocking_session,
5 blocking_session_serial#
6 from temp_hist_active_sess_history
7 where session_id = 2704
8 and session_serial# = 36420; SESSION_ID SESSION_SERIAL# EVENT BLOCKING_SESSION BLOCKING_SESSION_SERIAL#
---------- --------------- ---------------------------------------------------------------- ---------------- ------------------------
2704 36420 enq: TX - row lock contention 3537 32344
2704 36420 enq: TX - row lock contention 3537 32344
2704 36420 enq: TX - row lock contention 3537 32344
2704 36420 enq: TX - row lock contention 3537 32344
2704 36420 enq: TX - row lock contention 3537 32344
2704 36420 enq: TX - row lock contention 3537 32344
2704 36420 enq: TX - row lock contention 3537 32344
2704 36420 enq: TX - row lock contention 3537 32344
2704 36420 enq: TX - row lock contention 3537 32344
2704 36420 enq: TX - row lock contention 3537 32344
2704 36420 enq: TX - row lock contention 3537 32344 這樣迴圈找下去，得到如下 SQL> select session_id,
2 session_serial#,
3 event,
4 blocking_session,
5 blocking_session_serial#,
6 sql_id,
7 program,
8 record_time
9 from temp_hist_active_sess_history
10 where session_id = 3738
11 and session_serial# = 45559
12 order by record_time; .....
SESSION_ID SESSION_SERIAL# EVENT BLOCKING_SESSION BLOCKING_SESSION_SERIAL# SQL_ID PROGRAM RECORD_TIME
---------- --------------- ------------------------------- ---------------- ------------------------ ------------- ---------------- -------------
3738 45559 db file sequential read 8qg7sa3nramwx plsqldev.exe 2011-03-07 17:54:00
3738 45559 8qg7sa3nramwx plsqldev.exe 2011-03-07 17:54:10
3738 45559 8qg7sa3nramwx plsqldev.exe 2011-03-07 17:54:20
3738 45559 8qg7sa3nramwx plsqldev.exe 2011-03-07 17:54:30
3738 45559 8qg7sa3nramwx plsqldev.exe 2011-03-07 17:54:40
3738 45559 8qg7sa3nramwx plsqldev.exe 2011-03-07 17:54:50
3738 45559 8qg7sa3nramwx plsqldev.exe 2011-03-07 17:55:00
3738 45559 8qg7sa3nramwx plsqldev.exe 2011-03-07 17:55:10
3738 45559 8qg7sa3nramwx plsqldev.exe 2011-03-07 17:55:20
3738 45559 8qg7sa3nramwx plsqldev.exe 2011-03-07 17:55:30
3738 45559 8qg7sa3nramwx plsqldev.exe 2011-03-07 17:55:40
....
SESSION_ID SESSION_SERIAL# EVENT BLOCKING_SESSION BLOCKING_SESSION_SERIAL# SQL_ID PROGRAM RECORD_TIME
---------- --------------- ------------------------------- ---------------- ------------------------ ------------- ---------------- ------------
3738 45559 SQL*Net break/reset to client 8qg7sa3nramwx plsqldev.exe 2011-03-07 18:30:57
3738 45559 SQL*Net break/reset to client 8qg7sa3nramwx plsqldev.exe 2011-03-07 18:31:07
3738 45559 SQL*Net break/reset to client 8qg7sa3nramwx plsqldev.exe 2011-03-07 18:31:17
3738 45559 SQL*Net break/reset to client 8qg7sa3nramwx plsqldev.exe 2011-03-07 18:31:27
3738 45559 SQL*Net break/reset to client 8qg7sa3nramwx plsqldev.exe 2011-03-07 18:31:37
3738 45559 SQL*Net break/reset to client 8qg7sa3nramwx plsqldev.exe 2011-03-07 18:31:48
現在我們來看看‘8qg7sa3nramwx ’在做什麼 SQL> select to_char(sql_text) from dba_hist_sqltext where sql_id ='8qg7sa3nramwx'
2 ; TO_CHAR(SQL_TEXT)
--------------------------------------------------------------------------------------------------
--------------------------------------------------------------------------------------------------
update rmgz.opt_ocf set ponmark=2 where ponmark is null and ocftype in (8,9)
現在很明顯了：有維護人員在批量更新資料。 opt_ocf是一個比較大的表，裡面ocftype in (8,9)的重複記錄有很多，鎖了很多記錄，造成大量的Lock。 對於負載很大的應用系統，批量更新資料時一定要非常小心。 必須把大批量更新資料放在晚上閒時做或者把大事務劃分成小事務來分批提交. 附： 網上有許多關於cursor: pin S wait on X事件問題的描述，有的說是ＢＵＧ，有的說停用ASMM就好了,有的說修改了某某引數就ＯＫ了。其實只要我們注意日常在生產庫中的操作和維護，排除掉人為的因素，這樣的問題是很少會出現的。