Discussion:
'enq: TX - row lock contention' and 10046 trace
Rich
2012-11-29 16:27:08 UTC
Permalink
Hi List,
This is 10.2.0.4 on Solaris 10.

We are seeing large amounts of the blocking enqueue 'enq: TX - row lock
contention' on insert of a normal/heap table as well as smaller amounts on
a couple of updates of this table.

We have repro'd the issue in test and have 10046 (level 12) traces of all
of the sessions involved.
From the traces, we see these locks are mostly on one of the
(normal/B-tree) indexes (USERSTATUS), however, some of them are on another
(normal/B-tree) index (ROUTINGSTATUS).

We are trying to consolidate these traces into a timeline. We tried to use
trcsess, however, it requires at least one of the parameters be set. This
application (COTS) is not instrumented such that any of these fields are
populated, so that isn't working very well.

IIRC, there were tools (Perl script? maybe Hotsos/Cary Millsap?) allowing
many tracefiles to be consolidated in relation to time, however, I cannot
seem to find them.

Would someone on this list please direct me to such tools or give me
another avenue to try to determine what the application is doing?

Thanks,

Rich


--
http://www.freelists.org/webpage/oracle-l
kyle Hailey
2012-11-29 18:51:33 UTC
Permalink
A timeline tool would be cool.
For this situation why do you want a timeline?

If the locks are all on indexes, likely they are either unique key, foreign
key or bitmap issues.

You can query ASH and get an idea.

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: %'
and o.object_id (+)= ash.CURRENT_OBJ#
/

Here is what the three different cases looked like on my system:
uniq index
ST EVENT SID LM P2 P3 OBJ OTYPE FN BLOCKN
SQL_ID BSID
----- ---------------------- --- --- ------ ---- ----- ----- --- ------ --
10:39 enq: TX - row lock c 141 4 655406 6672 -1 0 0
bjvx94vnxtxgv 158
10:39 enq: TX - row lock c 141 4 655406 6672 -1 0 0
bjvx94vnxtxgv 158
10:39 enq: TX - row lock c 141 4 655406 6672 -1 0 0
bjvx94vnxtxgv 158
10:39 enq: TX - row lock c 141 4 655406 6672 -1 0 0
bjvx94vnxtxgv 158

FK
ST EVENT SID LM P2 P3 OBJ OTYPE FN BLOCKN
SQL_ID BSID
----- ---------------------- --- --- ------ ---- ----- ----- --- ------ --
10:41 enq: TX - row lock c 144 4 179681 7074 CHILD TABLE 1 60954
ahm7c9rupbz9r 1
10:41 enq: TX - row lock c 144 4 179681 7074 CHILD TABLE 1 60954
ahm7c9rupbz9r 1
10:41 enq: TX - row lock c 144 4 179681 7074 CHILD TABLE 1 60954
ahm7c9rupbz9r 1

bitmap
ST EVENT SID LM P2 P3 OBJ OTYPE FN BLOCKN
SQL_ID BSID
----- ---------------------- --- --- ------ ---- ----- ----- --- ------ --
10:41 enq: TX - row lock c 143 4 966081 4598 I1 INDEX 0 0
azav296xxqcjx 144
10:41 enq: TX - row lock c 143 4 966081 4598 I1 INDEX 0 0
azav296xxqcjx 144
10:41 enq: TX - row lock c 143 4 966081 4598 I1 INDEX 0 0
azav296xxqcjx 144
10:41 enq: TX - row lock c 143 4 966081 4598 I1 INDEX 0 0
azav296xxqcjx 144
Post by Rich
Hi List,
This is 10.2.0.4 on Solaris 10.
--
http://www.freelists.org/webpage/oracle-l
Rich
2012-11-29 19:53:14 UTC
Permalink
Thanks for your response, Kyle!
Running the query you provided (adding a timestamp) with:
col SAMPLE_TIME format a30
col LOCK_NAME format a21
col WAITER format 99999
col OTYPE format a6
col FILEN format 99999
col BLOCKN format 99999999

