Resolving cursor: pin S wait on X using interesting column final_blocking_session in v$session

Recently I was having issue in our test environment, users were complaining that database is not responding for any queries, it appears to be in hanged state.

After checking database for possible causes for performance issues, I found following:


 

SQL> select event,count(0) from v$session where username is not null and status='ACTIVE' group by event;
event                      count(0)
-----------------------    -----------
db file sequential read    1 
library cache lock         4 
cursor: pin S wait on X    25 
SQL*Net message to client  1

 

Definitely something was wrong with the database. So firstly I concentrated on wait event library cache lock. I found some user was executing following DDL on one of the highly accessible table in the database:


 

SQL> @s1
Enter Session ID: 1409
======================================================================================================
SID/Serial : 1409,39547
Module : TOAD 10.6.1.3
SQL_ID : d489wrxp66a0m
Foreground : PID: 11016:1228 - Toad.exe
Shadow : PID: 12339 - oracle@test4.test.com
Terminal : XXGGG / UNKNOWN
OS User : C_GGG on TEST4\C_GGG2-L
Ora User : SADB
Status Flags: ACTIVE DEDICATED USER
Tran Active : 000000028CC470A0
Login Time : Thu 11:44:52
Last Call : Thu 11:48:59 - 199.7 min
Lock/ Latch : NONE/ NONE
Latch Spin : NONE
Current SQL statement:
 ALTER TABLE sadb.audit_log DROP UNUSED COLUMNS CHECKPOINT 1000
Previous SQL statement:
Session Waits:
 WAITING: db file sequential read
Connect Info:
 : TCP/IP NT Protocol Adapter for Linux: Version 11.2.0.3.0 - Production
 : Oracle Advanced Security: encryption service for Linux: Version 11.2.0.3.0 - Production
 : Oracle Advanced Security: crypto-checksumming service for Linux: Version 11.2.0.3.0 - Production
Locks:
 TYPE=AE H: S R: NONE - ID1=282717 ID2=0
 DML/DATA ENQ H: X R: NONE - AUDIT_LOG
====================================================================================================

 

So here I got culprit for wait eventlibrary cache lock. Killing this session would have resolved sessions waiting for this wait event.

But what causing cursor: pin S wait on X?

I searched on Google for possible causes of this wait event, I found lots of documentation each pointing to different possibilities.

Is same session with SID : 1409 was the culprit? After describing v$session view, I found very interesting column – ‘final_blocking_session’ – which is introduced in Oracle 11g.


 

SQL> select distinct blocking_session from v$session where event='cursor: pin S wait on X';
BLOCKING_SESSION
----------------
 1305
 1520
SQL> select sql_id from v$session where sid in (1305,1520);
SQL_ID
-------------
4vcd40bta41pb
0h4n33suqpqtv
SQL> select distinct final_blocking_session from v$session where event='cursor: pin S wait on X';
FINAL_BLOCKING_SESSION
----------------------
 1409

 

So I found the culprit :-). After killing session with SID : 1409, issue got resolved.

After searching on Metalink I found very useful note:

Troubleshooting Database Contention With V$Wait_Chains (Doc ID 1428210.1), which says

In 11.2 you can add v$session.final_blocking_session to see the final blocker. The final blocker is the session/process at the top of the wait chain. This is the session/process that maybe causing the problem. Example of query with final_blocking_session info:


 

set pages 1000
set lines 120
set heading off
column w_proc format a50 tru
column instance format a20 tru
column inst format a28 tru
column wait_event format a50 tru
column p1 format a16 tru
column p2 format a16 tru
column p3 format a15 tru
column Seconds format a50 tru
column sincelw format a50 tru
column blocker_proc format a50 tru
column fblocker_proc format a50 tru
column waiters format a50 tru
column chain_signature format a100 wra
column blocker_chain format a100 wra
SELECT * 
FROM (SELECT 'Current Process: '||osid W_PROC, 'SID '||i.instance_name INSTANCE, 
 'INST #: '||instance INST,'Blocking Process: '||decode(blocker_osid,null,'<none>',blocker_osid)|| 
 ' from Instance '||blocker_instance BLOCKER_PROC,
 'Number of waiters: '||num_waiters waiters,
 'Final Blocking Process: '||decode(p.spid,null,'<none>',
 p.spid)||' from Instance '||s.final_blocking_instance FBLOCKER_PROC, 
 'Program: '||p.program image,
 'Wait Event: ' ||wait_event_text wait_event, 'P1: '||wc.p1 p1, 'P2: '||wc.p2 p2, 'P3: '||wc.p3 p3,
 'Seconds in Wait: '||in_wait_secs Seconds,
 'Seconds Since Last Wait: '||time_since_last_wait_secs sincelw,
 'Wait Chain: '||chain_id ||': '||chain_signature chain_signature,
'Blocking Wait Chain: '||decode(blocker_chain_id,null,
 '<none>',blocker_chain_id) blocker_chain
FROM v$wait_chains wc,
 gv$session s,
 gv$session bs,
 gv$instance i,
 gv$process p
WHERE wc.instance = i.instance_number (+)
AND (wc.instance = s.inst_id (+) and wc.sid = s.sid (+)
 and wc.sess_serial# = s.serial# (+))
 AND (s.final_blocking_instance = bs.inst_id (+) 
and s.final_blocking_session = bs.sid (+))
 AND (bs.inst_id = p.inst_id (+) and bs.paddr = p.addr (+))
 AND ( num_waiters > 0
 OR ( blocker_osid IS NOT NULL
 AND in_wait_secs > 10 ) )
ORDER BY chain_id,
 num_waiters DESC)
WHERE ROWNUM < 101;

 

This sql will give u OS process ID for final blocker.


 

Hope so u will find this post very useful 🙂

Cheers

Regards,

Adityanath

Advertisements