Thursday, November 17, 2011

Part 38 of series - Insert blocking horror....Insert on child table without index on foreign key locks parent table

The drop is in the ocean, and the ocean is in the drop. Who understands, and knows this? He Himself creates the wondrousplay of the world. He Himself contemplates it, and understands its true essence. 1 How rare are those who contemplate this spiritual wisdom. Through this, the supreme state of liberation is attained. 1 Pause The night is in the day, and the day is in the night. The same is true of hot and cold. No one else knows Hisstate and extent; without the Guru, this is not understood. 2 The female is in the male, and the male is in the female.Understand this, O God-realized being! The meditation is in the music, and knowledge is in meditation. Become Gurmukh, andspeak the Unspoken Speech. 3 The Light is in the mind, and the mind is in the Light. The Guru brings the five sensestogether, like brothers. Nanak is forever a sacrifice to those who enshrine love for the One Word of the Shabad.



Index of all the posts of Gurpartap Singh's Blog


The version of the database is 11.2.0.1, which is a 2 node RAC but all tests are done from node 1. The OS is RHEL 64 bit.

I was working on one of the vendor application where the session will go inactive and will put a table lock on the most popular table and the application will get stuck. We were not able to find the sql_id or sql_text of teh sql, though we know the session id. Once I kill that sid we are back in bussiness and all locks were gone. Then I did some research and found the sql_text of that session from logmier. Logminer is very friendly in 11gr2 and has a very good GUI interface in Grid control for 11gr2 databases.

the sql_text I found was the insert statement and that puzzled me. How can an insert statement block the table. I knew something to do with index on foreign key but I knew it happens with update statement but didn't know that it can happen with insert statement as well.

So, I simulated the situation in the test database of same version and same platform and found if we insert in the child table with a non indexed foreign key, it places "enq: TM-contention" on the parent table. So any DML session on the parent table will hang and if most of the transactions are going on that parent table then all those processes will hang you will run out of processes and in turn the database will hang. I have seen this behaviour most of the time on Vendor applications where thorugh testing of application is not done with full production load.

Here are all sql scripts to tackle such problem including the cron script that will email you the details of such a problem if it happens.


I am using the default famous schema scott here. If its not there just install it in your database to do this simple test.

The structure of the two tables involved is given below. Table dept is a parent table and the table EMP is
tha child to it. There is no index on column (scott.emp.dept)

CREATE TABLE SCOTT.DEPT
(
DEPTNO NUMBER(2),
DNAME VARCHAR2(14 BYTE),
LOC VARCHAR2(13 BYTE)
)
TABLESPACE USERS
PCTUSED 0
PCTFREE 10
INITRANS 1
MAXTRANS 255
STORAGE (
INITIAL 64K
NEXT 1M
MINEXTENTS 1
MAXEXTENTS UNLIMITED
PCTINCREASE 0
BUFFER_POOL DEFAULT
)
LOGGING
NOCOMPRESS
NOCACHE
NOPARALLEL
MONITORING;


CREATE UNIQUE INDEX SCOTT.PK_DEPT ON SCOTT.DEPT
(DEPTNO)
LOGGING
TABLESPACE USERS
PCTFREE 10
INITRANS 2
MAXTRANS 255
STORAGE (
INITIAL 64K
NEXT 1M
MINEXTENTS 1
MAXEXTENTS UNLIMITED
PCTINCREASE 0
BUFFER_POOL DEFAULT
)
NOPARALLEL;


ALTER TABLE SCOTT.DEPT ADD (
CONSTRAINT PK_DEPT
PRIMARY KEY
(DEPTNO)
USING INDEX SCOTT.PK_DEPT);


++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++


CREATE TABLE SCOTT.EMP
(
EMPNO NUMBER(4),
ENAME VARCHAR2(10 BYTE),
JOB VARCHAR2(9 BYTE),
MGR NUMBER(4),
HIREDATE DATE,
SAL NUMBER(7,2),
COMM NUMBER(7,2),
DEPTNO NUMBER(2)
)
TABLESPACE USERS
PCTUSED 0
PCTFREE 10
INITRANS 1
MAXTRANS 255
STORAGE (
INITIAL 64K
NEXT 1M
MINEXTENTS 1
MAXEXTENTS UNLIMITED
PCTINCREASE 0
BUFFER_POOL DEFAULT
)
LOGGING
NOCOMPRESS
NOCACHE
NOPARALLEL
MONITORING;


CREATE UNIQUE INDEX SCOTT.PK_EMP ON SCOTT.EMP
(EMPNO)
LOGGING
TABLESPACE USERS
PCTFREE 10
INITRANS 2
MAXTRANS 255
STORAGE (
INITIAL 64K
NEXT 1M
MINEXTENTS 1
MAXEXTENTS UNLIMITED
PCTINCREASE 0
BUFFER_POOL DEFAULT
)
NOPARALLEL;


ALTER TABLE SCOTT.EMP ADD (
CONSTRAINT PK_EMP
PRIMARY KEY
(EMPNO)
USING INDEX SCOTT.PK_EMP);

ALTER TABLE SCOTT.EMP ADD (
CONSTRAINT FK_DEPTNO
FOREIGN KEY (DEPTNO)
REFERENCES SCOTT.DEPT (DEPTNO));

===================================================================================================

I will do insert in the emp table and that will place a exlcusive lock on both the tables child table (emp) and
parent table (dept) .


Lets see that:
login as sysdba and execute following to check any locked objects:

SQL> select * from v$locked_object;

no rows selected

SQL>


