Our DB was very slow yesterday. It was difficult to work using SQL*Developer. The procedures which took only a few seconds to run day-before yesterday, was not completing yesterday. i.e. when you press execute for a procedure, the processing will continue for 1/2 hour, but without giving any result. When we requested the DBA to restart the DB, he sent us a trace file which says there was a deadlock. Problem is, looking at the trace file, I cannot find out which SQL caused the deadlock. If I know the SQL which caused the deadlock, then I know which procedures or even ad-hoc SQL I executed in SQL*Developer caused it. I cannot find any SQL which references the tables or columns in our application. So, how do we find out?? Now of course the DB is restarted. But, is there are any DD views which has the information still?
The trace file's top portion is shown below:
{code}
Trace file E:\ORACLE\DEST\diag\rdbms\clientdev2\clientdev2\trace\clientdev2_ora_5596.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Windows NT Version V6.1 Service Pack 1
CPU : 2 - type 8664, 2 Physical Cores
Process Affinity : 0x0x0000000000000000
Memory (Avail/Total): Ph:270M/4095M, Ph+PgF:2753M/14852M
VM name : VMWare Version (6)
Instance name: clientdev2
Redo thread mounted by this instance: 1
Oracle process number: 32
Windows thread id: 5596, image: ORACLE.EXE (SHAD)
*** 2015-01-29 05:32:33.266
*** SESSION ID:(19.25911) 2015-01-29 05:32:33.266
*** CLIENT ID:() 2015-01-29 05:32:33.266
*** SERVICE NAME:(SYS$USERS) 2015-01-29 05:32:33.266
*** MODULE NAME:(SQL Developer) 2015-01-29 05:32:33.266
*** ACTION NAME:() 2015-01-29 05:32:33.266
*** 2015-01-29 05:32:33.266
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-000a000d-00005171 32 19 X 25 137 S
TX-00070003-0000515b 25 137 X 32 19 X
session 19: DID 0001-0020-000001C3 session 137: DID 0001-0019-00009D7E
session 137: DID 0001-0019-00009D7E session 19: DID 0001-0020-000001C3
Rows waited on:
Session 19: no row
Session 137: obj - rowid = 00003AA0 - AAADqgAAAAAAAAAAAA
(dictionary objn - 15008, file - 0, block - 0, slot - 0)
----- Information for the OTHER waiting sessions -----
Session 137:
sid: 137 ser: 35775 audsid: 1350009 user: 0/SYS
flags: (0x8000045) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
flags2: (0x40009) -/-/INC
pid: 25 O/S info: user: SYSTEM, term: EDCARGDEVDB01, ospid: 5104
image: ORACLE.EXE (SHAD)
client details:
O/S info: user: Jared.Taylor, term: unknown, ospid: 13680
machine: EDCCTXAPP04 program: SQL Developer
application name: SQL Developer, hash value=1012150930
current SQL:
delete "XDB"."XDB$ELEMENT" where SYS_NC_OID$ = :1
----- End of information for the OTHER waiting sessions -----
Information for THIS session:
----- Current SQL Statement for this session (sql_id=27zh9sbzm22b4) -----
UPDATE "XDB"."XDB$RESOURCE" e SET e.xmldata.lastmodifierid = :1, e.xmldata.modificationdate = :2 WHERE e.sys_nc_oid$ = :3
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
object line object
handle number name
000007FF239B2848 55 package XDB.DBMS_XMLSCHEMA_INT
000007FF21F323E8 159 package body XDB.DBMS_XMLSCHEMA
000007FF23966220 45 package body PEGA.INT_VALIDATE_XML
000007FF23966220 291 package body PEGA.INT_VALIDATE_XML
000007FF21E50448 2443 package body PEGA.INT_PKG
000007FF21E50448 2502 package body PEGA.INT_PKG
000007FF1C674468 12 procedure PEGA.INT_SQL_DEV_AUTO_UNIT_TEST
000007FF2AC79520 2 anonymous block
===================================================
PROCESS STATE
-------------
Process global information:
process: 0x000007FF2A8A6548, call: 0x000007FF25CBF120, xact: 0x000007FF28A648D0, curses: 0x000007FF2AA6B400, usrses: 0x000007FF2AA7A248
in_exception_handler: no
----------------------------------------
SO: 0x000007FF2A8A6548, type: 2, owner: 0x0000000000000000, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x000007FF2A8A6548, name=process, file=ksu.h LINE:12616, pg=0
(process) Oracle pid:32, ser:22, calls cur/top: 0x000007FF25CBF120/0x000007FF25CC5C88
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 159
last post received-location: kcb2.h LINE:4139 ID:kcbzww
last process to post me: 2a89ef28 196 0
last post sent: 0 0 9
last post sent-location: ksq.h LINE:2014 ID:ksqrcl
last process posted by me: 2a89ef28 196 0
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 0x000007FF2A92F748
O/S info: user: SYSTEM, term: EDCARGDEVDB01, ospid: 5596
OSD pid info: Windows thread id: 5596, image: ORACLE.EXE (SHAD)
----------------------------------------
SO: 0x000007FF28D05BB0, type: 10, owner: 0x000007FF2A8A6548, flag: INIT/-/-/0x00 if: 0x1 c: 0x1
proc=0x000007FF2A8A6548, name=FileOpenBlock, file=ksfd.h LINE:6448, pg=0
(FOB) 000007FF28D05BB0 flags=2050 fib=000007FF28EF41C8 incno=0 pending i/o cnt=0
fname=E:\ORACLE\ORADATA\clientdev2\TEMP01.DBF
fno=201 lblksz=8192 fsiz=65536
----------------------------------------
SO: 0x000007FF2AA7A248, type: 4, owner: 0x000007FF2A8A6548, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x000007FF2A8A6548, name=session, file=ksu.h LINE:12624, pg=0
(session) sid: 19 ser: 25911 trans: 0x000007FF28A648D0, creator: 0x000007FF2A8A6548
flags: (0x8000045) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
flags2: (0x40009) -/-/INC
DID: , short-term DID:
txn branch: 0x0000000000000000
oct: 6, prv: 0, sql: 0x000007FF21EDBBA8, psql: 0x000007FF24BBF8B8, user: 84/PEGA
ksuxds FALSE at location: 0
service name: SYS$USERS
client details:
O/S info: user: Jared.Taylor, term: unknown, ospid: 13680
machine: EDCCTXAPP04 program: SQL Developer
application name: SQL Developer, hash value=1012150930
Current Wait Stack:
0: waiting for 'enq: TX - row lock contention'
name|mode=0x54580006, usn<<16 | slot=0x70003, sequence=0x515b
wait_id=78 seq_num=79 snap_id=1
wait times: snap=0.178829 sec, exc=0.178829 sec, total=0.178829 sec
wait times: max=infinite, heur=0.178829 sec
wait counts: calls=1 os=1
in_wait=1 iflags=0x55a0
There are 0 sessions blocked by this session.
Dumping one waiter:
inst: 1, sid: 26, ser: 757
wait event: 'library cache lock'
p1: 'handle address'=0x7ff14aaba58
p2: 'lock address'=0x7ff24a7ad40
p3: '100*mode+namespace'=0x3663800190003
row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
min_blocked_time: 20 secs, waiter_cache_ver: 16978
Wait State:
fixed_waits=0 flags=0x22 boundary=0x0000000000000000/-1
Session Wait History:
elapsed time of 0.149358 sec since current wait
0: waited for 'latch: cache buffers chains'
address=0x7ff29a28250, number=0x9b, tries=0x0
wait_id=77 seq_num=78 snap_id=1
wait times: snap=0.010671 sec, exc=0.010671 sec, total=0.010671 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000957 sec of elapsed time
1: waited for 'latch: cache buffers chains'
address=0x7ff2988caa8, number=0x9b, tries=0x0
wait_id=76 seq_num=77 snap_id=1
wait times: snap=0.015657 sec, exc=0.015657 sec, total=0.015657 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.012143 sec of elapsed time
2: waited for 'latch: cache buffers chains'
address=0x7ff29a28250, number=0x9b, tries=0x0
wait_id=75 seq_num=76 snap_id=1
wait times: snap=0.008833 sec, exc=0.008833 sec, total=0.008833 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.001820 sec of elapsed time
3: waited for 'latch: cache buffers chains'
address=0x7ff299b61d0, number=0x9b, tries=0x0
wait_id=74 seq_num=75 snap_id=1
wait times: snap=0.016726 sec, exc=0.016726 sec, total=0.016726 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.014371 sec of elapsed time
4: waited for 'latch: cache buffers chains'
address=0x7ff299b61d0, number=0x9b, tries=0x0
wait_id=73 seq_num=74 snap_id=1
wait times: snap=0.015138 sec, exc=0.015138 sec, total=0.015138 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.003904 sec of elapsed time
5: waited for 'latch: cache buffers chains'
address=0x7ff299b61d0, number=0x9b, tries=0x0
wait_id=72 seq_num=73 snap_id=1
wait times: snap=0.007737 sec, exc=0.007737 sec, total=0.007737 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.031562 sec of elapsed time
6: waited for 'latch: In memory undo latch'
address=0x7ff284cf8d0, number=0xfb, tries=0x0
wait_id=71 seq_num=72 snap_id=1
wait times: snap=0.008764 sec, exc=0.008764 sec, total=0.008764 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.279260 sec of elapsed time
7: waited for 'Disk file operations I/O'
FileOperation=0x2, fileno=0xc9, filetype=0x2
wait_id=70 seq_num=71 snap_id=1
wait times: snap=0.000290 sec, exc=0.000290 sec, total=0.000290 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.081379 sec of elapsed time
8: waited for 'library cache lock'
handle address=0x7ff14aaba58, lock address=0x7ff1a504490, 100*mode+namespace=0x3663800190003
wait_id=69 seq_num=70 snap_id=1
wait times: snap=119 min 11 sec, exc=119 min 11 sec, total=119 min 11 sec
wait times: max=infinite
wait counts: calls=2375 os=2375
occurred after 0.002279 sec of elapsed time
9: waited for 'SQL*Net message from dblink'
driver id=0x54435000, #bytes=0x1, =0x0
wait_id=68 seq_num=69 snap_id=1
wait times: snap=0.000577 sec, exc=0.000577 sec, total=0.000577 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000022 sec of elapsed time
Sampled Session History of session 19 serial 25911
---------------------------------------------------
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
idle or not in a wait (the sampling process does not know).
The history is displayed in reverse chronological order.
sample interval: 1 sec, max history 120 sec
---------------------------------------------------
[1 sample, 05:32:33]
waited for 'enq: TX - row lock contention', seq_num: 79
p1: 'name|mode'=0x54580006
p2: 'usn<<16 | slot'=0x70003
p3: 'sequence'=0x515b
time_waited: >= 0 sec (still in wait)
[119 samples, 05:30:32 - 05:32:32]
waited for 'library cache lock', seq_num: 70
p1: 'handle address'=0x7ff14aaba58
p2: 'lock address'=0x7ff1a504490
p3: '100*mode+namespace'=0x3663800190003
time_waited: 47 min 36 sec (sample interval: 119 sec)
---------------------------------------------------
Sampled Session History Summary:
longest_non_idle_wait: 'library cache lock'
[119 samples, 05:30:32 - 05:32:32]
time_waited: 47 min 36 sec (sample interval: 119 sec)
---------------------------------------------------
temporary object counter: 1
----------------------------------------
Virtual Thread:
kgskvt: 000007FF2A28B9A0, sess: 000007FF2AA7A248 sid: 19 ser: 25911
vc: 0000000000000000, proc: 000007FF2A8A6548, id: 19
consumer group cur: OTHER_GROUPS (upd? 0), mapped: DEFAULT_CONSUMER_GROUP, orig:
vt_state: 0x100, vt_flags: 0xE030, blkrun: 0, numa: 1
inwait: 0, posted_run=0
location where insched last set: kgskthrrun
location where insched last cleared: kgskthrrun2
location where inwait last set: NULL
location where inwait last cleared: kgskbindfast
is_assigned: 1, in_sched: 0 (0)
qcls: 0000000000000000, qlink: FALSE
vt_active: 0 (pending: 1)
vt_pq_active: 0, dop: 0
used quanta: 0 (cg: 0) usec, num penalty: 0
cpu start time: 0
idle time: 0, active time: 0 (cg: 0)
cpu yields: 0 (cg: 0), waits: 0 (cg: 0), wait time: 0 (cg: 0) usec
io waits: 0 (cg: 0), wait time: 0 (cg: 0) usec
ASL queued time outs: 0, time: 0 (cur 0, cg 0)
PQQ queued time outs: 0, time: 0 (cur 0, cg 0)
Queue timeout violation: 0
calls aborted: 0, num est exec limit hit: 0
undo current: 0k max: 0k
I/O credits acquired:small=0 large=0
I/O credits waiting for:small=0 large=0
KTU Session Commit Cache Dump for IDLs:
KTU Session Commit Cache Dump for Non-IDLs:
{code}