Library Cache Miss

Filed under:  Infrastructure, Troubleshooting — Jonathan Lewis @ 7:50 pm GMT 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 ofglobal 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 GMT 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 GMT 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 GMT 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 GMT 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 GMT Mar 31,2009 Reply


RSS feed for comments on this post. TrackBack URI

  • 0
    点赞
  • 0
    收藏
    觉得还不错? 一键收藏
  • 0
    评论
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值