Now will execute the following script to check blocking locks:

col blocking_status format a130
select l1.inst_id,s1.username '@' s1.machine
' Session status is ' s1.status ' ( SID=' s1.sid ' ) is blocking '
s2.username '@' s2.machine ' ( SID=' s2.sid ' ) ' AS blocking_status
from gv$lock l1, gv$session s1, gv$lock l2, gv$session s2
where s1.sid=l1.sid and s2.sid=l2.sid
and l1.BLOCK=1 and l2.request > 0
and l1.id1 = l2.id1
and l2.id2 = l2.id2


SQL> col blocking_status format a130
SQL> select l1.inst_id,s1.username '@' s1.machine
2 ' Session status is ' s1.status ' ( SID=' s1.sid ' ) is blocking '
3 s2.username '@' s2.machine ' ( SID=' s2.sid ' ) ' AS blocking_status
from gv$lock l1, gv$session s1, gv$lock l2, gv$session s2
4 5 where s1.sid=l1.sid and s2.sid=l2.sid
6 and l1.BLOCK=1 and l2.request > 0
7 and l1.id1 = l2.id1
8 and l2.id2 = l2.id2
9 ;

no rows selected

SQL>


Now execute the following to see the status of the active sessions i.e. what are active sessions doing in the database:


set line 300
set pages 1000
column inst_id format 9
column sid format 99999
column sql_id format a15
column LAST_CALL_ET format 9999999999
column event format a50
column a format a70
select b.INST_ID,b.sid,b.sql_id,
b.LAST_CALL_ET,b.event,b.username' 'b.machineb.program' '
b.BLOCKING_INSTANCE' 'b.BLOCKING_SESSIONservice_name'' a
from gv$session b
where b.event<>'SQL*Net message from client'
and b.event<> 'rdbms ipc message'
and b.event not like '%gcs remote message%'
and service_name not like '%SYS$BACKGROUND%'
order by b.inst_id,b.username,b.sql_id
;


SQL> set line 300
SQL> set pages 1000
SQL> column inst_id format 9
SQL> column sid format 99999
SQL> column sql_id format a15
SQL> column LAST_CALL_ET format 9999999999
column event format a50
SQL> SQL> column a format a70
SQL> select b.INST_ID,b.sid,b.sql_id,
2 b.LAST_CALL_ET,b.event,b.username' 'b.machineb.program' '
3 b.BLOCKING_INSTANCE' 'b.BLOCKING_SESSIONservice_name'' a
4 from gv$session b
5 where b.event<>'SQL*Net message from client'
6 and b.event<> 'rdbms ipc message'
7 and b.event not like '%gcs remote message%'
8 and service_name not like '%SYS$BACKGROUND%'
9 order by b.inst_id,b.username,b.sql_id
10 ;

INST_ID SID SQL_ID LAST_CALL_ET EVENT A
------- ------ --------------- ------------ -------------------------------------------------- ----------------------------------------------------------------------
1 6 91jar5kj4q216 0 PX Deq: Execute Reply SYS restart.rac.meditate.comsqlplus@restart.rac.meditate.com (TNS V1-V3) SY
S$USERS

1 167 91jar5kj4q216 0 PX Deq: Execution Msg SYS restart.rac.meditate.comoracle@restart.rac.meditate.coma (PZ99) SYS$USER
S

1 363 0 Streams AQ: waiting for messages in the queue SYS restart.rac.meditate.comaoraagent.bin@restart.rac.meditate.com (TNS V1-V3
) SYS$USERS

2 446 91jar5kj4q216 0 PX Deq: reap credit SYS restart.rac.meditate.comoracle@restart (PZ99) SYS$USERS

4 rows selected.

SQL>



Now lets start the transaction:


Open two new putty windows and login as scott in both of them:

In window 2 do following:

select * from emp;
select * from dept;


SQL> select * from emp;

EMPNO ENAME JOB MGR HIREDATE SAL COMM DEPTNO
---------- ---------- --------- ---------- ------------------ ---------- ---------- ----------
3 SCOTT CIO1 7839 17-NOV-11 2000 20 2
1 SCOTT CIO 7839 16-NOV-11 2000 20 1
2 SCOTT CIO1 7839 16-NOV-11 2000 20 2
7369 SMITH CLERK 7902 17-DEC-80 800 20
7499 ALLEN SALESMAN 7698 20-FEB-81 1600 300 30
7521 WARD SALESMAN 7698 22-FEB-81 1250 500 30
7566 JONES MANAGER 7839 02-APR-81 2975 20
7654 MARTIN SALESMAN 7698 28-SEP-81 1250 1400 30
7698 BLAKE MANAGER 7839 01-MAY-81 2850 30
7782 CLARK MANAGER 7839 09-JUN-81 2450 10
7788 SCOTT ANALYST 7566 19-APR-87 3000 20
7839 KING PRESIDENT 17-NOV-81 5000 10
7844 TURNER SALESMAN 7698 08-SEP-81 1500 0 30
7876 ADAMS CLERK 7788 23-MAY-87 1100 20
7900 JAMES CLERK 7698 03-DEC-81 950 30
7902 FORD ANALYST 7566 03-DEC-81 3000 20
7934 MILLER CLERK 7782 23-JAN-82 1300 10

17 rows selected.

SQL> select * from dept;

DEPTNO DNAME LOC
---------- -------------- -------------
1 COSTCENTER VANCOUVER
3 COSTCENTER VANCOUVER
2 EXPENSES SURREY
10 ACCOUNTING NEW YORK
20 RESEARCH DALLAS
30 SALES CHICAGO
40 OPERATIONS BOSTON

