This was first published on https://blog.dbi-services.com/investigating-oracle-lock-issues-with-event-10704 (2014-03-14)
Republishing here for new followers. The content is related to the the versions available at the publication date
Did you ever encounter unexplained Oracle lock issues? They may be coming from unindexed foreign keys (which is worse in 11g). It’s not easy to monitor. Of course you can check Oracle locks from V$LOCKED_OBJECT, but that is a solution only for locks that remain. Some Oracle locks are there only for a short duration. How do you check which lock is acquired by a statement?
Event 10704 is the solution. I’ll show some examples in order to explain which lines from the trace are interresting, and how to interpret them.
In this posting, I’ll illustrate how to use event 10704 to understand locking on referential integrity (the well know index on foreign key issue) in 12c.
I set the trace (10704 level 3 for the locks, 10046 to see the statements):
SQL> alter session set events='10046 trace name context forever, level 1 : 10704 trace name context forever, level 3' tracefile_identifier='ForeignKey'; Session altered.
I delete from the DEPT table:
SQL> DELETE FROM SCOTT.DEPT WHERE DEPTNO=0; 0 rows deleted.
and then terminate the transaction:
SQL> ROLLBACK; Rollback complete.
and stop the trace:
SQL> alter session set events='10046 trace name context off : 10704 trace name context off '; Session altered.
Now let’s get the trace file name:
SQL> column tracefile new_value tracefile SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=sys_context('USERENV','SID')); TRACEFILE -------------------------------------------------------------------------------- /u01/app/oracle/diag/rdbms/demo/DEMO/trace/DEMO_ora_28042_ForeignKey.trc
and grep the interresting lines from the trace file:
SQL> host grep -A 1 -E 'ksqgtl [*]{3}|ksqrcl: [A-Z]|ksqcnv: [A-Z]|XCTEND|PARSE ERROR|PARSING' &tracefile
The output is:
-- PARSING IN CURSOR #140064855052048 len=37 dep=0 uid=0 oct=7 lid=0 tim=294484898588 hv=3450586461 ad='822782c8' sqlid='c1fnpd76urjax' DELETE FROM SCOTT.DEPT WHERE DEPTNO=0 -- ksqgtl *** TM-00017EA8-00000000-00000000-00000000 mode=3 flags=0x401 timeout=21474836 *** ksqgtl: xcb=0x8eb5bcf8, ktcdix=2147483647, topxcb=0x8eb5bcf8 -- ksqgtl *** TM-00017EAA-00000000-00000000-00000000 mode=4 flags=0x401 timeout=21474836 *** ksqgtl: xcb=0x8eb5bcf8, ktcdix=2147483647, topxcb=0x8eb5bcf8 -- ksqrcl: TM-00017EAA-00000000-00000000-00000000 ksqcmi: TM-00017EAA-00000000-00000000-00000000 mode=0 timeout=0 -- PARSING IN CURSOR #140064855052048 len=8 dep=0 uid=0 oct=45 lid=0 tim=294484900906 hv=2761672982 ad='0' sqlid='8sst43uk9rk8q' ROLLBACK -- XCTEND rlbk=1, rd_only=1, tim=294484900964 ksqrcl: TM-00017EA8-00000000-00000000-00000000 ksqcmi: TM-00017EA8-00000000-00000000-00000000 mode=0 timeout=0 --
In order to interpret it, we need one more information – the OBJECT_ID in hexadecimal:
SQL> column object_name format a20 SQL> column object_type format a20 SQL> select object_id , to_char(object_id,'0XXXXXXX') , object_name,object_type from all_objects where owner='SCOTT' order by 2; OBJECT_ID TO_CHAR(O OBJECT_NAME OBJECT_TYPE ---------- --------- -------------------- -------------------- 97960 00017EA8 DEPT TABLE 97961 00017EA9 PK_DEPT INDEX 97962 00017EAA EMP TABLE 97963 00017EAB PK_EMP INDEX 97964 00017EAC BONUS TABLE 97965 00017EAD SALGRADE TABLE 7 rows selected.
Great. Now let’s interpret that. You see the DELETE statement in the trace file (written by event 10046 which is the sql_trace). Then we have:
…which means we get lock (ksqgtl) on table (lock_type=TM) SCOTT.DEPT (object_id=17EA8) in mode Row-X (mode=3). This is expected as we have the intention to delete rows, thus we request Row-X lock on the table. And next to it you see:
which is a table lock on SCOTT.EMP (object_id=17EAA) in Share mode (mode=4) – the child lock that we see since 8.1.7 when the foreign key is not indexed. That lock is released immediately (which is the behaviour since 9.2) after the delete:
ksqrcl is the function that releases lock. That is done before the end of the transaction (XCTEND from sql_trace). And the Row-X on DEPT is released once the transaction is ended:
If we create a index in order to avoid the Share mode lock:
SQL> CREATE INDEX SCOTT.FK_DEPTNO on SCOTT.EMP(DEPTNO); Index created.SQL> DELETE FROM SCOTT.DEPT WHERE DEPTNO=0; 0 rows deleted. SQL> ROLLBACK; Rollback complete.
…then here is what we get from the 10704 trace:
ksqgtl *** TM-00017EAA-00000000-00000000-00000000 mode=4 flags=0x401 timeout=0 ***
This is the Share mode lock on the table when creating the index. This is what a delete on the parent generates:
ksqgtl *** TM-00017EA8-00000000-00000000-00000000 mode=3 flags=0x401 timeout=21474836 *** ksqgtl *** TM-00017EAA-00000000-00000000-00000000 mode=3 flags=0x401 timeout=21474836 *** XCTEND rlbk=1, rd_only=1, tim=294485532138 ksqrcl: TM-00017EAA-00000000-00000000-00000000 ksqrcl: TM-00017EA8-00000000-00000000-00000000
…which are only Row-X (mode=3) locks, but are released only at the end of the transaction.
And besides requesting a lock (ksqgtl) and releasing a lock (ksqrcl), the third interresting function is when a lock is converted (ksqcnv) from one mode to another mode.
Let’s see an exemple when we first delete rows from the child (without the index on the foreign key):
SQL> DELETE FROM SCOTT.EMP WHERE DEPTNO=0 ksqgtl *** TM-00017EA8-00000000-00000000-00000000 mode=2 flags=0x401 timeout=21474836 *** ksqgtl *** TM-00017EAA-00000000-00000000-00000000 mode=3 flags=0x401 timeout=21474836 ***
DML on EMP (object_id=17EAA) requests a Row-X and because of the referential integrity it request also a Row-S on the opposite side DEPT (object_id=17EA8)
Note that I did this example on 12c. That behaviour has changed in each Oracle version (and you can use event 10704 on your version in order to check on yours). Basically it was Row-S before 11g. Then 11g changed it to Row-X which introduced a lot of issues (see here and here for example). Fortunately 12c get it back to Row-S for two situations: insert into parent and delete from child.
SQL> DELETE FROM SCOTT.DEPT WHERE DEPTNO=0 ksqcnv: TM-00017EA8-00000000-00000000-00000000 mode=3 timeout=21474836 ksqcnv: TM-00017EAA-00000000-00000000-00000000 mode=5 timeout=21474836 ksqcnv: TM-00017EAA-00000000-00000000-00000000 mode=3 timeout=21474836
Here we see the lock conversions. On DEPT (object_id=17EA8) we had a Row-S (mode=2) and now requesting a Row-X (mode=3) because of the DML on it. And because of the unindexed foreign key we temporarily need a Share lock in addition to the Row-X we had. This is Share Row-X (mode=5). And it is converted back to Row-X as soon as the delete is done.
So remember the following in order to interpret the 10704 trace dump:
For more reference, you can get the lock type description, such as TM , from V$LOCK_TYPE:
SQL> select * from v$lock_type where type='TM';
TYPE | NAME | ID1_TAG | ID2_TAG | IS_ | IS_ | DESCRIPTION | CON_ID |
---|---|---|---|---|---|---|---|
TM | DML | object # | table/partition | YES | NO | Synchronizes accesses to an object | 0 |
And when ID1 is an object# then the first hexadecimal is the OBJECT_ID from DBA_OBJECTS. About the lock modes, you have the intended row locks which have the goal to block concurrent DDL:
mode=2 is Row-S, mode=3 is Row-X and the table locks which have the goal to prevent concurrent row locks : mode=4 is Share, mode=5 is Row-X + Share, mode=6 is eXclusive.
You can also check the blocking matrix:
http://prezi.com/cdckwsgqxeyi/oracle-table-lock-modes/
– Here is a quick script to display which objects are locked in Share. Parameters: owner tablename. Not in prod ! set linesize 150 column object_id format a30 alter session set events=’10046 trace name context forever, level 1 : 10704 trace name context forever, level 3′ tracefile_identifier=’ForeignKey'; DELETE FROM “&1.”.”&2.” WHERE rownum=0; ROLLBACK; alter session set events=’10046 trace name context off : 10704 trace name context off ‘; column tracefile new_value tracefile select tracefile from v$process where addr=(select paddr from v$session where sid=sys_context(‘USERENV’,’SID’)); host awk -F- ‘/ksqgtl … TM-.*mode=[456]/{print >”/dev/stderr” ; sql=sql sep q $2 q ;sep=”,”}END{print “select to_char(object_id,”q”FM0xxxxxxx”q”) objecT_id,owner,object_name from all_objects where to_char(object_id,”q”FM0xxxxxxx”q”) in(“sql”);”}’ q=”‘” &tracefile > afiedt.buf start afiedt.buf exit
[…] Check what you have in terms of locks (for more info on that please check Franck Pachot blog post http://blog.dbi-services.com/investigating-oracle-lock-issues-with-event-10704/): […]
[…] few weeks ago i was reading a great article written by Franck Pachot about investigating lock issue using event 10704 , so come to me the idea to use systemtap for this investigation as it give us more flexibility […]