Oracle Trace File Interpretation: enq: TX – index contention

oracle

Background

I've got an application which is doing a large number of concurrent inserts into an Oracle table. The Top Activity view is reporting a lot of index contention and I am attempting to reduce this to improve performance.

The table in question has several indexes, but my suspicion is that the problem is leaf-block contention on the PK which is a monotonically increasing sequence. I know about reverse key indexes, but I'd like to be able to pin-point the problem before I dive in with guesswork fixes.

Trace File Contents

I've extracted a trace from the database when under load. I've included a chunk of it at the bottom, but one part in particular is puzzling me. The largest "enq: TX – index contention" entry accounts for 94% of the total time:

WAIT #47156432773600: nam='enq: TX - index contention' ela= 113183 name|mode=1415053316 usn<<16 | slot=4259845 sequence=43226 obj#=-1 tim=1329387810694927

I don't understand how to interpret this line. Googling has yielded that name|mode=1415053316 means Transaction in share mode (hex TX04), and that obj# would reference the object in SYS.OBJ$.

For the other waits where obj# is specified (see below), it points to the PK index I have suspicions about, but in the largest wait, the obj#=-1.

So, my questions are:

  • What does it mean for obj# to be -1 in this wait?
  • What does the usn<<16 | slot=4259845 parameter mean? Is it useful to me?
  • Does the sequence=43226 tell me anything useful?

More trace detail

PARSING IN CURSOR #47156432773600 len=654 dep=0 uid=41 oct=2 lid=41 tim=1329387810581386 hv=3365236844 ad='2977ccca8' sqlid='31r3hm349aw3c'
insert into AnonymousTable (a, b, c ...) values (:1, :2, :3 ...)
END OF STMT
PARSE #47156432773600:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=1329387810581384
WAIT #47156432773600: nam='enq: TX - index contention' ela= 113183 name|mode=1415053316 usn<<16 | slot=4259845 sequence=43226 obj#=-1 tim=1329387810694927
WAIT #47156432773600: nam='latch: ges resource hash list' ela= 3958 address=11249153232 number=91 tries=0 obj#=-1 tim=1329387810698944
WAIT #47156432773600: nam='enq: TX - index contention' ela= 1891 name|mode=1415053316 usn<<16 | slot=655387 sequence=48341 obj#=-1 tim=1329387810700949
WAIT #47156432773600: nam='buffer busy waits' ela= 162 file#=32 block#=618823 class#=1 obj#=28134 tim=1329387810701223
WAIT #47156432773600: nam='buffer busy waits' ela= 1572 file#=32 block#=618823 class#=1 obj#=28134 tim=1329387810702840
WAIT #47156432773600: nam='enq: TX - index contention' ela= 1809 name|mode=1415053316 usn<<16 | slot=5767194 sequence=85968 obj#=28134 tim=1329387810704709
WAIT #47156432773600: nam='buffer busy waits' ela= 2254 file#=32 block#=618823 class#=1 obj#=28134 tim=1329387810707018
WAIT #47156432773600: nam='enq: TX - index contention' ela= 15306 name|mode=1415053316 usn<<16 | slot=4784132 sequence=53965 obj#=28134 tim=1329387810722436
EXEC #47156432773600:c=1999,e=142776,p=0,cr=50,cu=364,mis=0,r=28,dep=0,og=1,plh=0,tim=1329387810724203
STAT #47156432773600 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=50 pr=0 pw=0 time=142726 us)'
WAIT #47156432773600: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=28134 tim=1329387810724288
WAIT #47156432773600: nam='SQL*Net message from client' ela= 363 driver id=1413697536 #bytes=1 p3=0 obj#=28134 tim=1329387810724667
CLOSE #47156432773600:c=0,e=7,dep=0,type=1,tim=1329387810724701

Best Answer

OBJ#=-1 means either means that the object number is missing or it's not related to an object. The best idea is to go into V$active_session_history and find the SQL_ID then get the SQL text via the SQL_ID and look at the object sin the SQL and what the SQL was doing.

As far as people suggesting INIT TRANS, that is unlikely as there is a separate wait event for INIT TRANS.

USN, SLOT and SEQUENCE map the UNDO entry for the transaction. They could be used to map back to activity in the UNDO but it's probably easier to get the transaction id the XID and use VERSIONS_XID on the objects involved.

see http://www.slideshare.net/khailey/ukoug-oracle-transaction-locks

Example ASH query

col object for A15
col otype for A10
select
      substr(event,0,20)    lock_name,
      ash.session_id        waiter,
      mod(ash.p1,16)        lmode,
      --ash.p2                p2,
      --ash.p3                p3,
      o.object_name           object,
      o.object_type           otype,
      CURRENT_FILE#           filen,
      CURRENT_BLOCK#          blockn,
      ash.SQL_ID             waiting_sql,
      BLOCKING_SESSION        blocker
      --,ash.xid
from
        v$active_session_history ash,
        all_objects o
where
          event like 'enq: TX - index contention'
  and o.object_id (+)= ash.CURRENT_OBJ#
/
Related Question