7 rows selected.

SQL>


In same session do:

insert into EMP values (4,'SCOTT','CIO1',7839,sysdate,2000,20,2);

Here is the output:

SQL> insert into EMP values (4,'SCOTT','CIO1',7839,sysdate,2000,20,2);

1 row created.

SQL>

Please note ---don't commit or rollback here.
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

Now in window 1:

Run the status check query:


select b.INST_ID,b.sid,b.sql_id,
b.LAST_CALL_ET,b.event,b.username' 'b.machineb.program' '
b.BLOCKING_INSTANCE' 'b.BLOCKING_SESSIONservice_name'' a
from gv$session b
where b.event<>'SQL*Net message from client'
and b.event<> 'rdbms ipc message'
and b.event not like '%gcs remote message%'
and service_name not like '%SYS$BACKGROUND%'
order by b.inst_id,b.username,b.sql_id
;


SQL> l
1 select b.INST_ID,b.sid,b.sql_id,
2 b.LAST_CALL_ET,b.event,b.username' 'b.machineb.program' '
3 b.BLOCKING_INSTANCE' 'b.BLOCKING_SESSIONservice_name'' a
4 from gv$session b
5 where b.event<>'SQL*Net message from client'
6 and b.event<> 'rdbms ipc message'
7 and b.event not like '%gcs remote message%'
8 and service_name not like '%SYS$BACKGROUND%'
9 order by b.inst_id,b.username,b.sql_id
10*
SQL> /

INST_ID SID SQL_ID LAST_CALL_ET EVENT A
------- ------ --------------- ------------ -------------------------------------------------- ----------------------------------------------------------------------
1 6 91jar5kj4q216 0 PX Deq: Execute Reply SYS restart.rac.meditate.comsqlplus@restart.rac.meditate.com (TNS V1-V3) SY
S$USERS

1 167 91jar5kj4q216 0 PX Deq: Execution Msg SYS restart.rac.meditate.comoracle@restart.rac.meditate.com (PZ99) SYS$USER
S

1 363 0 Streams AQ: waiting for messages in the queue SYS restart.rac.meditate.comoraagent.bin@restart.rac.meditate.com (TNS V1-V3
) SYS$USERS

2 48 g12bmbazvj86x 0 direct path read DBSNMP gridemagent@restart (TNS V1-V3) SYS$USERS
2 446 91jar5kj4q216 0 PX Deq: reap credit SYS restart.rac.meditate.comoracle@lrestart9 (PZ99) SYS$USERS

5 rows selected.

SQL>

Now run the query to see the locked objects, and see object_id 73201 and 73199 are locked with lock mode 3 i.e exclusive row lock
on table.



SQL> select * from v$locked_object;

XIDUSN XIDSLOT XIDSQN OBJECT_ID SESSION_ID ORACLE_USERNAME OS_USER_NAME PROCESS LOCKED_MODE
---------- ---------- ---------- ---------- ---------- ------------------------------ ------------------------------ ------------------------ -----------
10 2 224330 73201 128 SCOTT oracle 14937 3
10 2 224330 73199 128 SCOTT oracle 14937 3

2 rows selected.

SQL>

Now see where these object ids map to and they are mapping to SCOTT.EMP and SCOTT.DEPT

SQL> col OBJECT_NAME format a10
SQL> select object_id,object_name,owner from dba_objects where object_id in (73201,73199);

OBJECT_ID OBJECT_NAM OWNER
---------- ---------- ------------------------------
73201 EMP SCOTT
73199 DEPT SCOTT

2 rows selected.

SQL>


SQL>


Right now there are no blocking locks.


col blocking_status format a130
select l1.inst_id,s1.username '@' s1.machine
' Session status is ' s1.status ' ( SID=' s1.sid ' ) is blocking '
s2.username '@' s2.machine ' ( SID=' s2.sid ' ) ' AS blocking_status
from gv$lock l1, gv$session s1, gv$lock l2, gv$session s2
where s1.sid=l1.sid and s2.sid=l2.sid
and l1.BLOCK=1 and l2.request > 0
and l1.id1 = l2.id1
and l2.id2 = l2.id2
;


SQL> col blocking_status format a130
SQL> select l1.inst_id,s1.username '@' s1.machine
2 ' Session status is ' s1.status ' ( SID=' s1.sid ' ) is blocking '
3 s2.username '@' s2.machine ' ( SID=' s2.sid ' ) ' AS blocking_status
4 from gv$lock l1, gv$session s1, gv$lock l2, gv$session s2
5 where s1.sid=l1.sid and s2.sid=l2.sid
6 and l1.BLOCK=1 and l2.request > 0
7 and l1.id1 = l2.id1
8 and l2.id2 = l2.id2
9 ;

no rows selected

SQL>


++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

Now in window 3 excute the following sql:

update dept set DEPTNO=4 where DEPTNO=3;


SQL> show user
USER is "SCOTT"
SQL> update dept set DEPTNO=4 where DEPTNO=3;


and it will hang. now lets see what is going on in the database.


++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

Go to session 1 again and run the status query:

set line 300
set pages 1000
column inst_id format 9
column sid format 99999
column sql_id format a15
column LAST_CALL_ET format 9999999999
column event format a50
column a format a70
select b.INST_ID,b.sid,b.sql_id,
b.LAST_CALL_ET,b.event,b.username' 'b.machineb.program' '
b.BLOCKING_INSTANCE' 'b.BLOCKING_SESSIONservice_name'' a
from gv$session b
where b.event<>'SQL*Net message from client'
and b.event<> 'rdbms ipc message'
and b.event not like '%gcs remote message%'
and service_name not like '%SYS$BACKGROUND%'
order by b.inst_id,b.username,b.sql_id
;




