Treasure hunting and blocking sessions

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.