一次大量enq: TX - row lock contention锁等待的问题 - 数据库

sjk2013

浏览: 2186058 次

最近访客更多访客>>

BDQN磊

w11h22j33

devcang

hedgehog12

博主相关

博客

微博

相册

留言

关于我

文章分类

全部博客 (3465)

社区版块

存档分类

2014-05 ( 13)
2014-04 ( 74)
2014-03 ( 72)
更多存档...

一次大量enq: TX - row lock contention锁等待的问题

今天下午接到业务报障，系统出现问题，可能是数据库的问题
1，登录系统,查看等待事件，大量row lock

6:12:58]
[16:12:58] SID SERIAL# OSUSER USERNAME SVRPROC SQL_HASH_VALUE EVENT P1 P2 P3
[16:12:58]------ ---------- -------- -------- ------------------------ -------------- ------------------------------ --------------------- ---------- ----------
[16:12:58] 245 4637 app SOi 41353726 3961605653 db file sequential read 226 253846 1
[16:12:58] 3645 58373 app SOi 61604288 1523472697 db file sequential read 178 3443786 1
[16:12:58] 5651 26047 app PAR 64291328 2455471834 db file sequential read 142 2712414 1
[16:12:58] 13207 5781 app SOi 62915316 3349830783 db file sequential read 211 1462130 1
[16:12:58] 10198 64603 app PAR 45679292 2510471152 db file sequential read 91 2141228 1
[16:12:58] 11528 8197 app PAR 51708698 2284416154 db file sequential read 126 1683178 1
[16:12:58] 8863 53455 baoyb AIM 16319376 1467486395 db file sequential read 115 2078933 1
[16:12:58] 1 59191 app SOi 46072062 2644787661 enq: TX - row lock contention 1415053318 21889041 50009
[16:12:58] 22 26111 app SOi 48694114 3874015681 enq: TX - row lock contention 1415053318 21889041 50009
[16:12:58] 39 38595 AIC SOi 7210748 208342339 enq: TX - row lock contention 1415053318 21889041 50009
[16:12:58] 62 56753 AIC SOi 29426814 1088173244 enq: TX - row lock contention 1415053318 21889041 50009
[16:12:58]
[16:12:58] SID SERIAL# OSUSER USERNAME SVRPROC SQL_HASH_VALUE EVENT P1 P2 P3
[16:12:58]------ ---------- -------- -------- ------------------------ -------------- ------------------------------ --------------------- ---------- ----------
[16:12:58] 66 42397 app SOi 48366550 1088173244 enq: TX - row lock contention 1415053318 32047109 25967
[16:12:58] 189 52823 AIC SOi 38404948 208342339 enq: TX - row lock contention 1415053318 21889041 50009
[16:12:58] 212 451 app SOi 42402934 673329617 enq: TX - row lock contention 1415053318 21889041 50009
[16:12:58] 232 55865 app SOi 21956094 673329617 enq: TX - row lock contention 1415053318 21889041 50009
[16:12:58] 240 701 AIC SOi 42991652 208342339 enq: TX - row lock contention 1415053318 21889041 50009
[16:12:58] 247 6333 app SOi 5375522 3538716681 enq: TX - row lock contention 1415053318 21889041 50009
[16:12:58] 388 17499 app SOi 42140914 1763411819 enq: TX - row lock contention 1415053318 21889041 50009
[16:12:58] 389 50591 app SOi 33292644 208342339 enq: TX - row lock contention

2，使用锁等待的脚本查看，holder比较多，难以判断根源的holder