SQL> set line 300
SQL> set pages 1000
SQL> column inst_id format 9
SQL> column sid format 99999
SQL> column sql_id format a15
SQL> column LAST_CALL_ET format 9999999999
SQL> column event format a50
column a format a70
SQL> SQL> select b.INST_ID,b.sid,b.sql_id,
b.LAST_CALL_ET,b.event,b.username' 'b.machineb.program' '
2 3 b.BLOCKING_INSTANCE' 'b.BLOCKING_SESSIONservice_name'' a
4 from gv$session b
5 where b.event<>'SQL*Net message from client'
and b.event<> 'rdbms ipc message'
and b.event not like '%gcs remote message%'
6 7 8 and service_name not like '%SYS$BACKGROUND%'
9 order by b.inst_id,b.username,b.sql_id
10 ;

INST_ID SID SQL_ID LAST_CALL_ET EVENT A
------- ------ --------------- ------------ -------------------------------------------------- ----------------------------------------------------------------------
1 286 d4qj9ft3rf761 63 enq: TM - contention SCOTT restart.rac.meditate.comsqlplus@restart.rac.meditate.com (TNS V1-V3) 1
128SYS$USERS

1 6 91jar5kj4q216 0 PX Deq: Execute Reply SYS restart.rac.meditate.comsqlplus@restart.rac.meditate.com (TNS V1-V3) SY
S$USERS

1 167 91jar5kj4q216 0 PX Deq: Execution Msg SYS restart.rac.meditate.comoracle@restart.rac.meditate.com (PZ99) SYS$USER
S

1 363 1 Streams AQ: waiting for messages in the queue SYS restart.rac.meditate.comoraagent.bin@restart.rac.meditate.com (TNS V1-V3
) SYS$USERS

2 446 91jar5kj4q216 0 PX Deq: reap credit SYS restart.rac.meditate.comoracle@restart (PZ99) SYS$USERS

5 rows selected.

SQL>
SQL>


See, session 286 is haing a wait event of "enq: TM - contention"


Now check the blocking locks as:

col blocking_status format a130
select l1.inst_id,s1.username '@' s1.machine
' Session status is ' s1.status ' ( SID=' s1.sid ' ) is blocking '
s2.username '@' s2.machine ' ( SID=' s2.sid ' ) ' AS blocking_status
from gv$lock l1, gv$session s1, gv$lock l2, gv$session s2
where s1.sid=l1.sid and s2.sid=l2.sid
and l1.BLOCK=1 and l2.request > 0
and l1.id1 = l2.id1
and l2.id2 = l2.id2
;



SQL> col blocking_status format a130
SQL> select l1.inst_id,s1.username '@' s1.machine
' Session status is ' s1.status ' ( SID=' s1.sid ' ) is blocking '
2 3 s2.username '@' s2.machine ' ( SID=' s2.sid ' ) ' AS blocking_status
4 from gv$lock l1, gv$session s1, gv$lock l2, gv$session s2
5 where s1.sid=l1.sid and s2.sid=l2.sid
6 and l1.BLOCK=1 and l2.request > 0
and l1.id1 = l2.id1
7 8 and l2.id2 = l2.id2 ;

INST_ID BLOCKING_STATUS
------- ----------------------------------------------------------------------------------------------------------------------------------
1 SCOTT@restart.rac.meditate.com Session status is INACTIVE ( SID=128 ) is blocking SCOTT@restart.rac.meditate.com ( SID=286 )

1 row selected.

SQL>


So, sid 128 with the session status being inactive is blocking sid 286, believe me here it sid 286 is running update on emp.


++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

Now I opened a new session in new window 4 that will execute insert in dept (parent table):

SQL> show user
USER is "SCOTT"
SQL> insert into dept values (5,'ENJOYMENT','HOLLYWOOD');


Its, also hung.


+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

Lets run status check query again in window 1 again:


set line 300
set pages 1000
column inst_id format 9
column sid format 99999
column sql_id format a15
column LAST_CALL_ET format 9999999999
column event format a50
column a format a70
select b.INST_ID,b.sid,b.sql_id,
b.LAST_CALL_ET,b.event,b.username' 'b.machineb.program' '
b.BLOCKING_INSTANCE' 'b.BLOCKING_SESSIONservice_name'' a
from gv$session b
where b.event<>'SQL*Net message from client'
and b.event<> 'rdbms ipc message'
and b.event not like '%gcs remote message%'
and service_name not like '%SYS$BACKGROUND%'
order by b.inst_id,b.username,b.sql_id
;


SQL> set line 300
set pages 1000
SQL> SQL> column inst_id format 9
SQL> column sid format 99999
SQL> column sql_id format a15
column LAST_CALL_ET format 9999999999
SQL> SQL> column event format a50
SQL> column a format a70
SQL> select b.INST_ID,b.sid,b.sql_id,
2 b.LAST_CALL_ET,b.event,b.username' 'b.machineb.program' '
3 b.BLOCKING_INSTANCE' 'b.BLOCKING_SESSIONservice_name'' a
from gv$session b
4 5 where b.event<>'SQL*Net message from client'
6 and b.event<> 'rdbms ipc message'
7 and b.event not like '%gcs remote message%'
and service_name not like '%SYS$BACKGROUND%'
8 9 order by b.inst_id,b.username,b.sql_id
10 ;

