Skip to Main Content

Breadcrumb

Question and Answer

Chris Saxon

Thanks for the question, tan.

Asked: May 05, 2017 - 9:32 am UTC

Last updated: May 08, 2017 - 9:03 am UTC

Version: 11.2.0.4

Viewed 1000+ times

You Asked

Hi,
Forgive my pool english,I try my best to make my question clear.
I think deadlock only accured in a tansaction ,etc,
session 1 session 2
start transaction start transaction
1. update t1 set name='aa' where id=1;
2、update t1 set name='bb' where id=2;
3.update t1 set name='bbb' where id=2;
4. update t1 set name='aaa' where id=1;

ok,the deaklock accured.

But these days ,our RD have turned off the transaction in jdbc,we still got many application deadlock,I am confused for this,because there is no transaction for every session,why it still cause deadlock ,below is the deadlock tracefile.
Wait for your comment,thank you very much!

Hi,
Forgive my pool english,I try my best to make my question clear.
I think deadlock only accured in a tansaction ,etc,
session 1 session 2
start transaction start transaction
1. update t1 set name='aa' where id=1;
2、update t1 set name='bb' where id=2;
3.update t1 set name='bbb' where id=2;
4. update t1 set name='aaa' where id=1;

ok,the deaklock accured.

But these days ,our RD have turned off the transaction in jdbc,we still got many application deadlock,I am confused for this,because there is no transaction for every session,why it still cause deadlock ,below is the deadlock tracefile.
Wait for your comment,thank you very much!

Trace file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_30977.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/dbhome_1
System name: Linux
Node name: SIT1-DB1-primary
Release: 3.8.13-44.1.1.el6uek.x86_64
Version: #2 SMP Wed Sep 10 06:10:25 PDT 2014
Machine: x86_64
VM name: VMWare Version: 6
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 74
Unix process pid: 30977, image: oracle@SIT1-DB1-primary


*** 2017-04-29 18:18:15.497
*** SESSION ID:(892.41657) 2017-04-29 18:18:15.497
*** CLIENT ID:() 2017-04-29 18:18:15.497
*** SERVICE NAME:(orcl) 2017-04-29 18:18:15.497
*** MODULE NAME:(oracle@SIT1-DB1-primary (TNS V1-V3)) 2017-04-29 18:18:15.497
*** ACTION NAME:() 2017-04-29 18:18:15.497

KZIADGSYSOPERAUTH: connection is not secure.
KZIADGSYSOPERAUTH status = 72
Trace file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_30977.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/dbhome_1
System name: Linux
Node name: SIT1-DB1-primary
Release: 3.8.13-44.1.1.el6uek.x86_64
Version: #2 SMP Wed Sep 10 06:10:25 PDT 2014
Machine: x86_64
VM name: VMWare Version: 6
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 268
Unix process pid: 30977, image: oracle@SIT1-DB1-primary


*** 2017-05-02 15:10:09.201
*** SESSION ID:(1672.16519) 2017-05-02 15:10:09.201
*** CLIENT ID:() 2017-05-02 15:10:09.201
*** SERVICE NAME:(orcl) 2017-05-02 15:10:09.201
*** MODULE NAME:(JDBC Thin Client) 2017-05-02 15:10:09.201
*** ACTION NAME:() 2017-05-02 15:10:09.201



*** 2017-05-02 15:10:09.201
DEADLOCK DETECTED ( ORA-00060 )

[Transaction Deadlock]

The following deadlock is not an ORACLE error. It is a
deadlock due to user error in the design of an application
or from issuing incorrect ad-hoc SQL. The following
information may aid in determining the deadlock:

Deadlock graph:
---------Blocker(s)-------- ---------Waiter(s)---------
Resource Name process session holds waits process session holds waits
TX-00660003-0004f8ba 268 1672 X 267 1311 X
TX-0061000b-0003fbba 267 1311 X 265 439 X
TX-001e0006-00241d24 265 439 X 268 1672 X

session 1672: DID 0001-010C-000178F5 session 1311: DID 0001-010B-00000731
session 1311: DID 0001-010B-00000731 session 439: DID 0001-0109-000107DF
session 439: DID 0001-0109-000107DF session 1672: DID 0001-010C-000178F5

