一次cursor: pin S wait on X事件的跟蹤

        下午接到維護髮來的郵件，大體記憶體如下：

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就好了,有的說修改了某某引數就ＯＫ了。其實只要我們注意日常在生產庫中的操作和維護，排除掉人為的因素，這樣的問題是很少會出現的。