当前位置: 首页 > EVENT, ORACLE, 调优 > 正文

一次异常的gc buffer busy acquire与enq: TX – index contention的处理

早上一上班,客户的某个系统就出现大量的gc buffer busy acquire与enq:TX – index contention的争用,这系统N久没有出问题了,一出就出一个怪的问题。

1,查看会话等待信息

SQL> @we.sql                      
                       SESS_SERIAL               STATUS                            BLOCK_SESS      RUN   ROW_WAIT
 I EVENT               OSPID                     STATE      COM SQL_ID             INST:SESS       TIME  FILE#:OBJ#:BLOCK#:ROW#
-- ------------------  ------------------------- ---------- --- ------------------ --------------- ----- ----------------------
 1 gc buffer busy acq  2156:5297:27140           A.W.232MS  INS C.9zt41cpy5gkf8:0  F.1.1016        2055  86813:170:2925296:0
   gc buffer busy acq  2274:22651:18637          A.W.323MS  INS C.9zt41cpy5gkf8:0  F.1.1016        644   86813:170:2925296:0
   gc buffer busy acq  2279:3411:12231           A.W.219MS  INS C.9zt41cpy5gkf8:0  F.1.1016        1710  86813:170:2925296:0
   gc buffer busy acq  2280:2077:19130           A.W.435MS  INS C.9zt41cpy5gkf8:0  F.1.1016        475   86813:170:2925296:0
   gc buffer busy acq  2282:43097:12289          A.W.260MS  INS C.9zt41cpy5gkf8:0  F.1.1016        1708  86813:170:2925296:0
   gc buffer busy acq  2285:50617:17985          A.W.936MS  INS C.9zt41cpy5gkf8:0  F.1.1016        798   86813:170:2925296:0
   gc buffer busy acq  2286:22723:19032          A.W.621MS  INS C.9zt41cpy5gkf8:0  F.1.1016        492   86813:170:2925296:0
   gc buffer busy acq  2289:17463:27186          A.W.216MS  INS C.9zt41cpy5gkf8:0  F.1.1016        2074  86813:170:2925296:0
   gc buffer busy acq  2293:4003:21780           A.W.232MS  INS C.9zt41cpy5gkf8:0  F.1.1016        2065  86813:170:2925296:0
   gc buffer busy acq  2295:26043:12181          A.W.216MS  INS C.9zt41cpy5gkf8:0  F.1.1016        1708  86813:170:2925296:0
   gc buffer busy acq  2420:279:21801            A.W.223MS  INS C.9zt41cpy5gkf8:0  F.1.1016        2065  86813:170:2925296:0
   gc buffer busy acq  2422:511:27258            A.W.228MS  INS C.9zt41cpy5gkf8:0  F.1.1016        2074  86813:170:2925296:0
   gc buffer busy acq  2423:57659:17947          A.W.417MS  INS C.9zt41cpy5gkf8:0  F.1.1016        803   86813:170:2925296:0
   gc buffer busy acq  2426:56567:12077          A.W.231MS  INS C.9zt41cpy5gkf8:0  F.1.1016        1711  86813:170:2925296:0
   gc buffer busy acq  2428:28099:19132          A.W.374MS  INS C.9zt41cpy5gkf8:0  F.1.1016        469   86813:170:2925296:0
   gc buffer busy acq  2429:56481:12183          A.W.250MS  INS C.9zt41cpy5gkf8:0  F.1.1016        1710  86813:170:2925296:0
   gc buffer busy acq  2432:1795:21782           A.W.214MS  INS C.9zt41cpy5gkf8:0  F.1.1016        2065  86813:170:2925296:0
   gc buffer busy acq  2437:13301:12233          A.W.237MS  INS C.9zt41cpy5gkf8:0  F.1.1016        1710  86813:170:2925296:0
   gc buffer busy acq  2438:32663:19034          A.W.625MS  INS C.9zt41cpy5gkf8:0  F.1.1016        492   86813:170:2925296:0
   gc buffer busy acq  2566:12183:12291          A.W.270MS  INS C.9zt41cpy5gkf8:0  F.1.1016        1709  86813:170:2925296:0
  2[CPU]:SQL*Net mess  1006:5123:1800            A.S.0MS    SEL C.12bpa0t77gr6m:0                  1     133965:76:2986119:0
   db file scattered   1302:21557:3883           A.W.3MS    SEL C.1mvp4wb7r6gq0:13                 27    183720:82:2991681:0
   PX Deq: Execute Re  443:24965:4093            A.W.1MS    SEL C.2gxbgzntv7pg7:2                  1     -1:0:0:0
   [CPU]:PX Deq: Exec  1865:37941:14516          A.N.11MS   SEL C.2gxbgzntv7pg7:2                  1     -1:0:0:0
   gc buffer busy rel  2990:52667:668            A.W.85MS   INS C.323u94syb0x0k:56                 1     138414:117:857998:0
   gc buffer busy rel  2996:423:305              A.W.115MS  INS C.323u94syb0x0k:56                 1     138414:117:857998:0
   db file scattered   3413:4361:23757           A.W.8MS    SEL C.3dgw7uhgy7fww:2                  267   183727:10:1990447:0
   gc buffer busy rel  728:413:2142              A.W.204MS  UPD C.5f0545cj8rp1r:0  F.2.2298        1     119081:170:2593655:0
   db file scattered   1994:32293:22791          A.W.76MS   UPD C.6hprqd3j67d3v:0                  361   64792:81:1004936:0
   db file scattered   3154:62203:2591           A.W.15MS   UPD C.6kyg0u6gmrw5p:71                 340   183727:146:3360500:0
   gc current request  1998:57729:25736          A.W.2MS    DEL C.71a2abnvv466u:11                 1     138410:155:3428088:0
   db file scattered   1596:52555:21776          A.W.1MS    UPD C.7mnmfrx2ast9v:0                  4483  64796:132:3611408:0
   gc buffer busy rel  2298:40689:1652           A.W.5MS    INS C.835fpf0102r7p:10                 1     138414:117:857998:0
   gc buffer busy rel  2289:2907:1811            A.W.176MS  INS C.835fpf0102r7p:10 F.2.2298        1     138414:117:857998:0
   db file scattered   3140:38881:14478          A.W.1MS    SEL C.8y2tnucfk1vds:0                  5406  64796:141:3358805:0
   enq: TX - index co  3713:22261:1464           A.W.497268 INS C.9zt41cpy5gkf8:1  F.1.1016        497   86812:7:1330871:0
   enq: TX - index co  3717:44075:1886           A.W.461689 INS C.9zt41cpy5gkf8:1  F.1.1016        462   86812:7:1331071:0
   enq: TX - index co  3719:47031:32758          A.W.666448 INS C.9zt41cpy5gkf8:1  F.1.1016        745   86813:170:2927609:0
   enq: TX - index co  3850:1795:1888            A.W.460803 INS C.9zt41cpy5gkf8:1  F.1.1016        461   86812:7:1333119:0
   enq: TX - index co  3851:20419:2558           A.W.660477 INS C.9zt41cpy5gkf8:1  F.1.1016        2074  86813:170:2927673:0
   enq: TX - index co  3853:4859:21030           A.W.666455 INS C.9zt41cpy5gkf8:1  F.1.1016        1714  86813:170:2927609:0
   enq: TX - index co  3855:20321:15113          A.W.666453 INS C.9zt41cpy5gkf8:1  F.1.1016        1823  86813:170:2927609:0
   enq: TX - index co  3989:3263:1184            A.W.666451 INS C.9zt41cpy5gkf8:1  F.1.1016        1871  86813:170:2927609:0
   enq: TX - index co  3990:52699:1837           A.W.466910 INS C.9zt41cpy5gkf8:1  F.1.1016        467   86812:7:1334103:0
