Tuesday, January 22, 2013

"library cache lock" wait event...

Another wait event that I faced today:

The job that extracts the data from Oracle using fastreader generally finishes pretty fast but today it seems that it never finished...

Looking into session info found that its waiting on "library cache lock".

whats object is it waiting on and who is blocking it?
In my scenario I just ran the following queries to find out which object my select statement (yes it was a select query that was hung on library cache lock and not a DML). Found schedule jobs that were tripping over on Adding and Dropping partitions on this table at the same time made this query to get hung.

First query to find sessions with library cache lock:

select a.sid Waiter,b.SERIAL#,a.event,a.p1raw,
       substr(rawtohex(a.p1),1,30) Handle,
       substr(rawtohex(a.p2),1,30) Pin_addr,
       a.p3
  from gv$session_wait a, gv$session b
 where a.sid=b.sid
   and a.wait_time=0 and a.event like 'library cache lock';

Second query to find the actual object:

select to_char(SESSION_ID,'999') sid, substr(LOCK_TYPE,1,30) "Type",
       substr(lock_id1,1,23) "Object_Name", substr(mode_held,1,4) "HELD",
       substr(mode_requested,1,4) "REQ", lock_id2 "Lock_addr"
  from dba_lock_internal
 where mode_requested<>'None'
   and mode_requested<>mode_held
   and session_id = 1265; --place the sid from the above query to find an object for that session.



Here is the metalink note id:122793.1 which describes how to find answers for above questions.

Here is the excerpt for immediate reference (or for non-metalink users):
It has two methods and I like the first method by goring the SQL's:


METHOD 2: EXAMINE THE X$KGLLK TABLE

The X$KGLLK table (accessible only as SYS/INTERNAL) contains all the library object locks (both held & requested) for all sessions and is more complete than the V$LOCK view although the column names don't always reveal their meaning.

You can examine the locks requested (and held) by the waiting session by looking up the session address (SADDR) in V$SESSION and doing the following select:
select sid,saddr from v$session where event= 'library cache lock';

SID SADDR
---------- --------
16 572ed244


select kgllkhdl Handle,kgllkreq Request, kglnaobj Object
from x$kgllk where kgllkses = '572ed244'
and kgllkreq > 0;

HANDLE   REQUEST   OBJECT
-------- ---------- ------------------------------------------------------------
62d064dc          2 EMPLOYEES

This will show you the library cache lock requested by this session (KGLLKREQ > 0) where KGLNAOBJ contains the first 80 characters of the name of the object.The value in KGLLKHDL corresponds with the 'handle address' of the object in Method 1 Systemstate Analysis as shown above.

 If we now match the KGLLKHDL with the handles of other sessions in X$KGLLK that should give us the address of the blocking session.The session holding the lock will have KGLLKMOD > 0 as it is holding the lock.
select kgllkses saddr,kgllkhdl handle,kgllkmod mod,kglnaobj object
from x$kgllk lock_a
where kgllkmod > 0
and exists (select lock_b.kgllkhdl from x$kgllk lock_b
where kgllkses = '572ed244' /* blocked session */
and lock_a.kgllkhdl = lock_b.kgllkhdl
and kgllkreq > 0);

SADDR     HANDLE   MOD
--------  -------- ----------
OBJECT
------------------------------------------------------------
572eac94  62d064dc          3
EMPLOYEES


If we look a bit further we can then again match KGLLKSES with SADDR in v$session to find further information on the blocking session:

select sid,username,terminal,program from v$session where saddr = '572eac94'

SID        USERNAME                  TERMINAL
---------- ------------------------------ ------------------------------
PROGRAM
------------------------------------------------
12          SCOTT                          pts/20
sqlplus@goblin.forgotten.realms (TNS V1-V3)

In the same way we can also find all the blocked sessions:
select sid,username,terminal,program from v$session
where saddr in
(select kgllkses from x$kgllk lock_a
 where kgllkreq > 0
 and exists (select lock_b.kgllkhdl from x$kgllk lock_b
             where kgllkses = '572eac94' /* blocking session */
             and lock_a.kgllkhdl = lock_b.kgllkhdl
             and kgllkreq = 0)
);

SID        USERNAME                       TERMINAL
---------- ------------------------------ ------------------------------
PROGRAM
------------------------------------------------
13         SCOTT                           pts/22
sqlplus@goblin.forgotten.realms (TNS V1-V3)

16         SCOTT                           pts/7
sqlplus@goblin.forgotten.realms (TNS V1-V3)



Method 1: Systemstate Analysis

Systemstate event will create a tracefile containing detailed information on every Oracle process. This information includes all the resources held & requested by a specific process.