INST_ID SID SQL_ID LAST_CALL_ET EVENT A
------- ------ --------------- ------------ -------------------------------------------------- ----------------------------------------------------------------------
1 286 d4qj9ft3rf761 522 enq: TM - contention SCOTT restart.rac.meditate.comsqlplus@restart.rac.meditate.com (TNS V1-V3) 1
128SYS$USERS

1 445 g41gxvszt15g2 135 enq: TM - contention SCOTT restart.rac.meditate.comsqlplus@restart.rac.meditate.com (TNS V1-V3)
SYS$USERS

1 167 91jar5kj4q216 0 PX Deq: Execution Msg SYS restart.rac.meditate.comoracle@restart.rac.meditate.com (PZ99) SYS$USER
S

1 6 91jar5kj4q216 0 SQL*Net message to client SYS restart.rac.meditate.comsqlplus@restart.rac.meditate.com (TNS V1-V3) SY
S$USERS

1 363 0 Streams AQ: waiting for messages in the queue SYS restart.rac.meditate.comoraagent.bin@restart.rac.meditate.com (TNS V1-V3
) SYS$USERS

2 446 91jar5kj4q216 0 PX Deq: reap credit SYS restart.rac.meditate.comoracle@restart (PZ99) SYS$USERS

6 rows selected.

SQL>




now session 286 and session 445 are hung and wait event is "enq: TM - contention" i.e. a table lock.
445 is trying to insert in parent table.


Lets see the blocking sessions now:

col blocking_status format a130
select l1.inst_id,s1.username '@' s1.machine
' Session status is ' s1.status ' ( SID=' s1.sid ' ) is blocking '
s2.username '@' s2.machine ' ( SID=' s2.sid ' ) ' AS blocking_status
from gv$lock l1, gv$session s1, gv$lock l2, gv$session s2
where s1.sid=l1.sid and s2.sid=l2.sid
and l1.BLOCK=1 and l2.request > 0
and l1.id1 = l2.id1
and l2.id2 = l2.id2
;




SQL> col blocking_status format a130
SQL> select l1.inst_id,s1.username '@' s1.machine
2 ' Session status is ' s1.status ' ( SID=' s1.sid ' ) is blocking '
3 s2.username '@' s2.machine ' ( SID=' s2.sid ' ) ' AS blocking_status
4 from gv$lock l1, gv$session s1, gv$lock l2, gv$session s2
5 where s1.sid=l1.sid and s2.sid=l2.sid
6 and l1.BLOCK=1 and l2.request > 0
7 and l1.id1 = l2.id1
8 and l2.id2 = l2.id2 ;

INST_ID BLOCKING_STATUS
------- ----------------------------------------------------------------------------------------------------------------------------------
1 SCOTT@restart.rac.meditate.com Session status is INACTIVE ( SID=128 ) is blocking SCOTT@restart.rac.meditate.com ( SID=445 )
1 SCOTT@restart.rac.meditate.com Session status is INACTIVE ( SID=128 ) is blocking SCOTT@restart.rac.meditate.com ( SID=286 )

2 rows selected.

SQL>


Now lets see locks in more detail. Execute the following query against blocking session :

col OSUSER format a10
col TERMINAL format a15
col username format a10
col OBJECT_NAME format a20
col "Session Status" format a17
SELECT B.SID, C.USERNAME, C.OSUSER, C.TERMINAL, C.status "Session Status",
DECODE(B.ID2, 0, A.OBJECT_NAME,
'Trans-'to_char(B.ID1)) OBJECT_NAME, B.TYPE,
DECODE(B.LMODE,0,'--Waiting--',
1,'Null',
2,'Row Share',
3,'Row Excl i.e. TM - contention',
4,'Share',
5,'Sha Row Exc',
6,'Exclusive',
'Other') "Lock Mode",
DECODE(B.REQUEST,0,' ',
1,'Null',
2,'Row Share',
3,'Row Excl',
4,'Share',
5,'Sha Row Exc',
6,'Exclusive',
'Other') "Req Mode"
from DBA_OBJECTS A, V$LOCK B, V$SESSION C
where A.OBJECT_ID(+) = B.ID1
and B.SID = C.SID
AND c.sid = 128
and C.USERNAME is not null
order by B.SID, B.ID2;



SQL> col OSUSER format a10
SQL> col TERMINAL format a15
SQL> col username format a10
SQL> col OBJECT_NAME format a20
col "Session Status" format a17
SQL> SQL> SELECT B.SID, C.USERNAME, C.OSUSER, C.TERMINAL, C.status "Session Status",
DECODE(B.ID2, 0, A.OBJECT_NAME,
2 3 'Trans-'to_char(B.ID1)) OBJECT_NAME, B.TYPE,
DECODE(B.LMODE,0,'--Waiting--',
4 5 1,'Null',
6 2,'Row Share',
7 3,'Row Excl i.e. TM - contention',
4,'Share',
8 9 5,'Sha Row Exc',
6,'Exclusive',
10 11 'Other') "Lock Mode",
DECODE(B.REQUEST,0,' ',
1,'Null',
12 13 14 2,'Row Share',
3,'Row Excl',
15 16 4,'Share',
17 5,'Sha Row Exc',
18 6,'Exclusive',
19 'Other') "Req Mode"
from DBA_OBJECTS A, V$LOCK B, V$SESSION C
20 21 where A.OBJECT_ID(+) = B.ID1
22 and B.SID = C.SID
23 AND c.sid = 128
24 and C.USERNAME is not null
order by B.SID, B.ID2; 25