[16:16:03]SESS                                                     ID1        ID2      LMODE    REQUEST TY
[16:16:03]------------------------------------------------- ---------- ---------- ---------- ---------- --
[16:16:03]Holder:  7205                                       21037088      51133          6          0 TX
[16:16:03]Waiter: 14692                                       21037088      51133          0          6 TX
[16:16:03]Waiter: 6246                                        21037088      51133          0          6 TX
[16:16:03]Waiter: 1190                                        21037088      51133          0          6 TX
[16:16:03]Holder:  12643                                      21299226      52395          6          0 TX
[16:16:03]Waiter: 3820                                        21299226      52395          0          6 TX
[16:16:03]Waiter: 10197                                       21299226      52395          0          6 TX
[16:16:03]Waiter: 1926                                        21299226      52395          0          6 TX
[16:16:03]Holder:  7169                                       21561365      54540          6          0 TX
[16:16:03]Waiter: 13929                                       21561365      54540          0          6 TX
[16:16:03]Waiter: 1562                                        21561365      54540          0          6 TX
[16:16:03]
[16:16:03]SESS                                                     ID1        ID2      LMODE    REQUEST TY
[16:16:03]------------------------------------------------- ---------- ---------- ---------- ---------- --
[16:16:03]Waiter: 9080                                        21561365      54540          0          6 TX
[16:16:03]Holder:  8863                                       21889041      50009          6          0 TX
[16:16:03]Waiter: 14914                                       21889041      50009          0          6 TX
[16:16:03]Waiter: 14911                                       21889041      50009          0          6 TX
[16:16:03]Waiter: 14902                                       21889041      50009          0          6 TX
[16:16:03]Waiter: 14882                                       21889041      50009          0          6 TX
[16:16:03]Waiter: 14872                                       21889041      50009          0          6 TX
[16:16:03]Waiter: 14865                                       21889041      50009          0          6 TX
[16:16:03]Waiter: 14721                                       21889041      50009          0          6 TX

3，由于是rac，做一个全局的HANGANALYZE

[16:16:57]SQL> ORADEBUG setmypid
[16:16:57]Statement processed.
[16:17:02]SQL>  ORADEBUG setinst all
[16:17:03]Statement processed.
[16:17:07]SQL> ORADEBUG -g def hanganalyze 3
[16:17:26]Hang Analysis in /oracle/diag/rdbms/yydb/yydb1/trace/yydb1_diag_4260840.trc

4，此时被阻塞的语句是大量update

16:17:35]SQL_ID        PCTLOAD  CPU OTHER   IO SQL_TEXT
[16:17:35]------------- ------- ---- ----- ---- ----------------------------------------------------------------------------------------------------
[16:17:35]9bxujnufu8hfd      17    0   100    0 update INS__100 set STATE = :1 ,DONE_DATE = :2  where   ROWID = :3
[16:17:35]8vcrwd10dsd5w      15    0   100    0 update INS__101 set STATE = :1 ,DONE_DATE = :2  where   ROWID = :3
[16:17:35]777xsjn66q3a3      10    0   100    0 update INS__102 set STATE = :1 ,DONE_DATE = :2  where   ROWID = :3
[16:17:35]3xng1922jhqdx      10    0   100    0 update INS__103 set STATE = :1 ,DONE_DATE = :2  where   ROWID = :3
[16:17:35]5g2gyxwn24cfj       8    0   100    0 update INS__100 set OP_ID = :1 ,STATE = :2 ,DONE_DATE = :3  where   ROWID = :4
[16:17:35]ac17casyksfka       5    0   100    0 update INS__100 set EXPIRE_DATE = :1 ,EFFECTIVE_DATE = :2 ,STATE = :3 ,COUNTY_CODE = :4 ,DONE_DA
[16:17:35]7pdp5zfbc7bh5       4    0   100    0 update INS__104 set STATE = :1 ,DONE_DATE = :2  where   ROWID = :3
[16:17:35]024cfqtnjr1vb       3    0   100    0 update INS__103 set EXPIRE_DATE = :1 ,EFFECTIVE_DATE = :2 ,OP_ID = :3 ,STATE = :4 ,COUNTY_CODE =
[16:17:35]24m4b9jfqn2zm       2    0   100    0 update INS__101 set EXPIRE_DATE = :1 ,EFFECTIVE_DATE = :2 ,OP_ID = :3 ,STATE = :4 ,COUNTY_CODE =
[16:17:35]8vm3vv2t6ymv6       2    0   100    0 update INS__102 set STATE = :1 ,OP_ID = :2 ,DONE_DATE = :3  where   ROWID = :4
[16:17:35]cnq4y75v772af       2    0   100    0 update INS__103 set EXPIRE_DATE = :1 ,EFFECTIVE_DATE = :2 ,STATE = :3 ,COUNTY_CODE = :4 ,DONE_DA

5，查看HANGANALYZE log的内容，339 sessions被sid=8863的进程阻塞

.......
Chains most likely to have caused the hang:
 [a] Chain 1 Signature: 'db file scattered read'<='enq: TX - row lock contention'
     Chain 1 Signature Hash: 0x13c8fc65
 [b] Chain 2 Signature: 'db file scattered read'<='enq: TX - row lock contention'
     Chain 2 Signature Hash: 0x13c8fc65
 [c] Chain 3 Signature: 'db file scattered read'<='enq: TX - row lock contention'
     Chain 3 Signature Hash: 0x13c8fc65

