Oracle Scratchpad

July 19, 2007

Library Cache Miss

Filed under: Infrastructure,Troubleshooting — Jonathan Lewis @ 7:50 pm BST Jul 19,2007

The following question came up on the comp.databases.oracle.server newsgroup a little while ago: 

What is the interpretation of the following:

  • Misses in library cache during parse
    • (Misses while looking for plan in library cache–Hard parse)
  • Misses in library cache during execute
    • (Misses while about to execute the plan and found it missing/invalid in library cache)
 
call     count       cpu    elapsed       disk      query    current       rows 
------- ------  -------- ---------- ---------- ---------- ---------- ---------- 
Parse        2      0.02       0.02          0          0          0          0 
Execute      7      0.09       0.08          0          5          0          0 
Fetch     2017      0.63       0.75        203      47302          0      15000 
------- ------  -------- ---------- ---------- ---------- ---------- ---------- 
total     2026      0.75       0.86        203      47307          0      15000                 

Misses in library cache during parse: 1 
Misses in library cache during execute: 5 

As the poster points out, the statistics about “Misses in library cache” correspond to calls to the optimizer to produce an execution plan for the statement (the so-called “hard parse” – even though some such “parses” take place on the execute).

The real question, presumably, is “Why did Oracle have to re-optimise the statement so frequently prior to executing it ?”.

It’s hard to infer specific reasons, but we can take a couple of guesses. The statement was parsed twice (two parse calls) and executed seven times – so the client code seems to be holding cursor open for at least some of the time. On one parse call and two execute calls the execution plan was found in the library cache, but on most occasions it could not be found. So either it has been invalidated, or it had been flushed from the library cache (and “reloaded”) fairly frequently.

Invalidation means that some significant change occured to the objects referenced that made the current execution invalid. Flushes will occur if there is demand for free memory – execution plans are recreateable, so they can be flushed from memory even when the cursor is being held by the client.

To investigate further, we need to know whether the problem was one of simple reloads or invalidations. The first step is to go back to the raw trace file (which I assume you have since you’ve just used tkprof on it) and find the “parsing” line for the guilty statement. It will look something like this:

 
PARSING IN CURSOR #3 len=55 dep=0 uid=62 oct=3 lid=62 tim=117415948231 hv=1024979987 ad='1893bf40' 
select /*+ find this */ count(n2) from t1 where n1 = 15       

The hv value is the hash_value (even in 10g) from v$sql, and the ad is the address. Once you have these values, you can query v$sql for the critical information:

 
SQL> select 
  2     child_number, loads, invalidations, parse_calls, executions 
  3  from 
  4     v$sql 
  5  where 
  6     hash_value = 1024979987 
  7  ;      

CHILD_NUMBER      LOADS INVALIDATIONS PARSE_CALLS EXECUTIONS 
------------ ---------- ------------- ----------- ---------- 
           0          6             5           1          1 

I’ve only used the hash_value (that’s the efficient way into v$sql for versions before 10g – the address is useful only in the unlikely case of a hash collision occurring).

As you can see, the number of loads is just a tiny bit bigger than the number of invalidations. This tells me that most of my problems were do to a structural effect, rather than losing the plan through memory starvation. If the number of loads was much higher than the number of invalidations, that would indicate a memory flushing problem.

As you can see, I’ve also printed up the child_number – this isn’t information that would makes a lot of sense in the trace file – it’s potentially transient and misleading – but it is possible for the same SQL text to result in many child cursors, so it’s worth making sure you check v$sql so that you can see them all.

Just for reference, one of the issues that could cause this type of “excess invalidation” (prior to 10gR2) was the use of global temporary tables (GTTs) defined as ‘on commit preserve rows’. To empty such a table, you either had to terminate your session, delete all the rows (inefficiently) or truncate the table.

But the truncate command is DDL, so if you truncated your private copy of the table every cursor referencing that table would be invalidated. I’ve seen this cause massive contention in the SQL area when such tables have been used at high levels of concurrency.