..................................................


 I EVENT                                    SQL_ID               COUNT(*)
-- ---------------------------------------- ------------------ ----------
 1 gc cr request                            6y85n3b1mf2br               1
   gc current request                       9zt41cpy5gkf8               1
   [CPU]:SQL*Net message from client                                    1
   gc buffer busy acquire                   835fpf0102r7p               1
   db file sequential read                  6cggtx2xb1j7y               1
   [CPU]:PX Deq: Execution Msg              4wczjr3kkykdz               1
   gc cr request                            9ky32f56j88za               1
   db file scattered read                   dn8x8891w5mnc               1
   gc current request                       gwnzd3p33gxph               1
   gc current request                       835fpf0102r7p               2
   gc buffer busy acquire                   9zt41cpy5gkf8             277
 2 enq: TX - allocate ITL entry             9zt41cpy5gkf8               1
   gc cr request                            98ty656zmcpj4               1
   db file sequential read                  aztqbg5q4mmsg               1
   [CPU]:SQL*Net message to client          1cmwp2mdkq7dq               1
   gc cr request                            835fpf0102r7p               1
   db file sequential read                  1mvp4wb7r6gq0               1
   class slave wait                                                     1
   read by other session                    brduznyzz5auf               1
   db file scattered read                   brduznyzz5auf               1
   gc cr request                            cvdjyqc4s9k38               1
   db file scattered read                   6kyg0u6gmrw5p               1
   db file scattered read                   3dgw7uhgy7fww               1
   [CPU]:gc current request                 b87jvnf8d4n6n               1
   [CPU]:SQL*Net message from client        5wsdcv6tu5mfj               1
   gc current request                       a99hufkudc5u6               1
   db file scattered read                   8y2tnucfk1vds               1
   db file scattered read                   6hprqd3j67d3v               1
   [CPU]:PX Deq: Execution Msg              4wczjr3kkykdz               1
   PX Deq: Execute Reply                    4wczjr3kkykdz               1
   db file scattered read                   7mnmfrx2ast9v               1
   buffer busy waits                        323u94syb0x0k               2
   [CPU]:SQL*Net message to client          12bpa0t77gr6m               2
   buffer busy waits                        835fpf0102r7p               2
   enq: TX - index contention               9zt41cpy5gkf8             188

