{"id":3644,"date":"2014-03-14T06:44:00","date_gmt":"2014-03-14T05:44:00","guid":{"rendered":"https:\/\/www.dbi-services.com\/blog\/investigating-oracle-lock-issues-with-event-10704\/"},"modified":"2014-03-14T06:44:00","modified_gmt":"2014-03-14T05:44:00","slug":"investigating-oracle-lock-issues-with-event-10704","status":"publish","type":"post","link":"https:\/\/www.dbi-services.com\/blog\/investigating-oracle-lock-issues-with-event-10704\/","title":{"rendered":"Investigating Oracle lock issues with event 10704"},"content":{"rendered":"

By Franck Pachot<\/h2>\n

.
\nDid 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.\u00a0Of 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.\u00a0How do you check which lock is acquired by a statement?<\/p>\n

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.<\/p>\n

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.<\/p>\n

I set the trace (10704 level 3 for the locks, 10046 to see the statements):<\/p>\n

SQL> alter session set events='10046 trace name context forever, level 1 : 10704 trace name context forever, level 3' tracefile_identifier='ForeignKey';\nSession altered.<\/code><\/pre>\n
I delete from the DEPT table:<\/p>\n
SQL> DELETE FROM SCOTT.DEPT WHERE DEPTNO=0;\n0 rows deleted.<\/code><\/pre>\n
and then terminate the transaction:<\/p>\n
SQL> ROLLBACK;\nRollback complete.<\/code><\/pre>\n
and stop the trace:<\/p>\n
SQL> alter session set events='10046 trace name context off : 10704 trace name context off ';\nSession altered.<\/code><\/pre>\n
Now let’s get the trace file name:<\/p>\n
SQL> column tracefile new_value tracefile\nSQL> select tracefile from v$process where addr=(select paddr from v$session where sid=sys_context('USERENV','SID'));\n\nTRACEFILE\n--------------------------------------------------------------------------------\n\/u01\/app\/oracle\/diag\/rdbms\/demo\/DEMO\/trace\/DEMO_ora_28042_ForeignKey.trc<\/code><\/pre>\n
and grep the interresting lines from the trace file:<\/p>\n
SQL> host grep -A 1 -E 'ksqgtl [*]{3}|ksqrcl: [A-Z]|ksqcnv: [A-Z]|XCTEND|PARSE ERROR|PARSING' &tracefile<\/code><\/pre>\n
The output is:<\/p>\n
--\nPARSING IN CURSOR #140064855052048 len=37 dep=0 uid=0 oct=7 lid=0 tim=294484898588 hv=3450586461 ad='822782c8' sqlid='c1fnpd76urjax'\nDELETE FROM SCOTT.DEPT WHERE DEPTNO=0\n--\nksqgtl *** TM-00017EA8-00000000-00000000-00000000 mode=3 flags=0x401 timeout=21474836 ***\nksqgtl: xcb=0x8eb5bcf8, ktcdix=2147483647, topxcb=0x8eb5bcf8\n--\nksqgtl *** TM-00017EAA-00000000-00000000-00000000 mode=4 flags=0x401 timeout=21474836 ***\nksqgtl: xcb=0x8eb5bcf8, ktcdix=2147483647, topxcb=0x8eb5bcf8\n--\nksqrcl: TM-00017EAA-00000000-00000000-00000000\nksqcmi: TM-00017EAA-00000000-00000000-00000000 mode=0 timeout=0\n--\nPARSING IN CURSOR #140064855052048 len=8 dep=0 uid=0 oct=45 lid=0 tim=294484900906 hv=2761672982 ad='0' sqlid='8sst43uk9rk8q'\nROLLBACK\n--\nXCTEND rlbk=1, rd_only=1, tim=294484900964\nksqrcl: TM-00017EA8-00000000-00000000-00000000\nksqcmi: TM-00017EA8-00000000-00000000-00000000 mode=0 timeout=0\n--<\/code><\/pre>\n
In order to interpret it, we need one more information – the OBJECT_ID in hexadecimal:<\/p>\n
SQL> column object_name format a20\nSQL> column object_type format a20\nSQL> select object_id , to_char(object_id,'0XXXXXXX') , object_name,object_type from all_objects where owner='SCOTT' order by 2;\n\n OBJECT_ID \u00a0TO_CHAR(O OBJECT_NAME \u00a0 \u00a0 \u00a0 \u00a0 \u00a0OBJECT_TYPE\n---------- --------- -------------------- --------------------\n 97960 \u00a0 \u00a0 \u00a000017EA8 \u00a0DEPT \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 TABLE\n 97961 \u00a0 \u00a0 \u00a000017EA9 \u00a0PK_DEPT \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0INDEX\n 97962 \u00a0 \u00a0 \u00a000017EAA \u00a0EMP \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0TABLE\n 97963 \u00a0 \u00a0 \u00a000017EAB \u00a0PK_EMP \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 INDEX\n 97964 \u00a0 \u00a0 \u00a000017EAC \u00a0BONUS \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0TABLE\n 97965 \u00a0 \u00a0 \u00a000017EAD \u00a0SALGRADE \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 \u00a0 TABLE\n\n7 rows selected.<\/code><\/pre>\n
Great. Now let’s interpret that.
\nYou see the DELETE statement in the trace file (written by event 10046 which is the sql_trace). Then we have:<\/p>\n
\u00a0 ksqgtl *** TM-00017EA8-00000000-00000000-00000000 mode=3<\/samp><\/div>\n
…which means we get lock (ksqgtl) on table (lock_type=TM) SCOTT.DEPT (object_id=17EA8) in mode Row-X (mode=3).
\nThis is expected as we have the intention to delete rows, thus we request Row-X lock on the table.
\nAnd next to it you see:<\/p>\n
\u00a0 TM-00017EAA-00000000-00000000-00000000 mode=4<\/samp><\/div>\n
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.
\nThat lock is released immediately (which is the behaviour since 9.2) after the delete:<\/p>\n
ksqrcl: TM-00017EAA-00000000-00000000-00000000<\/samp><\/div>\n
ksqrcl is the function that releases lock. That is done before the end of the transaction (XCTEND from sql_trace).
\nAnd the Row-X on DEPT is released once the transaction is ended:<\/p>\n
ksqrcl: TM-00017EA8-00000000-00000000-00000000<\/samp><\/div>\n
If we create a index in order to avoid the Share mode lock:<\/p>\n
SQL> CREATE INDEX SCOTT.FK_DEPTNO on SCOTT.EMP(DEPTNO);\nIndex created.SQL> DELETE FROM SCOTT.DEPT WHERE DEPTNO=0;\n0 rows deleted.\nSQL> ROLLBACK;\nRollback complete.<\/code><\/pre>\n
…then here is what we get from the 10704 trace:<\/p>\n
ksqgtl *** TM-00017EAA-00000000-00000000-00000000 mode=4 flags=0x401 timeout=0 ***<\/samp><\/p>\n
This is the Share mode lock on the table when creating the index.
\nThis is what a delete on the parent generates:<\/p>\n
ksqgtl *** TM-00017EA8-00000000-00000000-00000000 mode=3 flags=0x401 timeout=21474836 ***\nksqgtl *** TM-00017EAA-00000000-00000000-00000000 mode=3 flags=0x401 timeout=21474836 ***\nXCTEND rlbk=1, rd_only=1, tim=294485532138\nksqrcl: TM-00017EAA-00000000-00000000-00000000\nksqrcl: TM-00017EA8-00000000-00000000-00000000<\/code><\/pre>\n
…which are only Row-X (mode=3) locks, but are released only at the end of the transaction.<\/p>\n
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.<\/p>\n
Let’s see an exemple when we first delete rows from the child\u00a0 (without the index on the foreign key):<\/p>\n
SQL> DELETE FROM SCOTT.EMP WHERE DEPTNO=0\nksqgtl *** TM-00017EA8-00000000-00000000-00000000 mode=2 flags=0x401 timeout=21474836 ***\nksqgtl *** TM-00017EAA-00000000-00000000-00000000 mode=3 flags=0x401 timeout=21474836 ***<\/code><\/pre>\n
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)<\/p>\n
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<\/a> and here<\/a> for example). Fortunately 12c get it back to Row-S for two situations: insert into parent and delete from child.<\/p>\n
SQL> DELETE FROM SCOTT.DEPT WHERE DEPTNO=0\nksqcnv: TM-00017EA8-00000000-00000000-00000000 mode=3 timeout=21474836\nksqcnv: TM-00017EAA-00000000-00000000-00000000 mode=5 timeout=21474836\nksqcnv: TM-00017EAA-00000000-00000000-00000000 mode=3 timeout=21474836<\/code><\/pre>\n
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.
\nAnd 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.<\/p>\n
So remember the following in order to interpret the 10704 trace dump:<\/p>\n