6 Replies Latest reply on Feb 22, 2012 8:16 AM by 834639

    High library cache load lock waits in AWR

      Hi All,

      Today i faced a significant performance problem related to shared pool. I made some observations, thought it would be a nice idea to share them with Oracle experts. Please feel free to add your observations/recommendations and correct me where i am wrong.

      Here are the excerpts from AWR report created for the problem timing. Database server is on and running with 2*16 configuration. DB cache size is 4,000M and shared pool size is of 3008M.

       Snap Id Snap Time Sessions Cursors/Session 
      Begin Snap: 9994 29-Jun-09 10:00:07 672 66.3 
      End Snap: 10001 29-Jun-09 17:00:49 651 64.4 
      Elapsed:   420.70 (mins)     
      DB Time:   4,045.34 (mins)   
      -- Very poor response time visible from difference between DB time and elapsed time.

      Load Profile
       Per Second Per Transaction 
      Redo size: 248,954.70 23,511.82 
      Logical reads: 116,107.04 10,965.40 
      Block changes: 1,357.13 128.17 
      Physical reads: 125.49 11.85 
      Physical writes: 51.49 4.86 
      User calls: 224.69 21.22 
      Parses: 235.22 22.21 
      Hard parses: 4.83 0.46 
      Sorts: 102.94 9.72 
      Logons: 1.12 0.11 
      Executes: 821.11 77.55 
      Transactions: 10.59   
      -- User calls and Parse count are almost same, means most of the calls are for parse. Most of the parses are soft. Per transaction 22 parses are very high figure.
      -- Not much disk I/O activity. Most of the reads are being satisfy from memory.

      Instance Efficiency
      Buffer Nowait %: 100.00 Redo NoWait %: 100.00 
      Buffer Hit %: 99.92 In-memory Sort %: 100.00 
      Library Hit %: 98.92 Soft Parse %: 97.95 
      Execute to Parse %: 71.35 Latch Hit %: 99.98 
      Parse CPU to Parse Elapsd %: 16.82 % Non-Parse CPU: 91.41 
      -- Low execute to parse ratio denotes CPU is significantly busy in parsing. Soft Parse% showing, most of the parse are soft parses. It means we should concentrate on soft parsing activity.

      -- Parse CPU to Parse Elapsed % is quite low, means some bottleneck is there related to parsing. It could be a side-effect of huge parsing pressure. Like CPU cycles are not available.

      Shared Pool Statistics
       Begin End 
      Memory Usage %: 81.01 81.92 
      % SQL with executions>1: 88.51 86.93 
      % Memory for SQL w/exec>1: 86.16 86.76 
      -- Shared Pool memory seems ok (in 80% range)
      -- 88% of the SQLs are repeating ones. It's a good sign.

      Top 5 Timed Events
      Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class 
      library cache load lock 24,243 64,286 2,652 26.5 Concurrency 
      db file sequential read 1,580,769 42,267 27 17.4 User I/O 
      CPU time   33,039   13.6   
      latch: library cache 53,013 29,194 551 12.0 Concurrency 
      db file scattered read 151,669 13,550 89 5.6 User I/O 
      Problem-1: Contention on Library cache: May be due to under-sized shared pool, incorrect parameters, poor application design, But since we already observed that most of the parses are soft parses and shared pool usgae in 80%, seems problem related to holding cursors. open_cursors/session_cached_cursors are red flags.
      Problem-2: User I/O, may be due to poor SQLs, I/O sub-system, or poor physical design (wrong indexes are being used as DB file seq reads)

      Wait Class
      Wait Class Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn 
      Concurrency 170,577 44.58 109,020 639 0.64 
      User I/O 2,001,978 0.00 59,662 30 7.49 
      System I/O 564,771 0.00 8,069 14 2.11 
      Application 145,106 1.25 6,352 44 0.54 
      Commit 176,671 0.37 4,528 26 0.66 
      Other 27,557 6.31 2,532 92 0.10 
      Network 6,862,704 0.00 696 0 25.68 
      Configuration 3,858 3.71 141 37 0.01 
      Wait Events
      Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn 
      library cache load lock 24,243 83.95 64,286 2652 0.09 
      db file sequential read 1,580,769 0.00 42,267 27 5.91 
      latch: library cache 53,013 0.00 29,194 551 0.20 
      db file scattered read 151,669 0.00 13,550 89 0.57 
      latch: shared pool 25,403 0.00 12,969 511 0.10 
      log file sync 176,671 0.37 4,528 26 0.66 
      enq: TM - contention 1,455 90.93 3,975 2732 0.01 
      Instance Activity Stats
      opened cursors cumulative 5,290,760 209.60 19.80 
      parse count (failures) 6,181 0.24 0.02 
      parse count (hard) 121,841 4.83 0.46 
      parse count (total) 5,937,336 235.22 22.21 
      parse time cpu 283,787 11.24 1.06 
      parse time elapsed 1,687,096 66.84 6.31 
      Latch Activity
      library cache 85,042,375 0.15 0.43 29194 304,831 7.16 
      library cache load lock 257,089 0.00 1.20 0 69,065 0.00 
      library cache lock 41,467,300 0.02 0.07 6 2,714 0.07 
      library cache lock allocation 730,422 0.00 0.44 0 0   
      library cache pin 28,453,986 0.01 0.16 8 167 0.00 
      library cache pin allocation 509,000 0.00 0.38 0 0 
      Init.ora parameters

      cursor_sharing= EXACT

      open_cursors= 3000

      session_cached_cursors= 0

      -- open_cursors value is too high. I have checked that maximum usage by a single session is 12%.
      -- session_cached_cursors are 0 causing soft parsing. 500/600 is good number to start with.
      cursor_sharing exact may cause hard parses. But here, hard parsing is comparatively small, we can ignore this.

      From v$librarycache
      --------------- ---------- ---------- ----------- ---------- ----------- ---------- -------------
      SQL AREA            162827      25127  .154317159  748901435  .999153087     107941         81886
      -- high invalidation count due to DDL like activities.
      -- high reloads due to small library cache.
      -- hit ratio too small.
      -- Need to pin frequently executed objects into library cache.
      P.S. Same question asked on Oracle_L, but due to formatting reasons, pasing duplicate contents here.
      Neeraj Bhatia
      Edited by: Neeraj.Bhatia2 on Jul 13, 2009 6:51 AM                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                
        • 1. Re: High library cache load lock waits in AWR
          Charles Hooper
          Thanks for making an effort to interpret what you found in the AWR report. A 7 hour duration for the report is likely far too long.

          Fixing the spacing of what you posted:
          Event                        Waits  Time(s) Avg Wait(ms) % Total Call Time Wait Class 
          library cache load lock     24,243  64,286         2,652    26.5 Concurrency 
          db file sequential read  1,580,769  42,267            27    17.4 User I/O 
          CPU time                            33,039                  13.6   
          latch: library cache        53,013  29,194           551    12.0 Concurrency 
          db file scattered read     151,669  13,550            89     5.6 User I/O
          I suspect that the shared pool size of 3008M is part of the problem - it is likely much larger than needed, allowing a larger number of child cursors to remain in the shared pool longer, which then increases the time for latching as the child cursors are checked.

          My notes state the following about library cache load lock: Latch contention: SQL parsing or sharing. This wait event occurs when a significant number of reloads/loads are occurring in the shared pool, possibly due to lack of reuse of SQL statements or an improperly sized shared pool area.

          "Oracle Database Reference 11 g Release 1" Page C-21 states:
          "The session tries to find the load lock for the database object so that it can load the object. The load lock is always obtained in Exclusive mode, so that no other process can load the same object. If the load lock is busy the session will wait on this event until the lock becomes available. Wait Time: 3 seconds (1 second for PMON)."

          Note that the average wait time of the library cache load lock wait is 2.652 seconds - nearly the same as the 3 second timeout. It could be that there were only a small number of actual waits on this event, and the waits keep timing out (hitting the 3 second mark where the wait counter was then increased by 1).

          The book "Oracle Wait Interface: A Practical Guide to Performance Diagnostics & Tuning" on page 158 states this about the latch: library cache wait:
          "When a hash value of a SQL statement of a SQL statement being parsed matches the hash value of a SQL statement with a high number of children or version count, Oracle has to compare the statement with all existing versions. The library cache latch must be held for the duration of the inspection, and this may cause other sessions to miss on their library cache latch requests."

          Paraphrases from the above book regarding this wait:
          "Oracle processes acquire the library cache latch when modifying, inspecting, pinning, locking, loading, or executing objects in the library cache structures (cursors, SQL statements, execution plans, and parse trees)."
          "The library cache latch is acquired during a soft parse operation."
          "Prior to Oracle 9i, where multiple sub-pools for the shared pool were introduced, oversized shared pools caused contention for the shared pool latch, which must be held while scanning long free lists."

          The above indicates that soft parsing is a contributor to this wait event, so the idea of setting session_cached_cursors to a value other than 0 is likely valid. A value of 500 or 600 is likely far too high - this is a per session parameter. You might start with 50 and increase the parameter if the 'session cursor cache count' for each session shows that all 50 of the session cached cursors are used by most of the sessions.

          Note in the statistics:
          opened cursors cumulative  5,290,760  209.60  19.80 
          parse count (failures)         6,181    0.24   0.02 
          parse count (hard)           121,841    4.83   0.46 
          parse count (total)        5,937,336  235.22  22.21 
          parse time cpu               283,787   11.24   1.06 
          parse time elapsed         1,687,096   66.84   6.31
          That there is a significant difference between the parse time cpu and the parse time elapsed - that means that something, on average, is significantly delaying the parses - likely related to the library cache wait events. You did not provide statistics which show the CPU utilization - that could provide a key to the cause of the problem. Specifically of interest is the section from V$OSSTAT and the section from V$SYS_TIME_MODEL.

          Charles Hooper
          IT Manager/Oracle DBA
          K&M Machine-Fabricating, Inc.
          1 person found this helpful
          • 2. Re: High library cache load lock waits in AWR
            I believe that the main reasion of library cache load lock contention is frequent invalidations and/or reloads.

            - Do you execute frequent DDL which invaliate the cursors - like compiling, granting?

            - High SESSION_CACHED_CURSORS value would help.

            - You might be able to find on which objects Oracle waits for the library cache load lock by looking into the active session history.

            - 3 sec of avg load lock wait seems to be too harsh. There might be other reasons for that.

            Dion Cho - Oracle Performance Storyteller

            http://dioncho.wordpress.com (english)
            http://ukja.tistory.com (korean)
            http://dioncho.blogspot.com (japanese)
            • 3. Re: High library cache load lock waits in AWR
              Thanks Charles. I really appreciate your efforts to diagnose the issue.

              I agree with you performance issue is caused by soft parsing, which can be solved by holding cursors (session_cached_cursors). It may be due to oversized shared pool, which is causing delay in searching child cursors.
              My second thought is, there is large number of reloads, which can be due to under-sized shared pool, if invalidation activities are not going (CBO statistics collection, DDL etc), cursors are being flushed frequently.

              CPU utilization is continuously high (above 90%). Pasting additional information from same AWR report.
              Namespace                Get Requests       Pct Miss        Pin Requests         Pct Miss      Reloads        Invalidations 
              BODY                       225,345               0.76            4,965,541            0.15           5,533           0 
              CLUSTER                   1,278                  1.41            2,542                  1.73           26                0 
              INDEX                       5,982                  9.31            13,922                7.35           258               0 
              SQL AREA                  141,465              54.10           27,831,235         1.21           69,863          19,085 
              Latch Miss Sources
              Latch Name             Where                                         NoWait Misses                 Sleeps             Waiter Sleeps 
              library cache lock       kgllkdl: child: no lock handle             0                                   8,250                   5,792 
              Time Model Statistics
              Statistic Name                                                                           Time (s)                               % of DB Time 
              sql execute elapsed time                                                           206,979.31                                      85.27 
              PL/SQL execution elapsed time                                                    94,651.78                                      39.00 
              DB CPU                                                                                     33,039.29                                      13.61 
              parse time elapsed                                                                      22,635.47                                       9.33 
              inbound PL/SQL rpc elapsed time                                                  14,763.48                                       6.08 
              hard parse elapsed time                                                               14,136.77                                       5.82 
              connection management call elapsed time                                        1,625.07                                       0.67 
              PL/SQL compilation elapsed time                                                        760.76                                       0.31 
              repeated bind elapsed time                                                               664.81                                       0.27 
              hard parse (sharing criteria) elapsed time                                             500.11                                       0.21 
              Java execution elapsed time                                                              252.95                                       0.10 
              failed parse elapsed time                                                                   167.23                                       0.07 
              hard parse (bind mismatch) elapsed time                                             124.11                                       0.05 
              sequence load elapsed time                                                                23.34                                        0.01 
              DB time                                                                                   242,720.12   
              background elapsed time                                                             11,645.52   
              background cpu time                                                                      247.25 
              According to this DB CPU is 65% utilization (DB CPU + Background CPU / Total Available CPU seconds). While at the same time DB host was 95% utilized (confirmed from DBA_HIST_SYSMETRIC_SUMMARY).

              Operating System Statistics
              Statistic                                         Total 
              BUSY_TIME                             3,586,030 
              IDLE_TIME                              1,545,064 
              IOWAIT_TIME                              22,237 
              NICE_TIME                                           0 
              SYS_TIME                                  197,661 
              USER_TIME                              3,319,452 
              LOAD                                                 11 
              RSRC_MGR_CPU_WAIT_TIME                  0 
              PHYSICAL_MEMORY_BYTES          867,180 
              NUM_CPUS                                           2 
              • 4. Re: High library cache load lock waits in AWR
                Yes, I am going to recommend increasing session_cached_cursors from current value of 0 (very bad setting).

                Database server has only two physical CPUs and at the time of AWR report CPU was constantly running above 90% levels, may be due to the same parsing activity is really slow and hence around 3 secs of load lock waits.
                • 5. Re: High library cache load lock waits in AWR
                  Charles Hooper
                  A 7 hour long Statspack or AWR capture period is too long - real problems will be hidden in the averages over the 7 hour time period.
                  Statistic                    Total 
                  BUSY_TIME                3,586,030 
                  IDLE_TIME                1,545,064 
                  IOWAIT_TIME                 22,237 
                  NICE_TIME                        0 
                  SYS_TIME                   197,661 
                  USER_TIME                3,319,452 
                  LOAD                            11 
                  RSRC_MGR_CPU_WAIT_TIME           0 
                  PHYSICAL_MEMORY_BYTES      867,180 
                  NUM_CPUS                         2
                  Reference: http://download.oracle.com/docs/cd/B19306_01/server.102/b14237/dynviews_2010.htm
                  "LOAD: Current number of processes that are either running or in the ready state, waiting to be selected by the operating-system scheduler to run. On many platforms, this statistic reflects the average load over the past minute."

                  The above seems to imply that there were periods were several processes were competing for CPU time. The PHYSICAL_MEMORY_BYTES statistic must be incorrect.

                  The CPUs on average are 69.89% busy (unless I calculated this wrong):
                  35860.30 / (15450.64 + 35860.30) * 100 = 69.89% busy

                  Having only 2 CPUs probably does not help much during the periods where library cache load locks occur.
                  Statistic Name                                  Time (s)  % of DB Time 
                  sql execute elapsed time                      206,979.31         85.27 
                  PL/SQL execution elapsed time                  94,651.78         39.00 
                  DB CPU                                         33,039.29         13.61 
                  parse time elapsed                             22,635.47          9.33 
                  inbound PL/SQL rpc elapsed time                14,763.48          6.08 
                  hard parse elapsed time                        14,136.77          5.82 
                  connection management call elapsed time         1,625.07          0.67 
                  PL/SQL compilation elapsed time                   760.76          0.31 
                  repeated bind elapsed time                        664.81          0.27 
                  hard parse (sharing criteria) elapsed time        500.11          0.21 
                  Java execution elapsed time                       252.95          0.10 
                  failed parse elapsed time                         167.23          0.07 
                  hard parse (bind mismatch) elapsed time           124.11          0.05 
                  sequence load elapsed time                         23.34          0.01 
                  DB time                                       242,720.12   
                  background elapsed time                        11,645.52   
                  background cpu time                               247.25
                  33,039 + 247.25 = 33,286.25 seconds of the 35,860.30 of busy time of the 25,242*2 = 50,484 available seconds = 65.93% busy due to Oracle

                  760.76 seconds were spent compiling PL/SQL. If those PL/SQL functions are referenced in SQL statements, it will cause unnecessary invalidations of SQL statements. If the PL/SQL functions are part of a package, all SQL statements which reference other PL/SQL functions after the one modified will likely be invalidated, causing unnecessary parsing.

                  You might want to take a look at this document by Kyle Hailey which describes some of the wait events you are seeing:
                  Slide 29 shows that using 'ANALYZE TABLE' results in SQL invalidations of any SQL statement which references the objects. On 10g and above, using DBMS_STATS causes a delayed invalidation of SQL statements referencing those objects - I am not sure if there is a delay with ANALYZE. Analyzing indexes could cause the same issue.

                  If you take a look again at the average wait time for the 'library cache load lock' waits which is 2.652 seconds, it is very close very close to the 3 second timeout for the wait event. As I stated previously, this could mean that there were not 24,243 waits on this event for an average of 2.652 seconds each, but maybe just a 100 true waits that each lasted 643 seconds, for instance (this would appear as 215 waits on this wait event for each of the true waits on the event).

                  Is someone rebuilding indexes, using analyze, changing PL/SQL functions, modifying table columns or adding columns? Do objects in different schemas have the same names? Are there public and private synonyms which have the same name but point to different objects? Are there issues where bind variable values vary significantly in size?

                  References which describe dependencies among objects and invalidations:

                  Select a much smaller time frame for analysis: 60 minutes, 30 minutes, 15 minutes, or 10 minutes (select 10 minutes if you know that the problem may be completely contained in that time period.

                  Charles Hooper
                  IT Manager/Oracle DBA
                  K&M Machine-Fabricating, Inc.
                  • 6. Re: High library cache load lock waits in AWR

                    I just read your post. You have a lot of understanding of awr report. Can you guide me ?

                    I shall be very glad and thankful to you.

                    My email id is adnanhamdussalam@gmail.com

                    Kind Regards,

                    Adnan Hamdus Salam