35 rows selected.


 I EVENT                                      COUNT(*)
-- ---------------------------------------- ----------
 1 gc buffer busy acquire                          277
   [CPU]:SQL*Net message from client                 3
   gc cr request                                     2
   db file sequential read                           2
   gc current request                                2
   [CPU]:PX Deq: Execution Msg                       1
   gc cr multi block request                         1
 2 enq: TX - index contention                      188
   db file scattered read                            6
   [CPU]:SQL*Net message from client                 4
   gc cr request                                     3
   [CPU]:SQL*Net message to client                   3
   [CPU]:latch: cache buffers chains                 3
   db file sequential read                           2
   [CPU]:db file scattered read                      1
   [CPU]:gc current request                          1
   class slave wait                                  1
   read by other session                             1
   enq: TX - allocate ITL entry                      1
   gc current request                                1
   [CPU]:PX Deq: Execution Msg                       1
   log file sync                                     1
   PX Deq: Execute Reply                             1

在等待信息中,可以发现节点1同时等待gc buffer busy acquire的会话达到277个,节点2同时等待enq: TX – index contention会话达到188个,这个还不是最严重的时候,在最后处理时候达到500之多。

 

在gc buffer busy acquire的p1,p2值全部一样,数据文件为170、块号为2925296上,出问题的SQL都是一条SQL:9zt41cpy5gkf8,这个跟enq:TX – index contention是同一条sql,这下基本知道不是sql性能底下导致的。

 

2,查询在170、2925296的物理读的会话

SQL> select event,sid,p1,p2 from gv$session where p1=170 and p2=2925296 and event not like 'gc %';

这里没有返回任何的行数,本以为是由于物理读异常导致GC等待出现,再导致INDEX争用的,现在看来不是。

 

3,KILL进程

为了先解决问题,确定先KILL阻塞者进程。但是KILL部分gv$session里面显示的阻塞者后没有效果,这个思路也不通了。

 

4,重启业务

 

甲方人员反映在早上5点过由于业务不能启动,KILL了一个数据库进程后业务能正常启动。这下暂时不知道在那里出问题,所有叫开发重启一下业务,但是被阻塞的进程越来越多,说明开发还没有重启业务。

 

5,手动刷BUFFER CACHE

 

在2014年12月在云南电信的项目中遇到过相同的问题,不过那个环境是9I,也是找不到阻塞者,通过flush buffer cache后正常的。

跟客户商量后,决定通过手动flush buffer cache,看能否正常恢复。

 

6,处理结果

 

通过flush buffer cache后,数据库等待事件恢复正常,等待事件信息如下

    I EVENT                                      COUNT(*)
   -- ---------------------------------------- ----------
    1 gc buffer busy acquire                            9
      SQL*Net message from dblink                       6
      db file sequential read                           5
      gc cr request                                     2
      [CPU]:SQL*Net message to client                   2
      gc current request                                2
      db file scattered read                            1
      log file sync                                     1
      [CPU]:gc current request                          1
      [CPU]:PX Deq: Execution Msg                       1
      PX Deq: Execute Reply                             1
    2 db file sequential read                          34
      SQL*Net message from dblink                      11
      gc buffer busy acquire                            9
      db file scattered read                            4
      gc buffer busy release                            3
      [CPU]:SQL*Net message from client                 3
      gc current request                                3
      gc cr request                                     2
      [CPU]:SQL*Net message to client                   2
      read by other session                             2
      enq: TX - index contention                        2
      [CPU]:PX Deq: Execution Msg                       1
      [CPU]:db file scattered read                      1
      class slave wait                                  1

 

7,原因分析

这里没有找到真正的原因,也没有找到阻塞者,估计要做SYSTEMSTATE才可以找到阻塞者。估计是由于某个进程异常,一直在读块不返回成功,持有的锁没有释放,相同的节点的会话再次申请这个块是出现gc buffer busy acquire等待,另外一个节点的INSERT语句出现索引的争用。

 

 

 

 

本文固定链接: http://www.htz.pw/2016/03/13/%e4%b8%80%e6%ac%a1%e5%bc%82%e5%b8%b8%e7%9a%84gc-buffer-busy-acquire%e4%b8%8eenq-tx-index-contention%e7%9a%84%e5%a4%84%e7%90%86.html | 认真就输

该日志由 huangtingzhong 于2016年03月13日发表在 EVENT, ORACLE, 调优 分类下, 通告目前不可用,你可以至底部留下评论。
原创文章转载请注明: 一次异常的gc buffer busy acquire与enq: TX – index contention的处理 | 认真就输