Doesn't look exactly the same as your output above...

Mine looks like (a single second):
SAMPLE_TIME LOCK_NAME WAITER
LMODE P2 P3 OBJECT OTYPE FILEN
BLOCKN WAITING_SQL BLOCKER
------------------------------ --------------------- ------ ----------
---------- ---------- ------------------------------ ------ ------
--------- ------------- ----------
...
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1403 4
5898263 1266032 IDX_BIZDOC_USERSTATUS INDEX 5 1245096
3ydys4ar7mauv 2412
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1412 4
4128795 1953483 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2083
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1572 4
2883608 2257046 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1601 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 0 0
4b7d6vbxx87cr 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1664 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 0 0
4b7d6vbxx87cr 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1713 4
327727 4802033 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2015
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1717 4
5898263 1266032 IDX_BIZDOC_USERSTATUS INDEX 5 1245096
3ydys4ar7mauv 2412
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1785 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 0 0
4b7d6vbxx87cr 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1790 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 0 0
4b7d6vbxx87cr 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1806 4
2883608 2257046 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1836 4
2883608 2257046 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1839 4
4128795 1953483 IDX_BIZDOC_USERSTATUS INDEX 5 1245126
3ydys4ar7mauv 2083
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1890 4
5898263 1266032 IDX_BIZDOC_USERSTATUS INDEX 5 1245096
3ydys4ar7mauv 2412
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 1992 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 5 7422
3ydys4ar7mauv 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2015 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 0 0
3ydys4ar7mauv 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2021 4
4128795 1953483 IDX_BIZDOC_USERSTATUS INDEX 5 1245126
3ydys4ar7mauv 2083
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2042 4
327727 4802033 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2015
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2083 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 5 7422
3ydys4ar7mauv 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2098 4
5898263 1266032 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2412
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2103 4
4128795 1953483 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2083
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2124 4
4128795 1953483 IDX_BIZDOC_USERSTATUS INDEX 5 1245126
3ydys4ar7mauv 2083
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2127 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 0 0
4b7d6vbxx87cr 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2160 4
4128795 1953483 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2083
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2208 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 0 0
4b7d6vbxx87cr 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2211 4
7733283 1214364 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 1992
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2261 4
2883608 2257046 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2284 4
4128795 1953483 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2083
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2289 4
2883608 2257046 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2317 4
4128795 1953483 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2083
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2335 4
4128795 1953483 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2083
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2339 4
5898263 1266032 IDX_BIZDOC_USERSTATUS INDEX 0 0
3d549m5yf6gyv 2412
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2349 4
2883608 2257046 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2369 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 0 0
4b7d6vbxx87cr 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2378 4
4128795 1953483 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2083
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2390 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 0 0
4b7d6vbxx87cr 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2394 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 0 0
3ydys4ar7mauv 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2398 4
4128795 1953483 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2083
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2412 4
2883608 2257046 IDX_BIZDOC_ROUTINGSTATUS INDEX 0 0
3ydys4ar7mauv 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2431 4
4128795 1953483 IDX_BIZDOC_USERSTATUS INDEX 5 1245126
3ydys4ar7mauv 2083
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2451 4
2883608 2257046 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 2445
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2623 4
7733283 1214364 IDX_BIZDOC_USERSTATUS INDEX 0 0
3ydys4ar7mauv 1992
29-NOV-12 09.03.18.824 AM enq: TX - row lock c 2646 4
2883608 2257046 IDX_BIZDOC_USERSTATUS INDEX 5 500862
3ydys4ar7mauv 2445
...
select SAMPLE_TIME,
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: %'
and o.object_id (+)= ash.CURRENT_OBJ#
/
--
http://www.freelists.org/webpage/oracle-l
kyle Hailey
2012-11-29 20:00:23 UTC
Permalink
are IDX_BIZDOC_USERSTATUS and IDX_BIZDOC_ROUTINGSTATUS bitmapped indexes?
- Kyle


--
http://www.freelists.org/webpage/oracle-l

Loading...