5 Comments »

  1. I was scared by the sight of the trace file. Now I can look at it with bit more confidence.

    Comment by satya — July 23, 2008 @ 10:02 pm BST Jul 23,2008 | Reply

  2. Hi Jonathan,

    I am really confused here. Please taek a look at the below trace

    TKPROF: Release 10.2.0.3.0 - Production on Fri Feb 20 10:25:02 2009
    
    Copyright (c) 1982, 2005, Oracle.  All rights reserved.
    
    
    
    Trace file: xxxxx1_ora_2465.trc
    
    Sort options: default
    
    ********************************************************************************
    count    = number of times OCI procedure was executed
    cpu      = cpu time in seconds executing
    elapsed  = elapsed time in seconds executing
    disk     = number of physical reads of buffers from disk
    query    = number of buffers gotten for consistent read
    current  = number of buffers gotten in current mode (usually for update)
    rows     = number of rows processed by the fetch or execute call
    ********************************************************************************
    
    insert into fet_trade_b(TICKER_ID,
                                                    TRADE_TIME, QUAD_ID,
                                                    TRADE_VOL_QTY,TRADE_PRC_AMT, PRICE_IND,
                                                    INSERT_SEQUENCE,DB_ACTION_TIME,DB_ACTION_TYPE,DB_ACTION_USER_ID) values (:1, :2, :3, :4, :5,
                                                    :6,trade_seq.nextval,:7,:8,:9)
    
    
    call     count       cpu    elapsed       disk      query    current        rows
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    Parse     1863      0.05       0.05          0          0          0           0
    Execute   1863      3.03       7.88       5331       3235      94854       37260
    Fetch        0      0.00       0.00          0          0          0           0
    ------- ------  -------- ---------- ---------- ---------- ----------  ----------
    total     3726      3.09       7.94       5331       3235      94854       37260
    
    Misses in library cache during parse: 1
    Misses in library cache during execute: 1
    Optimizer mode: ALL_ROWS
    Parsing user id: 513
    
    Rows     Row Source Operation
    -------  ---------------------------------------------------
         20  SEQUENCE  TRADE_SEQ (cr=0 pr=0 pw=0 time=135 us)
    
    
    Elapsed times include waiting on following events:
      Event waited on                             Times   Max. Wait  Total Waited
      ----------------------------------------   Waited  ----------  ------------
      library cache lock                             13        0.00          0.00
      gc current grant 2-way                       3040        0.00          1.18
      db file sequential read                      5316        0.05          4.01
      SQL*Net message to client                    1863        0.00          0.00
      SQL*Net message from client                  1863        6.62         89.21
      enq: HW - contention                           17        0.00          0.00
      row cache lock                                  7        0.00          0.00
      gc current multi block request                 27        0.00          0.01
      enq: FB - contention                           14        0.00          0.00
      log file sync                                   2        0.00          0.00
      gc cr grant 2-way                               1        0.00          0.00
      enq: TT - contention                            1        0.00          0.00
    ********************************************************************************
    
    

    I see the miss during parse and miss during execute as 1 but, the actual parse is 1863 tims. As you can see the insert statement has all bind variables except for the sequence.nextval.

    I also checked for invalidations,

    SQL> select child_number, loads, invalidations, parse_calls, executions from v$sql where hash_value = 35252651;

    CHILD_NUMBER LOADS INVALIDATIONS PARSE_CALLS EXECUTIONS
    ———— ———- ————- ———– ———-
    0 1 0 633 633

    Can you please throw some light here ?

    Comment by Sundar R — February 20, 2009 @ 4:51 pm BST Feb 20,2009 | Reply

  3. Sorry I missed some more comment . My doubt is that , will the usage of sequence.nextval cause a soft-parse every time when it is called.

    The sequences if created with a cache value of 20000 and this is on a 2 node RAC. Any insight comment would be of great help in understanding. here?

    Comment by Sundar R — February 20, 2009 @ 4:55 pm BST Feb 20,2009 | Reply

  4. Sundar R,

    The significance of the “Parse” line is that the front-end code has issued a parse call to the database. Without detailed examination of things like session stats, trace files etc. you can’t really tell what the database response was to that parse call.

    It is quite possible that the OCI library had cached a pointer to the cursor in the session cursor cache so that the effect of the call was virtually identical to the use of a held cursor. The only thing we can be confident about from this tkprof output is that Oracle did not have to optimise the statement on every parse call (or we would have seen lots of library cache misses).

    Answering your specific question – the presence of the sequence.nextval will not cause a “soft parse” on every call.

    Comment by Jonathan Lewis — March 21, 2009 @ 11:24 pm BST Mar 21,2009 | Reply

  5. SEQUENCE.NEXTVAL will cause (probably soft) parse and execute of stmt: “update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6,cache=:7,highwater=:8,audit$=:9,flags=:10 where obj#=:1:” everytime it should increment the sequence – in case the sequence is NOCACHE it’ll happen for every SEQUENCE.NEXTVAL, in case of CACHE 10 it’ll happen for every 10th SEQUENCE.NEXTVAL, etc.

    Comment by Alon Principal — March 31, 2009 @ 11:59 am BST Mar 31,2009 | Reply


RSS feed for comments on this post. TrackBack URI

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

Theme: Rubric. Get a free blog at WordPress.com

Follow

Get every new post delivered to your Inbox.

Join 4,267 other followers