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

原创 2012年09月28日 17:05:02
今天下午接到业务报障,系统出现问题,可能是数据库的问题
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,系统恢复。问题出在了开发人员在业务高峰期批量更新数据,高峰时间段批量更新数据是大忌!!!!

一次数据库相关操作卡住的排查--enq: TX - row lock contention

问题描述:某日客户来电某HR系统排值班表的操作一直HANG住,一直无法完成。 这种问题,主要思路是围绕查看此操作因何HANG住。 常见的严重的HANG住有DB方面的AUDIT无空间、归档空间满以及...

ORACE_常见等待事件001_enq: TX - row lock contention

enq: TX - row lock contention是oracle常见的等待事件之一。enq是一种保护共享资源的锁定机制,一个排队机制,先进先出(FIFO)发生TX锁的原因一般有几个: 1.不...

oracle 11g数据库”enq: TX - row lock contention“等待事件的处理

今天早晨发现数据库出现”enq: TX - row lock contention“等待,记录下处理过程: SQL*Plus: Release 11.2.0.2.0 Production   SI...

enq: TX - row lock contention 等待事件

OS环境:windows server 2008 64位数据库版本:11.2.0今天在使用rman备份的时候随意的查看了一下等待事件,除了了我们现在系统遇到的IO瓶颈外,还额外的发了enq: TX -...

数据库出现 enq: TX - row lock contention

数据库出现 enq: TX - row lock contention 今天上午过来,做awr报告数据库出现了很多enq: TX - row lock contention的等待事件,以前从来...
  • RuleV5
  • RuleV5
  • 2012年08月03日 14:14
  • 3898

解决enq: TX - row lock contention的性能故障

今天下午接到同事电话,说Tuxedo
  • cn_mos
  • cn_mos
  • 2014年10月14日 20:51
  • 1503

[Oracle] enq: TX - row lock contention 优化案例

根据开发反馈,最近每天早上7:30应用会报警,应用的日志显示数据库连接池满了,新的连接被拒绝。 首先,我做了ASH报告(报告区间:7:25 ~ 7:35),从ASH的等待事件发现enq: TX - r...

ORACLE 归档空间满导致的enq: TX - row lock contention

ORA-15041 enq: TX - row lock contention diskgroup SFILEARCHDG01 was mounted diskgroup SFILEARCHDG01 ...

enq: TX - Row Lock Contention

遇到了一个 enq: TX - row lock contention的问题,从tkprof看,update真正执行的时间(cpu)很快,但elapsed时间非常长,在最后发现 enq: TX - r...

enq: TX - row lock contention故障处理一则

一个很简单的问题,之所以让我对这个问题进行总结,一是因为没我想象的简单,在处理的过程中遇到了一些磕磕碰碰,甚至绕了一些弯路,二是引发了我对故障处理时的一些思考。...
  • oradh
  • oradh
  • 2014年06月20日 14:18
  • 1860
内容举报
返回顶部
收藏助手
不良信息举报
您举报文章:一次大量enq: TX - row lock contention锁等待的问题
举报原因:
原因补充:

(最多只允许输入30个字)