SID USERNAME OSUSER TERMINAL Session Status OBJECT_NAME TY Lock Mode Req Mode
------ ---------- ---------- --------------- ----------------- -------------------- -- ----------------------------- -----------
128 SCOTT oracle pts/1 INACTIVE ORA$BASE AE Share
128 SCOTT oracle pts/1 INACTIVE DEPT TM Row Excl i.e. TM - contention
128 SCOTT oracle pts/1 INACTIVE EMP TM Row Excl i.e. TM - contention
128 SCOTT oracle pts/1 INACTIVE Trans-655362 TX Exclusive

4 rows selected.

SQL>



Observe its lock mode is "TM Row Excl" i.e. enqueue is "TM - contention" i.e. table level lock on tables DEPT and EMP.


Now lets see what v$transaction is showing by running the following query:


col Seesion_status format a17
col Transaction_Status format a25
SELECT vs.sid,
vs.username,
vs.status Seesion_status,
vs.sql_id,
vs.event,
vt.start_time ,
vt.status Transaction_Status,
vt.START_SCN,
vt.DEPENDENT_SCN,
vt.XID
FROM v$transaction vt,v$session vs
WHERE vt.ses_addr=vs.saddr AND vs.sid=128;




SQL> col Seesion_status format a17
SQL> col Transaction_Status format a25
SQL> SELECT vs.sid,
2 vs.username,
3 vs.status Seesion_status,
4 vs.sql_id,
5 vt.start_time ,
6 vt.status Transaction_Status,
7 vt.START_SCN,
vt.DEPENDENT_SCN,
8 9 vt.XID
10 FROM v$transaction vt,v$session vs
11 WHERE vt.ses_addr=vs.saddr AND vs.sid=128;

SID USERNAME SEESION_STATUS SQL_ID EVENT START_TIME TRANSACTION_STATUS START_SCN DEPENDENT_SCN XID
------ ---------- ----------------- -------------- ------------------------------------------------- -------------------- ------------------------- ---------- ------------- ----------------
128 SCOTT INACTIVE SQL*Net message from client 11/18/11 00:16:56 ACTIVE 14702206 0 0A0002004A6C0300

1 row selected.

SQL>


Note in all above we have the session 128 locking two tables i.e. we cannot do DML against them and also the session 128 is inactive.

Now lets map v$transaction with table flashback_transaction_query and see the undo statement using the following query:


col LOGON_USER format a10
col TABLE_OWNER format a10
col TABLE_NAME format a15
col undo_chg format 9999
col OPERATION format a10
col UNDO_SQL format a30
SELECT
vs.sid,
vs.status Session_Status,
to_char(start_timestamp,'DD-MM-YY HH24:MI:SS'),
logon_user,
table_owner,
table_name,
undo_change# undo_chg,
operation,
undo_sql,
vt.status Transaction_Status,
ftq.XID,
ftq.START_SCN,
ftq.COMMIT_SCN
FROM flashback_transaction_query ftq,v$transaction vt,v$session vs
WHERE ftq.xid = vt.xid and vt.ses_addr=vs.saddr AND vs.sid=128;


SQL> col LOGON_USER format a10
SQL> col TABLE_OWNER format a10
SQL> col TABLE_NAME format a15
SQL> col undo_chg format 9999
SQL> col OPERATION format a10
SQL> col UNDO_SQL format a30
SQL> SELECT
2 vs.sid,
vs.status Session_Status,
to_char(start_timestamp,'DD-MM-YY HH24:MI:SS'),
3 4 5 logon_user,
table_owner,
table_name,
6 7 8 undo_change# undo_chg,
operation,
9 10 undo_sql,
vt.status Transaction_Status,
11 12 ftq.XID,
13 ftq.START_SCN,
14 ftq.COMMIT_SCN
FROM flashback_transaction_query ftq,v$transaction vt,v$session vs
15 WHERE ftq.xid = vt.xid and vt.ses_addr=vs.saddr AND vs.sid=128;
16