Rows waited on:
Session 1672: obj - rowid = 00015916 - AAAXt0AAJAAJ6UCAA5
(dictionary objn - 88342, file - 9, block - 2598146, slot - 57)
Session 1311: obj - rowid = 00015916 - AAAXt0AAJAAJ6UCAA8
(dictionary objn - 88342, file - 9, block - 2598146, slot - 60)
Session 439: obj - rowid = 00015916 - AAAXt0AAJAAJ6UCAA6
(dictionary objn - 88342, file - 9, block - 2598146, slot - 58)

----- Information for the OTHER waiting sessions -----
Session 1311:
sid: 1311 ser: 50379 audsid: 14615172 user: 84/PAYADM
flags: (0x100045) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
flags2: (0x40009) -/-/INC
pid: 267 O/S info: user: oracle, term: UNKNOWN, ospid: 30975
image: oracle@SIT1-DB1-primary
client details:
O/S info: user: root, term: unknown, ospid: 1234
machine: 819e0b272776 program: JDBC Thin Client
application name: JDBC Thin Client, hash value=2546894660
current SQL:
update URMTSMLG set CHK_NO = :1 ,ERR_NUM=:2 , SEND_NUM=:3 ,
SEND_TIME=:4 , SEND_SECONDS=:5 , SUC_NUM=:6 ,
FLAG=:7 where SM_ID=:8

Session 439:
sid: 439 ser: 36613 audsid: 14615171 user: 84/PAYADM
flags: (0x100045) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
flags2: (0x40009) -/-/INC
pid: 265 O/S info: user: oracle, term: UNKNOWN, ospid: 30973
image: oracle@SIT1-DB1-primary
client details:
O/S info: user: root, term: unknown, ospid: 1234
machine: 819e0b272776 program: JDBC Thin Client
application name: JDBC Thin Client, hash value=2546894660
current SQL:
update URMTSMLG set CHK_NO = :1 ,ERR_NUM=:2 , SEND_NUM=:3 ,
SEND_TIME=:4 , SEND_SECONDS=:5 , SUC_NUM=:6 ,
FLAG=:7 where SM_ID=:8

----- End of information for the OTHER waiting sessions -----

Information for THIS session:

----- Current SQL Statement for this session (sql_id=3wpfd4krkujjw) -----
update URMTSMLG set CHK_NO = :1 ,ERR_NUM=:2 , SEND_NUM=:3 ,
SEND_TIME=:4 , SEND_SECONDS=:5 , SUC_NUM=:6 ,
FLAG=:7 where SM_ID=:8
===================================================
PROCESS STATE
-------------
Process global information:
process: 0x1ee7ba460, call: 0x6b024428, xact: 0x1e24220f8, curses: 0x1ec860bc0, usrses: 0x1ec860bc0
in_exception_handler: no
----------------------------------------
SO: 0x1ee7ba460, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x1ee7ba460, name=process, file=ksu.h LINE:12721, pg=0
(process) Oracle pid:268, ser:67, calls cur/top: 0x6b024428/0x6b024428
flags : (0x0) -
flags2: (0x0), flags3: (0x10)
intr error: 0, call error: 0, sess error: 0, txn error 0
intr queue: empty
ksudlp FALSE at location: 0
(post info) last post received: 0 0 0
last post received-location: No post
last process to post me: none
last post sent: 0 0 26
last post sent-location: ksa2.h LINE:285 ID:ksasnd
last process posted by me: 0x1ef7b0280 2 6
(latch info) wait_event=0 bits=0x0
Process Group: DEFAULT, pseudo proc: 0x1efbc6260
O/S info: user: oracle, term: UNKNOWN, ospid: 30977
OSD pid info: Unix process pid: 30977, image: oracle@SIT1-DB1-primary
----------------------------------------
SO: 0x1ec860bc0, type: 4, owner: 0x1ee7ba460, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x1ee7ba460, name=session, file=ksu.h LINE:12729, pg=0
(session) sid: 1672 ser: 16519 trans: 0x1e24220f8, creator: 0x1ee7ba460
flags: (0x100045) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
flags2: (0x40009) -/-/INC
DID: , short-term DID:
txn branch: (nil)
edition#: 100 oct: 6, prv: 0, sql: 0x74e1a1a8, psql: 0x93a256c0, user: 84/PAYADM
ksuxds FALSE at location: 0
service name: orcl
client details:
O/S info: user: root, term: unknown, ospid: 1234
machine: 819e0b272776 program: JDBC Thin Client
application name: JDBC Thin Client, hash value=2546894660
Current Wait Stack:
0: waiting for 'enq: TX - row lock contention'
name|mode=0x54580006, usn<<16 | slot=0x1e0006, sequence=0x241d24
wait_id=11 seq_num=14 snap_id=2
wait times: snap=0.352643 sec, exc=3.352264 sec, total=3.383318 sec
wait times: max=infinite, heur=3.383318 sec
wait counts: calls=1 os=1
in_wait=1 iflags=0x15a0
There is at least one session blocking this session.
Dumping 1 direct blocker(s):
inst: 1, sid: 439, ser: 36613
Dumping final blocker:
inst: 1, sid: 439, ser: 36613
There are 8 sessions blocked by this session.
Dumping one waiter:
inst: 1, sid: 1311, ser: 50379
wait event: 'enq: TX - row lock contention'
p1: 'name|mode'=0x54580006
p2: 'usn<<16 | slot'=0x660003
p3: 'sequence'=0x4f8ba
row_wait_obj#: 88342, block#: 2598146, row#: 60, file# 9
min_blocked_time: 0 secs, waiter_cache_ver: 19833
Wait State:
fixed_waits=0 flags=0x23 boundary=(nil)/-1
Session Wait History:
elapsed time of 0.000000 sec since current wait
0: waited for 'latch: enqueue hash chains'
address=0x1eb6bc928, number=0x1d, tries=0x0
wait_id=12 seq_num=13 snap_id=1
wait times: snap=0.031054 sec, exc=0.031054 sec, total=0.031054 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000000 sec of elapsed time
1: waited for 'enq: TX - row lock contention'
name|mode=0x54580006, usn<<16 | slot=0x1e0006, sequence=0x241d24
wait_id=11 seq_num=12 snap_id=1
wait times: snap=2.999621 sec, exc=2.999621 sec, total=2.999621 sec
wait times: max=infinite
wait counts: calls=1 os=1
occurred after 0.000212 sec of elapsed time
2: waited for 'SQL*Net message from client'
driver id=0x54435000, #bytes=0x1, =0x0
wait_id=10 seq_num=11 snap_id=1
wait times: snap=0.005516 sec, exc=0.005516 sec, total=0.005516 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000068 sec of elapsed time
3: waited for 'SQL*Net message to client'
driver id=0x54435000, #bytes=0x1, =0x0
wait_id=9 seq_num=10 snap_id=1
wait times: snap=0.000001 sec, exc=0.000001 sec, total=0.000001 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000144 sec of elapsed time
4: waited for 'SQL*Net message from client'
driver id=0x54435000, #bytes=0x1, =0x0
wait_id=8 seq_num=9 snap_id=1
wait times: snap=0.015559 sec, exc=0.015559 sec, total=0.015559 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000172 sec of elapsed time
5: waited for 'SQL*Net message to client'
driver id=0x54435000, #bytes=0x1, =0x0
wait_id=7 seq_num=8 snap_id=1
wait times: snap=0.000001 sec, exc=0.000001 sec, total=0.000001 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000339 sec of elapsed time
6: waited for 'SQL*Net message from client'
driver id=0x54435000, #bytes=0x1, =0x0
wait_id=6 seq_num=7 snap_id=1
wait times: snap=0.003987 sec, exc=0.003987 sec, total=0.003987 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000004 sec of elapsed time
7: waited for 'SQL*Net message to client'
driver id=0x54435000, #bytes=0x1, =0x0
wait_id=5 seq_num=6 snap_id=1
wait times: snap=0.000001 sec, exc=0.000001 sec, total=0.000001 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000052 sec of elapsed time
8: waited for 'SQL*Net message from client'
driver id=0x54435000, #bytes=0x1, =0x0
wait_id=4 seq_num=5 snap_id=1
wait times: snap=0.002282 sec, exc=0.002282 sec, total=0.002282 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000026 sec of elapsed time
9: waited for 'SQL*Net message to client'
driver id=0x54435000, #bytes=0x1, =0x0
wait_id=3 seq_num=4 snap_id=1
wait times: snap=0.000001 sec, exc=0.000001 sec, total=0.000001 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.003330 sec of elapsed time
Sampled Session History of session 1672 serial 16519
---------------------------------------------------
The sampled session history is constructed by sampling
the target session every 1 second. The sampling process
captures at each sample if the session is in a non-idle wait,
an idle wait, or not in a wait. If the session is in a
non-idle wait then one interval is shown for all the samples
the session was in the same non-idle wait. If the
session is in an idle wait or not in a wait for
consecutive samples then one interval is shown for all
the consecutive samples. Though we display these consecutive
samples in a single interval the session may NOT be continuously
--More--(0%)

