Investigating Oracle lock issues with event 10704

By Franck Pachot

.
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:

• ksqgtl: lock request
• ksqcnv: lock conversion
• ksqrrcl: lock release

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';

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/