Oracle 11.2.0.4 on Linux. This is two-node RAC, but services are limited to one node. The waits described below happened on node#2.
We observed heavy waits on 'enq: TX - contention' and 'buffer busy waits', it happened twice on the same day, both times lasted for about an hour.
The impact was mostly on INSERT statements into one table. The table isn't partitioned, size = 200 GB, rowcount = 60 million. The table has two securefile CLOB columns. LOB segments are: column#1 = 200 GB, column #2 = 100 GB. LOBs are defied with chunk = 8192, cache = NO, in_row = YES. Database block size = 8192.
Most waits were for one block: datafile 72, block 501636. This block belongs to LOB segment for column#1, extent with extend_id = 0, this extent starts at block 501632. Block dump is shown below, could someone explain what it contains?
There is a MOS note on these waits and several blog posts:
MOS Note 1532311.1 Securefiles DMLs cause high 'buffer busy waits' & 'enq: TX - contention' wait events leading to whole database performance degradation
https://magnusjohanssontuning.wordpress.com/2013/03/06/high-buffer-busy-waits-securefiles/
http://jakub.wartak.pl/blog/?p=798
Block dump:
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options
ORACLE_HOME = /ora01/oradbs/orabase/product/11204
System name: Linux
Node name:
Release: 2.6.32-696.1.1.el6.x86_64
Version: #1 SMP Tue Mar 21 12:19:18 EDT 2017
Machine: x86_64
Instance name:
Redo thread mounted by this instance: 2
Oracle process number: 128
Unix process pid: 45543, image: oracle@
*** 2019-11-27 00:06:30.430
*** SESSION ID:(3057.11129) 2019-11-27 00:06:30.430
*** CLIENT ID:() 2019-11-27 00:06:30.430
*** SERVICE NAME:() 2019-11-27 00:06:30.430
*** MODULE NAME:() 2019-11-27 00:06:30.430
*** ACTION NAME:() 2019-11-27 00:06:30.430
Trace file /ora01/oradbs/orabase/diag/rdbms///trace/ora_45543.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options
ORACLE_HOME = /ora01/oradbs/orabase/product/11204
System name: Linux
Node name:
Release: 2.6.32-696.1.1.el6.x86_64
Version: #1 SMP Tue Mar 21 12:19:18 EDT 2017
Machine: x86_64
Instance name:
Redo thread mounted by this instance: 2
Oracle process number: 86
Unix process pid: 45543, image: oracle@(TNS V1-V3)
*** 2019-12-24 11:44:02.591
*** SESSION ID:(3619.29475) 2019-12-24 11:44:02.591
*** CLIENT ID:() 2019-12-24 11:44:02.591
*** SERVICE NAME:(SYS$USERS) 2019-12-24 11:44:02.591
*** MODULE NAME:(sqlplus@ (TNS V1-V3)) 2019-12-24 11:44:02.591
*** ACTION NAME:() 2019-12-24 11:44:02.591
Start dump data blocks tsn: 6 file#:72 minblk 501636 maxblk 501636
Block dump from cache:
Dump of buffer cache at level 4 for tsn=6 rdba=302491524
BH (0x4c5eb1d298) file#: 72 rdba: 0x1207a784 (72/501636) class: 8 ba: 0x4c5b9ca000
set: 121 pool: 3 bsz: 8192 bsi: 0 sflg: 1 pwc: 0,25
dbwrid: 0 obj: 178886 objn: 178886 tsn: 6 afn: 72 hint: f
hash: [0x19719cd178,0x19719cd178] lru: [0x459d73d3e8,0x483db15148]
lru-flags: hot_buffer
ckptq: [NULL] fileq: [NULL] objq: [0x425db75e10,0x12d7b0f0f8] objaq: [0x629dd5cac0,0x729dd28fa0]
st: XCURRENT md: NULL fpin: 'ktslwhh44: ktslfsum_cfs' tch: 22 le: 0x511f1e5d88
flags: block_written_once redo_since_read remote_transfered
force_cr_override
LRBA: [0x0.0.0] LSCN: [0x0.0] HSCN: [0xffff.ffffffff] HSUB: [1]
Block dump from disk:
buffer tsn: 6 rdba: 0x1207a784 (72/501636)
scn: 0x0ddc.41a26339 seq: 0x01 flg: 0x04 tail: 0x63393d01
frmt: 0x02 chkval: 0x0641 type: 0x3d=NGLOB: Hash Bucket
Hex dump of block: st=0, typ_found=1
Dump of memory from 0x00007EFC0550BA00 to 0x00007EFC0550DA00
7EFC0550BA00 0000A23D 1207A784 41A26339 04010DDC [=.......9c.A....]
7EFC0550BA10 00000641 00000000 00000002 00000000 [A...............]
7EFC0550BA20 00000000 00000000 00000001 109FE7D8 [................]
7EFC0550BA30 11F0F481 00000000 00000000 00000000 [................]
7EFC0550BA40 00000000 00000000 00000000 00000000 [................]
Repeat 2 times
7EFC0550BA70 00000000 00000000 00000000 000013DE [................]
7EFC0550BA80 00000000 0002BAC6 00000000 11F0F481 [................]
7EFC0550BA90 00000008 00000008 109FE7D8 00000000 [................]
7EFC0550BAA0 00000000 00000000 00000000 10DAA8B7 [................]
7EFC0550BAB0 00000000 00000000 00000000 00000002 [................]
7EFC0550BAC0 0EEF0D0C 00000000 00000000 00000000 [................]
7EFC0550BAD0 00000002 21823FEB 00000000 00000000 [.....?.!........]
7EFC0550BAE0 00000000 00000002 10D65DFD 00000000 [.........]......]
7EFC0550BAF0 00000000 00000000 00000002 10D33F45 [............E?..]
7EFC0550BB00 00000000 00000000 00000000 00000002 [................]
7EFC0550BB10 10D33C20 00000000 00000000 00000000 [ <..............]
7EFC0550BB20 00000002 10D62992 00000000 00000000 [.....)..........]
7EFC0550BB30 00000000 00000002 11F0F481 00000000 [................]
7EFC0550BB40 00000000 00000000 00000000 231E1AE9 [...............#]
7EFC0550BB50 00000000 00000000 00000000 00000002 [................]
7EFC0550BB60 386DBE84 00000000 00000000 00000000 [..m8............]
7EFC0550BB70 00000001 386DBE8C 00000000 00000000 [......m8........]
7EFC0550BB80 00000000 00000002 3871893B 00000000 [........;.q8....]
7EFC0550BB90 00000000 00000000 00000002 2EDD5C59 [............Y\..]
7EFC0550BBA0 00000000 00000000 00000000 00000002 [................]
7EFC0550BBB0 3FC28EC7 00000000 00000000 00000000 [...?............]
7EFC0550BBC0 00000001 3FC28EF0 00000000 00000000 [.......?........]
7EFC0550BBD0 00000000 00000002 00000000 00000000 [................]
7EFC0550BBE0 00000000 00000000 00000000 00000000 [................]
Repeat 14 times
7EFC0550BCD0 00000000 00000000 00000002 00000000 [................]
7EFC0550BCE0 00000000 00000000 00000000 00000000 [................]
Repeat 464 times
7EFC0550D9F0 00000000 00000000 00000000 63393D01 [.............=9c]
Dump of Hash Bucket Block
--------------------------------------------------------
Hash Bucket Header Dump
Range: 2k to 32k
Inst:2 Flag:1 Total:0 FSG_COUNT:5086 OBJD:178886 Inc:0
fsg_count:5086
Head:0x 0x109fe7d8 Tail:0x 0x11f0f481
Opcdode:0 Locker Xid: 0x0000.000.00000000
Fsbdba: 0x11f0f481 Fbrdba: 0x0
Head Cache Entries
-------------------
Head: 0 fsg_db: 0x109fe7d8
Head: 1 fsg_db: 0x10daa8b7
Head: 2 fsg_db: 0x0eef0d0c
Head: 3 fsg_db: 0x21823feb
Head: 4 fsg_db: 0x10d65dfd
Head: 5 fsg_db: 0x10d33f45
Head: 6 fsg_db: 0x10d33c20
Head: 7 fsg_db: 0x10d62992
-------------------
Tail Cache Entries
-------------------
Tail: 0 fsg_db: 0x11f0f481
Tail: 1 fsg_db: 0x231e1ae9
Tail: 2 fsg_db: 0x386dbe84
Tail: 3 fsg_db: 0x386dbe8c
Tail: 4 fsg_db: 0x3871893b
Tail: 5 fsg_db: 0x2edd5c59
Tail: 6 fsg_db: 0x3fc28ec7
Tail: 7 fsg_db: 0x3fc28ef0
-------------------
Free Space Chunk Summary
Inst:2 Minc:0 Maxc:0 Count:0 Tot:0 MAXC:0
CFS Chunk List
--------------
--------------------------------------------------------
GLOBAL CACHE ELEMENT DUMP (address: 0x511f1e5d88):
id1: 0x7a784 id2: 0x48 pkey: OBJ#178886 block: (72/501636)
lock: X rls: 0x0 acq: 0x0 latch: 3
flags: 0x20 fair: 0 recovery: 0 fpin: 'ktslwhh44: ktslfsum_cfs'
bscn: 0xddc.41a26339 bctx: (nil) write: 0 scan: 0x0
lcp: (nil) lnk: [NULL] lch: [0x4c5eb1d3d0,0x4c5eb1d3d0]
seq: 14145 hist: 113 238 180 58 113 238 180 58 113 238 180 58 113 238 180 58
113 238 180 58
LIST OF BUFFERS LINKED TO THIS GLOBAL CACHE ELEMENT:
flg: 0x0a200000 sflg: 0x2000 lflg: 0x8 state: XCURRENT tsn: 6 tsh: 22
addr: 0x4c5eb1d298 obj: 178886 cls: 1ST LEVEL BMB bscn: 0xddc.41a26339
GCS SHADOW 0x511f1e5e00,13 resp[0x16d28ae7f0,0x7a784.48] pkey 178886.0
grant 2 cvt 0 mdrole 0x2 st 0x100 lst 0x40 GRANTQ rl LOCAL
master 2 owner 2 sid 0 remote[(nil),0] hist 0x851018102127c286
history 0x6.0x5.0x1f.0x9.0x2.0x2.0x6.0x8.0x5.0x1.
cflag 0x0 sender 0 flags 0x10 replay# 0 abast (nil).x0.1 dbmap (nil)
disk: 0x0000.00000000 write request: 0x0000.00000000
pi scn: 0x0000.00000000 sq[0x16d28ae830,0x16d28ae830]
msgseq 0x0 updseq 0x0 reqids[87,0,0] infop (nil) lockseq xf6e2
GCS SHADOW END
GCS RESOURCE 0x16d28ae7f0 hashq [0x1692128f90,0x149bae9e00] name[0x7a784.48] pkey 178886.0
grant 0x511f1e5e00 cvt (nil) send (nil)@1,0 write (nil),0@65536
flag 0x0 mdrole 0x2 mode 2 scan 0.0 role LOCAL
disk: 0x0ddb.0b38ed57 write: 0x0000.00000000 cnt 0x0 hist 0x8e
xid 0x0000.000.00000000 sid 0 pkwait 0s rmacks 0
refpcnt 0 weak: 0x0000.00000000
pkey 178886.0
hv 111 [stat 0x0, 2->2, wm 32768, RMno 0, reminc 48, dom 0]
kjga st 0x4, step 0.0.0, cinc 48, rmno 5487, flags 0x0
lb 0, hb 0, myb 1930480, drmb 1930480, apifrz 0
GCS SHADOW 0x511f1e5e00,13 resp[0x16d28ae7f0,0x7a784.48] pkey 178886.0
grant 2 cvt 0 mdrole 0x2 st 0x100 lst 0x40 GRANTQ rl LOCAL
master 2 owner 2 sid 0 remote[(nil),0] hist 0x851018102127c286
history 0x6.0x5.0x1f.0x9.0x2.0x2.0x6.0x8.0x5.0x1.
cflag 0x0 sender 0 flags 0x10 replay# 0 abast (nil).x0.1 dbmap (nil)
disk: 0x0000.00000000 write request: 0x0000.00000000
pi scn: 0x0000.00000000 sq[0x16d28ae830,0x16d28ae830]
msgseq 0x0 updseq 0x0 reqids[87,0,0] infop (nil) lockseq xf6e2
GCS SHADOW END
GCS RESOURCE END
2019-12-24 11:44:02.607459 : kjbmbassert [0x7a784.48]
2019-12-24 11:44:02.607539 : kjbmsassert(0x7a784.48)(to 1)(lvl 4)
End dump data blocks tsn: 6 file#: 72 minblk 501636 maxblk 501636