SID SESSION_ TO_CHAR(START_TIM LOGON_USER TABLE_OWNE TABLE_NAME UNDO_CHG OPERATION UNDO_SQL TRANSACTION_STATUS XID START_SCN COMMIT_SCN
------ -------- ----------------- ---------- ---------- --------------- -------- ---------- ------------------------------ ------------------------- ---------------- ---------- ----------
128 INACTIVE 18-11-11 00:16:55 SCOTT SCOTT EMP 1 INSERT delete from "SCOTT"."EMP" wher ACTIVE 0A0002004A6C0300 14702206
e ROWID = 'AAAR3xAAEAAAACUAAB'
;

128 INACTIVE 18-11-11 00:16:55 SCOTT 2 BEGIN ACTIVE 0A0002004A6C0300 14702206

2 rows selected.

SQL> SQL>


i.e. insert is the culprit and is the blocker.


To find the sql text in session 128 you need to use logminer. It has a very good interface in grid control for 11g databases.


=============================================================================================================================

I was having lots of problems when this happened on my vendor system so created a small shell script to get alerts
to my email when this type of thing happens.


Here is my script and run it every 5 minutes in cron:


$ cat locking.sh
#!/usr/bin/ksh
# Check details of blocking session
# usage:
# locking.sh $SID
# example (if sid of the database is KHEMHARAN1 use:
# locking.sh KHEMHARAN1

export PATH=$PATH:/usr/local/bin

export ORACLE_SID=$1
export ORAENV_ASK=NO
. oraenv

ps -efgrep pmongrep ${ORACLE_SID} > /dev/null

if [ $? = 1 ]
then
exit
fi

DT=`date +%Y%m%d%H%M%S`

ALERT_LOG=$HOME/gurpartap/log/alert_long_session_${ORACLE_SID}.log
echo " " > ${ALERT_LOG}

print " set head off verify off feed off pages 0 lin 120
conn system/xxxxx
set serveroutput on
set line 300
select 'long running sql 'sql_id' from 'username'@'machine' over 'LAST_CALL_ET' seconds sid='sid','serial#status
from v\$session
where
username like '%SCOTT' and
-- and service_name like '%sv1' and
(LAST_CALL_ET >180 and
status='ACTIVE')
or (LAST_CALL_ET >3600 and
status='KILLED');

SET SERVEROUTPUT ON;
declare
cursor cur is
select distinct s1.sid
from gv\$lock l1, gv\$session s1, gv\$lock l2, gv\$session s2
where s1.sid=l1.sid and s2.sid=l2.sid
and l1.BLOCK=1 and l2.request > 0
and l1.id1 = l2.id1
and l2.id2 = l2.id2 ;
cursor cur2 (p_sid number) is
SELECT
B.SID,
C.USERNAME,
C.OSUSER,
C.TERMINAL,
C.status "Session_Status",
DECODE(B.ID2, 0, A.OBJECT_NAME,'Trans-'to_char(B.ID1)) "OBJECT_NAME",
B.TYPE,
DECODE(B.LMODE,0,'--Waiting--',
1,'Null',
2,'Row Share',
3,'Row Excl i.e. TM - contention',
4,'Share',
5,'Sha Row Exc',
6,'Exclusive',
'Other') "Lock_Mode",
DECODE(B.REQUEST,0,' ',
1,'Null',
2,'Row Share',
3,'Row Excl',
4,'Share',
5,'Sha Row Exc',
6,'Exclusive',
'Other') "Req_Mode"
from DBA_OBJECTS A, V\$LOCK B, V\$SESSION C
where A.OBJECT_ID(+) = B.ID1
and B.SID = C.SID
AND c.sid = p_sid
and C.USERNAME is not null
order by B.SID, B.ID2;
cursor cur3 (p_sid number) is
SELECT vs.sid,
vs.username,
vs.status Seesion_status,
vs.sql_id,
vt.start_time ,
vt.status Transaction_Status,
vt.START_SCN,
vt.DEPENDENT_SCN,
vt.XID
FROM v\$transaction vt,v\$session vs
WHERE vt.ses_addr=vs.saddr AND vs.sid=p_sid;
cursor cur4 (p_sid number) is
SELECT
vs.sid,
vs.status Session_Status,
to_char(start_timestamp,'DD-MM-YY HH24:MI:SS') Start_Timestamp,
logon_user,
table_owner,
table_name,
undo_change# undo_chg,
operation,
undo_sql,
vt.status Transaction_Status,
ftq.XID,
ftq.START_SCN,
ftq.COMMIT_SCN
FROM flashback_transaction_query ftq,v\$transaction vt,v\$session vs
WHERE ftq.xid = vt.xid and vt.ses_addr=vs.saddr AND vs.sid=p_sid;
begin
for rec in cur loop
dbms_output.put_line('SID Username OSuser Terminal Session_Status TYPE OBJECT_NAME Lock_Mode Req_Mod');
for rec2 in cur2(rec.sid) loop
dbms_output.put_line(rec2.SID ' ' rec2.username ' ' rec2.osuser ' ' rec2.terminal ' ' rec2.Session_Status ' ' rec2.TYPE ' ' rec2.OBJECT_NAME ' ' rec2.Lock_Mode ' ' rec2.Req_Mode);
end loop;
dbms_output.put_line(chr(10));
dbms_output.put_line('SID Username Session_Status XID start_time TXN_Status START_SCN DEPENDENT_SCN sql_id');
for rec3 in cur3(rec.sid) loop
dbms_output.put_line(rec3.SID ' ' rec3.username ' ' rec3.Seesion_status ' ' rec3.XID ' ' rec3.start_time ' ' rec3.Transaction_Status ' ' rec3.START_SCN ' ' rec3.DEPENDENT_SCN ' ' rec3.sql_id);
end loop;
dbms_output.put_line(chr(10));
dbms_output.put_line('SID Session_Status Start_Timestamp Logon_User Operation XID Table_Owner Table_Name');
for rec4 in cur4(rec.sid) loop
dbms_output.put_line(rec4.SID ' ' rec4.Session_Status ' ' rec4.start_timestamp ' ' rec4.logon_user ' ' rec4.operation ' ' rec4.xid ' 'rec4.table_owner ' ' rec4.table_name);
end loop;
dbms_output.put_line(chr(10));
dbms_output.put_line('Operation XID START_SCN undo_sql COMMIT_SCN');
for rec5 in cur4(rec.sid) loop
dbms_output.put_line(rec5.operation ' ' rec5.xid ' ' rec5.START_SCN ' 'rec5.undo_sql ' ' rec5.COMMIT_SCN);
end loop;
end loop;
end;
/



" sqlplus -s /nolog > ${ALERT_LOG}

grep "long running sql" ${ALERT_LOG} > /dev/null

if [ $? = 0 ]
then
mailx -s "long running online sql found in ${ORACLE_SID} at ${DT}, call dba " "xxxxx.xxxx@yahoo.com" < ${ALERT_LOG} fi ========================================================================================================================== The email output from this script looks like: 'LONGRUNNINGSQL'SQL_ID'FROM'USERNAME'@'MACHINE'OVER'LAST_CALL_ET'SECONDSSID='SID','SERIAL#STATUS --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- long running sql 1gaj97tkvy8jd from SCOTT@restart.rac.meditate.com over 255 seconds sid=286,455ACTIVE 1 row selected. SID Username OSuser Terminal Session_Status TYPE OBJECT_NAME Lock_Mode Req_Mod 128 SCOTT oracle pts/1 INACTIVE AE ORA$BASE Share 128 SCOTT oracle pts/1 INACTIVE TM EMP Row Excl i.e. TM - contention 128 SCOTT oracle pts/1 INACTIVE TM DEPT Row Excl i.e. TM - contention 128 SCOTT oracle pts/1 INACTIVE TX Trans-65538 Exclusive SID Username Session_Status XID start_time TXN_Status START_SCN DEPENDENT_SCN sql_id 128 SCOTT INACTIVE 010002007A720000 11/17/11 23:36:57 ACTIVE 14694222 0 SID Session_Status Start_Timestamp Logon_User Operation XID Table_Owner Table_Name 128 INACTIVE 17-11-11 23:36:56 SCOTT INSERT 010002007A720000 SCOTT EMP 128 INACTIVE 17-11-11 23:36:56 SCOTT BEGIN 010002007A720000 Operation XID START_SCN undo_sql COMMIT_SCN INSERT 010002007A720000 14694222 delete from "SCOTT"."EMP" where ROWID = 'AAAR3xAAEAAAACUAAB'; BEGIN 010002007A720000 14694222 PL/SQL procedure successfully completed. ==========================================================================================================================

Now the fix.

I will rollback all the transactions and will create index on colum dept of table scott.emp and see what happens. To see the missing indexes on foreign key of a table use following script:

SELECT owner'.'table_name'.'column_name FROM (
SELECT c.owner,c.table_name, cc.column_name
FROM sys.dba_constraints c, sys.dba_cons_columns cc, sys.dba_constraints pk
WHERE c.constraint_name = cc.constraint_name
AND c.constraint_type = 'R'
AND pk.CONSTRAINT_NAME=c.R_CONSTRAINT_NAME
and pk.table_name like '%&parent_table_name%'
and c.owner like '%&owner%'
MINUS
SELECT i.owner,i.table_name, ic.column_name
FROM sys.dba_indexes i, sys.dba_ind_columns ic
WHERE i.index_name = ic.index_name and ic.COLUMN_POSITION=1
)
ORDER BY table_name;


Output is as:


SQL> l
1 SELECT owner'.'table_name'.'column_name FROM (
2 SELECT c.owner,c.table_name, cc.column_name
3 FROM sys.dba_constraints c, sys.dba_cons_columns cc, sys.dba_constraints pk
4 WHERE c.constraint_name = cc.constraint_name
5 AND c.constraint_type = 'R'
6 AND pk.CONSTRAINT_NAME=c.R_CONSTRAINT_NAME
7 and pk.table_name like '%&parent_table_name%'
8 and c.owner like '%&owner%'
9 MINUS
10 SELECT i.owner,i.table_name, ic.column_name
11 FROM sys.dba_indexes i, sys.dba_ind_columns ic
12 WHERE i.index_name = ic.index_name and ic.COLUMN_POSITION=1
13 )
14* ORDER BY table_name
SQL> /
Enter value for parent_table_name: DEPT
old 7: and pk.table_name like '%&parent_table_name%'
new 7: and pk.table_name like '%DEPT%'
Enter value for owner: SCOTT
old 8: and c.owner like '%&owner%'
new 8: and c.owner like '%SCOTT%'

OWNER'.'TABLE_NAME'.'COLUMN_NAME
------------------------------------------------------------------------------------------------------------------------
SCOTT.EMP.DEPTNO

1 row selected.

SQL>



CREATE INDEX SCOTT.DEPT_IX ON SCOTT.EMP
(DEPTNO)
LOGGING;


Output is as:

SQL> CREATE INDEX SCOTT.DEPT_IX ON SCOTT.EMP
(DEPTNO)
LOGGING;
2 3
Index created.

SQL>

================================================================================================


Lets repeat the scenario after the fix now:



In session 2 do following:

insert into EMP values (4,'SCOTT','CIO1',7839,sysdate,2000,20,2);

SQL> insert into EMP values (4,'SCOTT','CIO1',7839,sysdate,2000,20,2);

1 row created.

SQL>


++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

In window 3 do same update and this time it doesn't hang and just updates and even commit works:

SQL> update dept set DEPTNO=4 where DEPTNO=3;

1 row updated.

SQL> commit;

Commit complete.

SQL>

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++


In window 4 do same inser and this time it doesn't hang and just inserts and even commit works:

SQL> insert into dept values (5,'ENJOYMENT','HOLLYWOOD');

1 row created.

SQL> commit;

Commit complete.

SQL>

============================================================================================
============================================================================================




This body is frail; old age is overtaking it. Those whoare protected by the Guru are saved, while others die, to be reincarnated; they continue coming and going. Others die, to bereincarnated; they continue coming and going, and in the end, they depart with regret. Without the Name, there is no peace.According to one.s actions here, so are the rewards received; the self-willed manmukhs lose their honor. In the City of Death,there is pitch darkness and huge clouds of dust; neither sister nor brother is there. This body is frail; old age is overtaking it.

No comments:

Post a Comment