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

时间：2021-11-25 22:55:14

转自：http://blog.itpub.net/195110/viewspace-688790/

 

下午接到维护发来的邮件，大体内存如下：

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就好了,有的说修改了某某参数就ＯＫ了。其实只要我们注意日常在生产库中的操作和维护，排除掉人为的因素，这样的问题是很少会出现的。

 

标签：

相关文章