===============================================================================
Non-intersecting chains:

-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (yydb.yydb1)
                   os id: 46072062
              process id: 320, oracle@scyydb1
              session id: 1
        session serial #: 59191
    }
    is waiting for 'enq: TX - row lock contention' with wait info:
    {
                      p1: 'name|mode'=0x54580006
                      p2: 'usn<<16 | slot'=0x14e0011
                      p3: 'sequence'=0xc359
            time in wait: 73 min 18 sec
           timeout after: never
                 wait id: 5488
                blocking: 0 sessions
             current sql: update INS_ set STATE = :1 ,DONE_DATE = :2  where   ROWID = :3
             short stack: ksedsts()+644<-ksdxfstk()+44<-ksdxcb()+3384<-sspuser()+116<-47dc<-sskgpwwait()+32<-skgpwwait()+180<-ksliwat()+11032<-kslwaitctx()+1
80<-kjusuc()+3652<-ksipgetctxi()+1892<-ksqcmi()+21888<-ksqgtlctx()+2904<-ksqgelctx()+660<-ktuGetTxForXid()+184<-ktcwit1()+456<-IPRA.$kdddgb()+6860<-kdddgb()+
96<-kdusru()+8516<-updrowFastPath()+1192<-qerupFetch()+2596<-updaul()+1100<-updThreePhaseExe()+336<-updexe()+344<-opiexe()+14476<-kpoal8()+4616<-opiodr()+720
<-ttcpip()+1028<-opitsk()+1508<-opiino()+940<-opiodr()+720<-opidrv()+1132<
            wait history:
              * time between current wait and wait #1: 0.000401 sec
              1.       event: 'SQL*Net message from client'
                 time waited: 0.000596 sec
                     wait id: 5487            p1: 'driver id'=0x28444553
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000008 sec
              2.       event: 'SQL*Net message to client'
                 time waited: 0.000002 sec
                     wait id: 5486            p1: 'driver id'=0x28444553
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000117 sec
              3.       event: 'db file sequential read'
                 time waited: 0.007607 sec
                     wait id: 5485            p1: 'file#'=0xa2
                                              p2: 'block#'=0x112360
                                              p3: 'blocks'=0x1
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (yydb.yydb1)
                   os id: 16319376
              process id: 1567, oracle@scyydb1
              session id: 8863
        session serial #: 53455
    }
    which is waiting for 'db file scattered read' with wait info:
    {
                      p1: 'file#'=0xc4
                      p2: 'block#'=0x26d37c
                      p3: 'blocks'=0x10
            time in wait: 0.000000 sec
           timeout after: never
                 wait id: 6304859
                blocking: 339 sessions
             current sql: update so1.INS__ins t set t.expire_date=to_date('20121231 23:59:59','yyyymmdd hh24:mi:ss') where (t.offer_inst_id,t.use
r_id) in
(select a.offer_inst_id,a.user_id from wlanCPss2 a )
             short stack: ksedsts()+644<-ksdxfstk()+44<-ksdxcb()+3384<-sspuser()+116<-47dc<-poll()+12<-sntpoltsts()+884<-snttmoredata()+52<-nsmore2recv()+246
0<-nioqts()+6588<-ksuttctest()+128<-updrow()+16292<-qerupFetch()+856<-updaul()+1100<-updThreePhaseExe()+336<-updexe()+344<-opiexe()+14476<-kpoal8()+4616<-opi
odr()+720<-ttcpip()+1028<-opitsk()+1508<-opiino()+940<-opiodr()+720<-opidrv()+1132<-sou2o()+136<-opimai_real()+608<-ssthrdmain()+268<-main()+204<-__start()+1
12

6，通过sid定位用户信息，确定为有人用plsql在运行上述sql

SESSION_ID SAMPLE_TIME                                                                 PROGRAM                                          MACHINE
---------- --------------------------------------------------------------------------- ------------------------------------------------ ---------------

      8863 28-SEP-12 03.49.13.605 PM                                                   plsqldev.exe                                     XX-VM-RDS1

7，杀掉了问题sid，系统恢复。问题出在了开发人员在业务高峰期批量更新数据，高峰时间段批量更新数据是大忌！！！！

分享到：