While an operation is hanging, open a new session and launch the following statement:
For Oracle 9.2.0.1 or higher:
$sqlplus '/ as sysdba'
oradebug setmypid
oradebug unlimit
oradebug dump systemstate 266

For older versions you can use the following syntax that is also possible in higher versions.The level 266 is not available before 9.2.0.6
alter session set max_dump_file_size=unlimited;
alter session set events 'immediate trace name systemstate level 10'

 Oracle will create a systemstate tracefile in your USER_DUMP_DEST directory.

Get the PID (ProcessID) of the 'hanging' session:
select pid from v$process where addr=
(select paddr from v$session where sid= );

The systemstate dump contains a separate section with information for each process.
Open the tracefile and do a search for "PROCESS ".
In the process section search for the wait event by doing a search on 'waiting for'.
PROCESS 20:
----------------------------------------
SO: 0x7d2bd820, type: 2, owner: (nil), flag: INIT/-/-/0x00
(process) Oracle pid=20, calls cur/top: 0x7d3d62d0/0x7d3d85dc, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 109 0 4
last post received-location: kslpsr
last process to post me: 7d2b8d94 1 6
last post sent: 0 0 24
last post sent-location: ksasnd
last process posted by me: 7d2b8d94 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 0x7d2ed5dc
O/S info: user: oracle, term: pts/7, ospid: 19759
OSD pid info: Unix process pid: 19759, image: goblin.forgotten.realms (TNS V1-V3)



(session) sid: 141 trans: (nil), creator: 0x7d2bd820, flag: (41) USR/- BSY/-/-/-/-/-
DID: 0001-0014-00000668, short-term DID: 0000-0000-00000000
txn branch: (nil)
oct: 6, prv: 0, sql: 0x62d01c34, psql: 0x7c20f24c, user: 542/SCOTT
service name: SYS$USERS
O/S info: user: oracle, term: pts/7, ospid: 19758, machine: goblin.forgotten.realms
program: sqlplus@goblin.forgotten.realms (TNS V1-V3)
application name: SQL*Plus, hash value=3669949024
waiting for 'library cache lock' blocking sess=0x(nil) seq=36 wait_time=0 seconds since wait started=11
handle address=62d064dc, lock address=79f88a68, 100*mode+namespace=c9

  • Use the handle address to find information on the object locked:

SO: 0x79f88a68, type: 53, owner: 0x7d3d62d0, flag: INIT/-/-/0x00
LIBRARY OBJECT LOCK: lock=79f88a68 handle=62d064dc request=S
call pin=(nil) session pin=(nil) hpc=0000 hlc=0000
htl=0x79f88ab4[0x79e71e60,0x79e71e60] htb=0x79e71e60 ssga=0x79e716fc
user=7d3a13b8 session=7d3a13b8 count=0 flags=[0000] savepoint=0xce
LIBRARY OBJECT HANDLE: handle=62d064dc mtx=0x62d06590(0) cdp=0
name=SCOTT.EMPLOYEES

We see the library object lock is being requested in Shared mode (request=S)
Name of the the object is SCOTT.EMPLOYEES
  • Use the 'handle address' to find the process that is holding the lock on  your resource by doing a search on the address within the same tracefile.

PROCESS 18:
----------------------------------------
SO: 0x7d2bcca8, type: 2, owner: (nil), flag: INIT/-/-/0x00
(process) Oracle pid=18, calls cur/top: 0x79f3ab84/0x7d3d5fc8, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 109 0 4
last post received-location: kslpsr
last process to post me: 7d2b8d94 1 6
last post sent: 0 0 24
last post sent-location: ksasnd
last process posted by me: 7d2b8d94 1 6



SO: 0x75fe8f7c, type: 53, owner: 0x7b751914, flag: INIT/-/-/0x00
LIBRARY OBJECT LOCK: lock=75fe8f7c handle=62d064dc mode=X
call pin=(nil) session pin=(nil) hpc=0000 hlc=0000
htl=0x75fe8fc8[0x79f81790,0x79fc3ef8] htb=0x79f81790 ssga=0x79f8102c
user=7d3988d0 session=7d3988d0 count=1 flags=[0000] savepoint=0x146e
LIBRARY OBJECT HANDLE: handle=62d064dc mtx=0x62d06590(0) cdp=0
name=SCOTT.EMPLOYEES

From the output we can see that the Process 18 (pid)  is holding  an exclusive lock (mode=X) on the object we are trying to access. Using V$PROCESS and V$SESSION we can retrieve the sid, user, terminal, program,... for this process.

The actual statement that was launched by this session is also listed in the tracefile (statements and other library cache objects are preceded by 'name=').


No comments:

Post a Comment