Bored with being just a
Sherlock Holmes dba? Take a look at
treasurehunt.solita.fi some tricky puzzles available for a week. The airprize available only to
scan-agile participants but the pages seem to be open for all internet.
Back to Sherlock Holmesing. Blocking sessions are tricky ones. At least when the bug report is talking about yesterday. The application is throwing 5 minute transaction timeout to end user face. Lucky us the Diagnostic pack is available.
The bug information is tracked to a action SOS.createSO. And lucky us we have module, action and client_identifier populated to the session while accessing database.
select session_id,blocking_session,blocking_session_serial#,sql_exec_start,min(sample_time),max(sample_time), count(*), action
from DBA_HIST_ACTIVE_SESS_HISTORY s
where sample_time > sysdate -300
and event= 'enq: TX - row lock contention'
and action = 'SOS.createSO'
group by session_id,blocking_session,blocking_session_serial#,sql_exec_start,action
having count(*) > 29
order by min(sample_time) desc
;
sessio blocki blocking sql_exec_start min(sample_time) max(sample_time) count action
465 699 17041 07.03.2012 12:32:45 07.03.2012 12:32:49,839 07.03.2012 12:37:40,203 30 SOS.createSO
We see that our reported bug session 465 was blocked by session 699. The five minutes timeout is readable from count(*) being 30.
There is no other information about the blocking session than the sid and serial#. Should we be lucky to see some samples around the same time from this blocking session.
select s.*
from DBA_HIST_ACTIVE_SESS_HISTORY s
where session_id = 699
and session_serial# = 17041
;
No rows
Unlucky us. How about any other sessions being influenced by the kept row lock?
select session_id,blocking_session,blocking_session_serial#,sql_exec_start,min(sample_time),max(sample_time), count(*), action
from DBA_HIST_ACTIVE_SESS_HISTORY s
where sample_time > sysdate -300
and event= 'enq: TX - row lock contention'
group by session_id,blocking_session,blocking_session_serial#,sql_exec_start,action
having count(*) > 29
order by min(sample_time) desc
;
sessio blocki blocking sql_exec_start min(sample_time) max(sample_time) count action
465 699 17041 07.03.2012 12:32:45 07.03.2012 12:32:49,839 07.03.2012 12:37:40,203 30 SOS.createSO
30 699 17041 07.03.2012 12:31:11 07.03.2012 12:31:19,712 07.03.2012 12:36:10,080 30 SOS.createSOL
461 699 17041 07.03.2012 12:16:32 07.03.2012 12:16:38,563 07.03.2012 12:21:28,946 30 SOS.createSOL
406 699 17041 07.03.2012 12:14:21 07.03.2012 12:14:28,402 07.03.2012 12:19:18,780 30 SOS.createSOL
657 304 2655 02.03.2012 12:38:37 02.03.2012 12:38:41,735 02.03.2012 12:43:32,113 30 SOS.createSOL
The session 699 blocked also other sessions doing action SOS.createSOL. The time frame 699 was holding the lock got wider is has started already at time 12:14:21.
And yet again lucky us the similar thing happened a couple days ago also. Another blocking session is found.
select sample_time,sql_exec_start,s.module,s.action,s.client_id
from DBA_HIST_ACTIVE_SESS_HISTORY s
where session_id = 304
and session_serial# = 2655
;
sample_tim sql_exec module action client_id
02.03.2012 12:25:20 services RIS.updateRI integration
02.03.2012 12:47:47 works SS.getSOT obfuscateduser
And yet again lucky us. We get a before and after problem suspect end users and actions. The guilty code lines are possible to find with this information and application logs. Yet again Diagnostic pack license purchase got us to the right direction. The problem would have otherwise been unsolved.