Blog - comments

Hi Olivier, That's a good question. I think the reason is that data_object_id cannot identify a segm...
@toms and others: -- create your output: iozone -Rab output.xls /u01-- scp off to desptop, or to loc...
Scott
Hi Frank,Very interesting post ! Congratulations for starting an Oracle 7 ; did you virtualize an HP...
Olivier Berthommé
Belle démo, je crois que je vais te la piquer ! Mais as tu essayé un DBCC CHECKCONSTRAINTS ou un DBC...
SQLpro

Thanks Franck , you are a savior! Great article indeed.

Prasad
Blog Franck Pachot Investigating Oracle lock issues with event 10704

dbi services Blog

Welcome to the dbi services Blog! This IT blog focuses on database, middleware, and OS technologies such as Oracle, Microsoft SQL Server & SharePoint, EMC Documentum, MySQL, PostgreSQL, Sybase, Unix/Linux, etc. The dbi services blog represents the view of our consultants, not necessarily that of dbi services. Feel free to comment on our blog postings.

  • Home
    Home This is where you can find all the blog posts throughout the site.
  • Categories
    Categories Displays a list of categories from this blog.
  • Tags
    Tags Displays a list of tags that have been used in the blog.
  • Bloggers
    Bloggers Search for your favorite blogger from this site.

Investigating Oracle lock issues with event 10704

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:

  ksqgtl *** TM-00017EA8-00000000-00000000-00000000 mode=3

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

  TM-00017EAA-00000000-00000000-00000000 mode=4

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: TM-00017EAA-00000000-00000000-00000000

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:

ksqrcl: TM-00017EA8-00000000-00000000-00000000

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';
TYPE NAMEID1_TAGID2_TAGIS_IS_DESCRIPTIONCON_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: 

CaptureLockMatrix.PNG

http://prezi.com/cdckwsgqxeyi/oracle-table-lock-modes/

Rate this blog entry:
1

I'm a Senior Consultant, and Oracle Technology Leader at dbi services (Switzerland).


Certified DBA (OCM 11g, OCP 12c, Performance Tuning Expert, Exadata Implementation) I cover all database areas: architecture, data modeling, database design, tuning, operation, and training.


My preferred area is troubleshooting oracle and performance tuning, especially when I acheive to enable an efficient collaboration between the developers and the operational team.
Besides this blog, I participate in the Oracle Community in forums, blogs, articles and presentation.

All that is referenced from my twitter account:
 


    O_Database12c_Admin_Professional_clrOCE_ODb11gPerfTun_clr11gocm_logoalt

Comments

  • Franck Pachot
    Franck Pachot Thursday, 10 July 2014

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

Leave your comment

Guest Saturday, 01 November 2014
AddThis Social Bookmark Button
Deutsch (DE-CH-AT)   French (Fr)

Contact

Contact us now!

Send us your request!

Our workshops

dbi FlexService SLA - ISO 20000 certified.

dbi FlexService SLA ISO 20000

Expert insight from insiders!

Fixed Price Services

dbi FlexService SLA - ISO 20000 certified.

dbi FlexService SLA ISO 20000

A safe investment: our IT services at fixed prices!

Your flexible SLA

dbi FlexService SLA - ISO 20000 certified.

dbi FlexService SLA ISO 20000

ISO 20000 certified & freely customizable!

dbi services Newsletter