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

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

    • Thanks for visiting and appreciate your feedback. 🙂

      Please find below script contents:
      —————————————————————————————————————————–
      set serveroutput on size 50000
      set echo off feed off veri off

      accept SID prompt ‘Enter Session ID: ‘

      DECLARE
      v_pid number;
      s sys.v_$session%ROWTYPE;
      p sys.v_$process%ROWTYPE;
      BEGIN
      Begin
      select spid into v_pid
      from sys.v_$process p, sys.v_$session s
      where p.addr = s.paddr
      and (s.sid = &&SID)
      ;
      exception
      when no_data_found then
      dbms_output.put_line(‘Unable to find process id &&SID!!!’);
      return;
      when others then
      dbms_output.put_line(sqlerrm);
      return;
      end;

      select * into p from sys.v_$process where spid = v_pid;
      select * into s from sys.v_$session where paddr = p.addr;

      dbms_output.put_line(‘=============================================================================================================’);
      dbms_output.put_line(‘SID/Serial : ‘|| s.sid||’,’||s.serial#);
      dbms_output.put_line(‘Module : ‘||s.module);
      dbms_output.put_line(‘SQL_ID : ‘||s.sql_id);
      dbms_output.put_line(‘Foreground : ‘|| ‘PID: ‘||s.process||’ – ‘||s.program);
      dbms_output.put_line(‘Shadow : ‘|| ‘PID: ‘||p.spid||’ – ‘||p.program);
      dbms_output.put_line(‘Terminal : ‘|| s.terminal || ‘/ ‘ || p.terminal);
      dbms_output.put_line(‘OS User : ‘|| s.osuser||’ on ‘||s.machine);
      dbms_output.put_line(‘Ora User : ‘|| s.username);
      dbms_output.put_line(‘Status Flags: ‘|| s.status||’ ‘||s.server||’ ‘||s.type);
      dbms_output.put_line(‘Tran Active : ‘|| nvl(s.taddr, ‘NONE’));
      dbms_output.put_line(‘Login Time : ‘|| to_char(s.logon_time, ‘Dy HH24:MI:SS’));
      dbms_output.put_line(‘Last Call : ‘|| to_char(sysdate-(s.last_call_et/60/60/24), ‘Dy HH24:MI:SS’) || ‘ – ‘ || to_char(s.last_call_et/60, ‘999990.0’) || ‘ min’);
      dbms_output.put_line(‘Lock/ Latch : ‘|| nvl(s.lockwait, ‘NONE’)||’/ ‘||nvl(p.latchwait, ‘NONE’));
      dbms_output.put_line(‘Latch Spin : ‘|| nvl(p.latchspin, ‘NONE’));

      dbms_output.put_line(‘Current SQL statement:’);
      for c1 in ( select * from sys.v_$sqltext
      where HASH_VALUE = s.sql_hash_value order by piece) loop
      dbms_output.put_line(chr(9)||c1.sql_text);
      end loop;

      dbms_output.put_line(‘Previous SQL statement:’);
      for c1 in ( select * from sys.v_$sqltext
      where HASH_VALUE = s.prev_hash_value order by piece) loop
      dbms_output.put_line(chr(9)||c1.sql_text);
      end loop;

      dbms_output.put_line(‘Session Waits:’);
      for c1 in ( select * from sys.v_$session_wait where sid = s.sid) loop
      dbms_output.put_line(chr(9)||c1.state||’: ‘||c1.event);
      end loop;

      dbms_output.put_line(‘Connect Info:’);
      for c1 in ( select * from sys.v_$session_connect_info where sid = s.sid) loop
      dbms_output.put_line(chr(9)||’: ‘||c1.network_service_banner);
      end loop;

      dbms_output.put_line(‘Locks:’);
      for c1 in ( select
      decode(l.type,
      — Long locks
      ‘TM’, ‘DML/DATA ENQ’, ‘TX’, ‘TRANSAC ENQ’,
      ‘UL’, ‘PLS USR LOCK’,
      — Short locks
      ‘BL’, ‘BUF HASH TBL’, ‘CF’, ‘CONTROL FILE’,
      ‘CI’, ‘CROSS INST F’, ‘DF’, ‘DATA FILE ‘,
      ‘CU’, ‘CURSOR BIND ‘,
      ‘DL’, ‘DIRECT LOAD ‘, ‘DM’, ‘MOUNT/STRTUP’,
      ‘DR’, ‘RECO LOCK ‘, ‘DX’, ‘DISTRIB TRAN’,
      ‘FS’, ‘FILE SET ‘, ‘IN’, ‘INSTANCE NUM’,
      ‘FI’, ‘SGA OPN FILE’,
      ‘IR’, ‘INSTCE RECVR’, ‘IS’, ‘GET STATE ‘,
      ‘IV’, ‘LIBCACHE INV’, ‘KK’, ‘LOG SW KICK ‘,
      ‘LS’, ‘LOG SWITCH ‘,
      ‘MM’, ‘MOUNT DEF ‘, ‘MR’, ‘MEDIA RECVRY’,
      ‘PF’, ‘PWFILE ENQ ‘, ‘PR’, ‘PROCESS STRT’,
      ‘RT’, ‘REDO THREAD ‘, ‘SC’, ‘SCN ENQ ‘,
      ‘RW’, ‘ROW WAIT ‘,
      ‘SM’, ‘SMON LOCK ‘, ‘SN’, ‘SEQNO INSTCE’,
      ‘SQ’, ‘SEQNO ENQ ‘, ‘ST’, ‘SPACE TRANSC’,
      ‘SV’, ‘SEQNO VALUE ‘, ‘TA’, ‘GENERIC ENQ ‘,
      ‘TD’, ‘DLL ENQ ‘, ‘TE’, ‘EXTEND SEG ‘,
      ‘TS’, ‘TEMP SEGMENT’, ‘TT’, ‘TEMP TABLE ‘,
      ‘UN’, ‘USER NAME ‘, ‘WL’, ‘WRITE REDO ‘,
      ‘TYPE=’||l.type) type,
      decode(l.lmode, 0, ‘NONE’, 1, ‘NULL’, 2, ‘RS’, 3, ‘RX’,
      4, ‘S’, 5, ‘RSX’, 6, ‘X’,
      to_char(l.lmode) ) lmode,
      decode(l.request, 0, ‘NONE’, 1, ‘NULL’, 2, ‘RS’, 3, ‘RX’,
      4, ‘S’, 5, ‘RSX’, 6, ‘X’,
      to_char(l.request) ) lrequest,
      decode(l.type, ‘MR’, o.object_name,
      ‘TD’, o.object_name,
      ‘TM’, o.object_name,
      ‘RW’, ‘FILE#=’||substr(l.id1,1,3)||
      ‘ BLOCK#=’||substr(l.id1,4,5)||’ ROW=’||l.id2,
      ‘TX’, ‘RS+SLOT#’||l.id1||’ WRP#’||l.id2,
      ‘WL’, ‘REDO LOG FILE#=’||l.id1,
      ‘RT’, ‘THREAD=’||l.id1,
      ‘TS’, decode(l.id2, 0, ‘ENQUEUE’, ‘NEW BLOCK ALLOCATION’),
      ‘ID1=’||l.id1||’ ID2=’||l.id2) objname
      from sys.v_$lock l, dba_objects o
      where sid = s.sid
      and l.id1 = o.object_id(+) ) loop
      dbms_output.put_line(chr(9)||c1.type||’ H: ‘||c1.lmode||’ R: ‘||c1.lrequest||’ – ‘||c1.objname);
      end loop;

      dbms_output.put_line(‘=============================================================================================================’);

      END;
      /

      undef UNIXID
      —————————————————————————————————————————–

  1. Interesting Article, I could co-relate to a similar issue I am facing now in my application. Thanks for the script

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s