一次异常的gc buffer busy acquire与enq: TX – index contention的处理
Mar132016
早上一上班，客户的某个系统就出现大量的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/?p=1106 | 认真就输
最新评论
K.I.S.S.LANG:
来过，总要留下点什么brokensword:
非常感谢博主的分享，不知博主可以冰冻心灵:
主库使用ALTER DATABAcsdw:
是 1031
哈哈,,黄大师,总结得好huangtingzhong:
Loading Hinted E
下面是ASM磁盘头的部分ASM
RMAN backup to F
Database Crashed
How to Resolve O
最活跃的读者