and Chris said...

I'm not sure what you mean by "our RD have turned off the transaction in jdbc". But unless your application commits after each update, you still have a transaction open in the database.

If session 1 runs:

update t1 set name='aa' where id=1;


It blocks all further updates to t1 where id = 1 until this commits. Similarly if you run:

update t1 set name='bb' where id=2;


in a second session it does the same for id = 2.

So when you run this back in your first session

update t1 set name='bbb' where id=2;


It has to wait until the second session commits. If instead session 2 runs:

update t1 set name='aaa' where id=1;


Then both session are waiting on each other. Deadlock!

If you need both updates to happen as part of your transaction, lock all the rows you intend to change before running the update with:

select * from t1 where id in (1, 2) for update;


Then run the updates afterwards. The second will be blocked on the "select for update" at the start. Once it's able to acquire these locks, you know it can proceed with the updates.

Rating

  (2 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

thanks for replay

tan alan, May 05, 2017 - 10:23 am UTC

Hi,
Thanks for you quickly replay,but,
I am an Oracle DBA,I know litter about programming,the developer told me he has set auto commmit property in jdbc,it mearns every one SQL should committed ofter next one is executed,so there is no transaction including 2 SQLs,deadlock should not occured.


Chris Saxon
May 05, 2017 - 11:03 am UTC

Looking more closely at the tracefile I can you have three sessions waiting on each other in a circle. They're waiting on updates, so you probably still have uncommitted work from a previous statement.

Have you tried tracing the application to see what's going on?

thanks for replay

A reader, May 05, 2017 - 2:48 pm UTC

Hi,
Thanks for your reply.
The application is multi-thread ,every thread does same things.
it's hard to trace a session.
But could you please confirm one thing about jdbc autocommit:
when the jdbc connection method set to autocommit,then every sql be committed ofter it is executed?

Thank you !
Chris Saxon
May 08, 2017 - 9:03 am UTC

Yes, it's my understanding that auto commit will after each statement:

When a connection is created, it is in auto-commit mode. This means that each individual SQL statement is treated as a transaction and is automatically committed right after it is executed. (To be more precise, the default is for a SQL statement to be committed when it is completed, not when it is executed. A statement is completed when all of its result sets and update counts have been retrieved. In almost all cases, however, a statement is completed, and therefore committed, right after it is executed.)

https://docs.oracle.com/javase/tutorial/jdbc/basics/transactions.html

You could trace all the activity for the clients using your ORCL service with DBMS_MONITOR.SERV_MOD_ACT_STAT_ENABLE:

http://docs.oracle.com/database/122/ARPLS/DBMS_MONITOR.htm#GUID-B1BD843C-FDD0-41C5-8300-FF9E501CD0CF

Note this will add some overhead and generate lots of trace data in a busy application. So use with care!

By any chance are there triggers on the tables you're updating?

More to Explore

VLDB

If you are new to partitioning, check out Connor McDonald's introduction series here.

VLDB

Documentation set on VLDB and Partitioning.