No blocking session for wait event: 'Library cache pin'

  • From: Sanjeev M <sanjeevorcle@xxxxxxxxx>
  • To: ORACLE-L <oracle-l@xxxxxxxxxxxxx>
  • Date: Tue, 2 Aug 2011 11:19:34 -0700

Environment: 2 node RAC on OEL 5
Grid Home  : 11.2.0.2
RDBMS Home: 11.1.0.7.7

On our database, Session was waiting most of the time on 'library cache pin'
wait - for a decent amount like a minute or more before toggling to another
wait event db file sequential read and back to this wait.

Could it be a bug that the blocker session is not showing up?

select p1raw,p1text,event,sid from v$session where sid=1710;
P1RAW
P1TEXT
EVENT                                                                   SID
----------------
----------------------------------------------------------------
---------------------------------------------------------------- ----------
0000000356213B10 handle
address                                                   library cache
pin                                                      1710
select * from x$kglpn where KGLPNHDL='000000032FA9B7A0';
no rows selected    <=== Expected to see some info here regading object,
lock mode (Either null/shared or exclusive) however no output!!!

Also checked for other handle addresses from gv$session to see if it
possibly is having some kind of dependancy:

select inst_id,p1raw,count(1) from gv$session where event='library cache
pin' group by inst_id,p1raw;
   INST_ID P1RAW              COUNT(1)
---------- ---------------- ----------
         1 000000032FA9B7A0          1
         1 0000000356213B10          1

select * from x$kglpn where KGLPNHDL='000000032FA9B7A0';
no rows selected    <=== Expected to see some info here regading object,
lock mode (Either null/shared or exclusive) however no output!!!
Also tried gv$ges_blocking_enqueue however output does not show anything
related to *"lib pin   -- Nx Gx"*

'WAI    INST_ID       SPID RESOURCE_NAME1
---- ---------- ---------- ------------------------------
Wait          1      10838 [0x75daf18b][0x4c05b769],[NB]
Wait          2      17532 [0x19][0x2],[RS]
Wait          2          0 [0x8c0][0x10000],[BL]
Blkr          1      10132 [0x19][0x2],[RS]
Blkr          2      17508 [0x1][0x0],[PW]

Ran tanel poder's snapper while this was happening and it says session on
CPU:

@snapper ash=sql_id+event+wait_class+p1+p2+p3 5 1 1710
Sampling SID 1710 with interval 5 seconds, taking 1 snapshots...
-- Session Snapper v3.14 by Tanel Poder @ E2SN ( http://tech.e2sn.com )

--------------------------------------------------------------------------------------------------------------------------------
Active% | SQL_ID          | EVENT                     | WAIT_CLASS      |
P1               | P2               | P3
--------------------------------------------------------------------------------------------------------------------------------
*   100% | 10za9fj1va0kd   | ON CPU                    | ON CPU
|                  |                  |*
--  End of ASH snap 1, end=2011-08-02 11:00:58, seconds=5, samples_taken=42

PL/SQL procedure successfully completed.

*SQL statement that was being run for this session was:*

select msi.inventory_item_id                   from mtl_parameters mp,
                      mtl_system_items msi,
mtl_system_items_interface msii                   where
msii.transaction_id = :transaction_id_bind                    and
msii.set_process_id = :set_id_bind2                    *and rownum = 1
*                 and msi.organization_id = mp.organization_id
         and  msi.segment1 = msii.segment1
Plan hash value: 904999408
----------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name                          |
Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |
|       |       |   342 (100)|          |
|*  1 |  COUNT STOPKEY                 |
|       |       |            |          |
|   2 |   NESTED LOOPS                 |                               |
21 |   882 |   342   (1)| 00:00:05 |
|   3 |    NESTED LOOPS                |                               |
21 |   798 |   342   (1)| 00:00:05 |
|   4 |     TABLE ACCESS FULL          | MTL_SYSTEM_ITEMS_B            |
12245 |   191K|   342   (1)| 00:00:05 |
|*  5 |     TABLE ACCESS BY INDEX ROWID| MTL_SYSTEM_ITEMS_INTERFACE    |
1 |    22 |     0   (0)|          |
|*  6 |      INDEX RANGE SCAN          | MTL_SYSTEM_ITEMS_INTERFACE_N6 |
1 |       |     0   (0)|          |
|*  7 |    INDEX UNIQUE SCAN           | MTL_PARAMETERS_U1             |
1 |     4 |     0   (0)|          |
----------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(ROWNUM=1)
   5 - filter(("MSII"."SET_PROCESS_ID"=:SET_ID_BIND2 AND
"MSI"."SEGMENT1"="MSII"."SEGMENT1"))
   6 - access("MSII"."TRANSACTION_ID"=:TRANSACTION_ID_BIND)
   7 - access("MSI"."ORGANIZATION_ID"="MP"."ORGANIZATION_ID")
Any pointers or help much appreciated.

Thanks,
Sanjeev.

Other related posts: