FAQ
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:

_at_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 _at_ 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.

Search Discussions

  • Sanjeev M at Aug 2, 2011 at 6:32 pm
    Typo corrected in *RED* below
    On Tue, Aug 2, 2011 at 11:19 AM, Sanjeev M wrote:

    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='0000000356213B10';
    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:
    _at_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 _at_ 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.
    --
    http://www.freelists.org/webpage/oracle-l
  • Bobak, Mark at Aug 2, 2011 at 8:19 pm
    Sanjeev,

    I think your problem here is misunderstanding your script output. As per Tanel's script, your process was 'ON CPU'. If it's on cpu, it's not waiting, and the wait event indicates that last thing that it waited on, but it has long since moved on.

    The key is to consider the value of V$SESSION.STATE, in combination with V$SESSION.EVENT. If STATE column is anything other than 'WAITING', then you are *not* waiting, and are in fact, on the CPU. In this case, if STATE is 'WAITED SHORT TIME', then you waited on the event recorded in EVENT for less than a centisecond. If it's 'WAITED KNOWN TIME', then the time you waited is reflected in WAIT_TIME, and if STATE is 'WAITED UNKNOWN TIME', you need to enable timed_statistics.

    So, you're not really stuck on library cache pin wait, at all.

    Hope that helps,

    -Mark

    From: oracle-l-bounce_at_freelists.org On Behalf Of Sanjeev M
    Sent: Tuesday, August 02, 2011 2:32 PM
    To: ORACLE-L
    Subject: Re: No blocking session for wait event: 'Library cache pin'

    Typo corrected in RED below
    On Tue, Aug 2, 2011 at 11:19 AM, Sanjeev M > wrote:
    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='0000000356213B10';
    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:

    _at_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 _at_ E2SN ( http://tech.e2sn.com<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.
  • Tanel Poder at Aug 3, 2011 at 1:54 am
    +1 to what Mark & Marcin said (although I prefer using the V$SESSION.STATE
    too, not decode the WAIT_TIME manually)

    And it looks like the CPU usage comes from excessive LIOs which come from
    the nested loop which is driven by all the rows that come from the
    MTL_SYSTEM_ITEMS_B

    table... so if you get thousands of rows from that table, you'll end up
    doing the index range scan (the other child under that nested loops join)
    also thousands of times. If this query worked well in past, it's probably a
    stats issue (or just that there's more rows in that driving table now).

    --
    Tanel Poder
    http://blog.tanelpoder.com/
    http://www.ExpertOracleExadata.com
    On Tue, Aug 2, 2011 at 11:19 PM, Bobak, Mark wrote:

    Sanjeev,****

    ** **

    I think your problem here is misunderstanding your script output. As per
    Tanel�s script, your process was �ON CPU�. If it�s on cpu, it�s not
    waiting, and the wait event indicates that last thing that it waited on, but
    it has long since moved on.****

    ** **

    The key is to consider the value of V$SESSION.STATE, in combination with
    V$SESSION.EVENT. If STATE column is anything other than �WAITING�, then you
    are **not** waiting, and are in fact, on the CPU. In this case, if STATE
    is �WAITED SHORT TIME�, then you waited on the event recorded in EVENT for
    less than a centisecond. If it�s �WAITED KNOWN TIME�, then the time you
    waited is reflected in WAIT_TIME, and if STATE is �WAITED UNKNOWN TIME�, you
    need to enable timed_statistics.****

    ** **

    So, you�re not really stuck on library cache pin wait, at all.****

    ** **

    Hope that helps,****

    ** **

    -Mark****

    --
    http://www.freelists.org/webpage/oracle-l
  • Mark W. Farnham at Aug 3, 2011 at 3:51 pm
    +1 as well.



    Also be aware that if direct adaptive read kicks in that gets you blocks of
    first row pieces, for which the query may then demand non-first row pieces
    by db file sequential read, even if the secondary row pieces are in the same
    block since it was not buffer cached unless the table is in keep cache.



    I can't remember at the moment whether mtl_system_items has over 255 columns
    (which generates multiple row pieces even without row migration).



    A short section of extended trace will make this quite obvious if it is the
    root cause (as opposed to getting a newly bad plan or organic growth as per
    Tanel, which are both more likely).



    Regards,



    mwf



    From: oracle-l-bounce_at_freelists.org
    On Behalf Of Tanel Poder
    Sent: Tuesday, August 02, 2011 9:55 PM
    To: Mark.Bobak_at_proquest.com
    Cc: sanjeevorcle_at_gmail.com; ORACLE-L
    Subject: Re: No blocking session for wait event: 'Library cache pin'



    +1 to what Mark & Marcin said (although I prefer using the V$SESSION.STATE
    too, not decode the WAIT_TIME manually)



    And it looks like the CPU usage comes from excessive LIOs which come from
    the nested loop which is driven by all the rows that come from the
    MTL_SYSTEM_ITEMS_B table... so if you get thousands of rows from that table,
    you'll end up doing the index range scan (the other child under that nested
    loops join) also thousands of times. If this query worked well in past, it's
    probably a stats issue (or just that there's more rows in that driving table
    now).



    --

    Tanel Poder

    http://blog.tanelpoder.com/

    http://www.ExpertOracleExadata.com

    On Tue, Aug 2, 2011 at 11:19 PM, Bobak, Mark
    wrote:

    Sanjeev,

    I think your problem here is misunderstanding your script output. As per
    Tanel's script, your process was 'ON CPU'. If it's on cpu, it's not
    waiting, and the wait event indicates that last thing that it waited on, but
    it has long since moved on.

    The key is to consider the value of V$SESSION.STATE, in combination with
    V$SESSION.EVENT. If STATE column is anything other than 'WAITING', then you
    are *not* waiting, and are in fact, on the CPU. In this case, if STATE is
    'WAITED SHORT TIME', then you waited on the event recorded in EVENT for less
    than a centisecond. If it's 'WAITED KNOWN TIME', then the time you waited
    is reflected in WAIT_TIME, and if STATE is 'WAITED UNKNOWN TIME', you need
    to enable timed_statistics.

    So, you're not really stuck on library cache pin wait, at all.

    Hope that helps,

    -Mark

    --
    http://www.freelists.org/webpage/oracle-l
  • Marcin Przepiorowski at Aug 2, 2011 at 9:17 pm

    On Tue, Aug 2, 2011 at 7:19 PM, Sanjeev M wrote:
    select p1raw,p1text,event,sid from v$session where sid=1710;
    P1RAW
    P1TEXT
    EVENT                                                                   SID
    ----------------
    ----------------------------------------------------------------
    ---------------------------------------------------------------- ----------
    0000000356213B10 handle
    address                                                   library cache
    pin                                                      1710
    Hi,

    Add wait_time to your query

    select p1raw,p1text,event,sid, wait_time from v$session where sid=1710;

    If wait_time = 0 session is waiting
    If wait_time <> 0 session is on CPU but event and p1 columns still
    have old values (Oracle is lazy and doesn't clean it)

    Probably this is why you have different output from your query and Tanel's tool.
    If session is on CPU you need to analyse session stats (add stats and
    gather to snapper) and take a look here -
    http://blog.tanelpoder.com/2010/01/15/beyond-oracle-wait-interface-part-2/
  • Sanjeev M at Aug 2, 2011 at 9:38 pm
    Thanks Marcin,Mark for clarification - will keep this in mind in future.

    ~ Sanjeev.
    On Tue, Aug 2, 2011 at 2:17 PM, Marcin Przepiorowski wrote:
    On Tue, Aug 2, 2011 at 7:19 PM, Sanjeev M wrote:

    select p1raw,p1text,event,sid from v$session where sid=1710;
    P1RAW
    P1TEXT
    EVENT SID
    ----------------
    ----------------------------------------------------------------
    ----------------------------------------------------------------
    ----------
    0000000356213B10 handle
    address library cache
    pin 1710
    Hi,

    Add wait_time to your query

    select p1raw,p1text,event,sid, wait_time from v$session where sid=1710;

    If wait_time = 0 session is waiting
    If wait_time <> 0 session is on CPU but event and p1 columns still
    have old values (Oracle is lazy and doesn't clean it)

    Probably this is why you have different output from your query and Tanel's
    tool.
    If session is on CPU you need to analyse session stats (add stats and
    gather to snapper) and take a look here -
    http://blog.tanelpoder.com/2010/01/15/beyond-oracle-wait-interface-part-2/

    --
    Marcin Przepiorowski
    http://oracleprof.blogspot.com
    --
    http://www.freelists.org/webpage/oracle-l

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouporacle-l @
categoriesoracle
postedAug 2, '11 at 6:19p
activeAug 3, '11 at 3:51p
posts7
users5
websiteoracle.com

People

Translate

site design / logo © 2022 Grokbase