" Library Cache: Mutex X " On Koka Cursors (LOBs) Non-Shared : (文档 ID 758674.1)

In this Document Symptoms Changes Cause Solution ReferencesAPPLIES TO:Oracle Server - Enterprise Edition - Version: 10.2.0.1 to 11.1.0.7 - Release: 10.2 to 11.1Oracle Se

mybluetiankong

1648人浏览 · 2014-01-20 15:37:33

mybluetiankong · 2014-01-20 15:37:33 发布

In this Document
  Symptoms

      Changes

      Cause

      Solution

      References
APPLIES TO: Oracle Server - Enterprise Edition - Version: 10.2.0.1 to 11.1.0.7 - Release: 10.2 to 11.1 
 
  Oracle Server - Enterprise Edition - Version: 11.1.0.7 and later    [Release: 11.1 and later] 
 
  Information in this document applies to any platform. 
 
  Oracle Server Enterprise Edition - Version: 11.1.0.7 
 
  Performance 
 
  11.1.0.x 
 
  Child Cursors 
 
  Library Cache: Mutex X 
 
  kksfbc child completion 
 
  NLS_LENGTH_SEMANTICS  
 
  cursor: pin S wait on X 
 SYMPTOMSIn testing prior to going to 11g, you find that application procedures which had completed in Oracle 10g in  minutes (e.g. 30-40 ) are now taking 12 hours or more ... or may not complete at all
Symptom #1
Using Oracle 11g with Automatic Memory Management you may find within a short amount of time CPU Utilization reached up to 100% and detected unusual Wait Event stats for 2 or more of the following: 
library cache: mutex X
cursor: pin S wait on X
cursor: mutex S
cursor: pin S
kksfbc child completion
Concurrency         -- as a Foreground Wait at 100%
Symptom #2
Exceptional time spent for one of the following
ksdxexeotherwait                   -- Long duration waits due to spin or 'other'
% of busy CPU for Instance   -- 90%+ 
   If you are use "Automatic Memory Management" you may test switching to Manual as a workaround 
CPU Utilization may improve substantially from the previously seen ~ 100% CPU but the values for "library cache: mutex X" will remain high and some procedures may never complete or run for several hours whereas they completed in minutes on 10gRx

Symtom #3
No confirmation that the following query ever completes: (N/A)*

     High DBTime for a Simple Query that should execute in less than one second (85.6%)**
Elapsed     CPU                     Elap per  % Total 

      Time (s)    Time (s) Executions     Exec(s)   DB Time     SQL Id 

      ---------- ---------- ------------ ---------- -------     ------------- 

      32,514     32,195      N/A*           N/A*       85.6**   6dv0dpznx0dg9 

select VALUE from NLS_SESSION_PARAMETERS where PARAMETER='NLS_LENGTH_SEMANTICS'

Symptom #4
 You have determined that
No session is in a hung state (per systemstate / hang analysis)
Oracle and Application may show processes as ACTIVE but you cannot kill the process from the OS and now work is being done by Oracle or the application
Symptom #5
AWR:  Library cache: mutex X and Concurrency Wait Class dominates the Top 5 Wait Events

                                                      Avg 

                                        %Time   Total   Wait    

      Wait Class                  Waits -outs   Time(s) (ms)  %DB time 

      ----------------------------------------- ---------------- -------- ---- 

      library cache: mutex X 370,798,153       336,901   1    32.1 Concurrency

      DB CPU                     264,148                      25.1 

      ksdxexeotherwait             1,548         1,275  824     .1 Other 

      cursor: mutex S            751,745           627    1     .1 Concurrency 

      latch: shared pool          34,948           386   11     .0 Concurrency

      ... 
    
     Further AWR statistics will include High Concurrency Foreground Wait Events

                                                             Avg 

                                          %Time   Total  Wait  wait  Waits%DB 

      Event                         Waits -outs    Time   (s)  (ms)  /txn time

      ----------------------------------------------------------------------

      library cache: mutex X  370,798,153  100  336,901    1   1.4E+05   32. 

      ksdxexeotherwait              1,548    0    1,275  824     0.6      .1 

      cursor: mutex S             751,745  100      627    1   277.2      .1 

      latch: shared pool           34,948    0      386   11    12.9      .0

      cursor: pin S             2,837,512  100      375    0 1,046.3      .0

      cursor: pin S wait on X       7,486   92      154   21     2.8      .0

      wait list latch free            808    0       63   78     0.3      .0

      latch free                       17    0        5  270     0.0      .0 

      cursor: mutex X              18,935  100        2    0     7.0      .0

      ...

      ...

Second example profiling FOREGROUND WAITS

    Foreground Wait Events DB/Inst: OPRDBI/oprdbi1 Snaps: 2798-2799 

      -> s - second, ms - millisecond - 1000th of a second 

      -> Only events with Total Wait Time (s) >= .001 are shown 

      -> ordered by wait time desc, waits desc (idle events last) 

      -> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0 

                                                           Avg 

                                              %Time Total  Wait wait Waits%DB 

      Event                             Waits -outs Time(s)(ms) /txn time 

      ------------------------------------------------------------------------
library cache: mutex X**    204,036,772  100*  431    0  5.9E+04    1. 

      kksfbc child completion           4,578  100*  234   51  1.3       .8 

      read by other session            27,325    0    83    3  7.9       .3 

      db file scattered read           20,853    0    68    3  6.0       .2 

      db file sequential read          10,007    0    62    6  2.9       .2 

      SQL*Net more data from cli        9,541    0    36    4  2.8       .1 

      cursor: pin S wait on X           1,648  100*   18   11  0.5       .1 

      *  Notice the 100% TimeOuts

      ** Huge number of Waits for library cache: mutex X

      ALSO: This problem had another symtom where the session completely Stopped

                                                          Avg 

                                           %Time Total   Wait  wait Waits%DB 

      Event                         Waits -outs Time (s) (ms) /txn time 

      ---------------------------------------------------------------------- 

      ksdxexeotherwait                 4     0   1,342 335507  0.0      3.5 

      db file scattered read     179,361     0     721      4  30.3     1.9 

      gc buffer busy acquire     168,885     0     708      4  28.6     1.9 

      db file sequential read    420,651     0     656      2  71.1     1.7 

      library cache: mutex X 256,357,476   100     485      0  4.3E+04  1. 

      ...

      ... 

    11.1.0.7 Sample

  - The query hung on select from nls_length_semantics 

       - Mutex stats hit 100% waits 

       - Child completion hit 100% waits 

       - CPU consumption high for no load:

            3-5x of all session time for the AWR duration 

                                                       Avg 

                                          %Time TotalWait  wait  Waits   %DB 

      Event                     Waits     -outs Time(s)    (ms)  /txn   time 

      -----------------------   -----     ----- -----   ------- ------  ---- 

      library cache: mutex X  204,036,772  100   431          0  5.9E+04  1. 

      kksfbc child completion       4,578  100   234         51   1.3    .8 

Symptom #6
Sample SYSTEM STATE excerpt shows exceptional oper SHRD or GET_EXCL[sive] on One mutex

    "...Resource Holder State 

          Mutex 96fb6306 273: Blocker 

      Object Names 

      ~~~~~~~~~~~~ 

      Mutex 96fb6306 

      ..."
    
     Grep for above mutex in the system state dump ... long list ... point being that a large number of sessions either have it shared or want it exclusive, heavily contended mutex. 

    "...

      Mutex 4dfa82650(0, 1) idn 96fb6306 oper SHRD 

      Mutex 4df7b1248(0, 1) idn 96fb6306 oper SHRD 

      Mutex 4df0c68b8(0, 1) idn 96fb6306 oper SHRD 

      Mutex 4df9a99b0(0, 1) idn 96fb6306 oper SHRD 

      Mutex 4df5d5b88(0, 1) idn 96fb6306 oper SHRD 

      Mutex 4df620bc0(0, 1) idn 96fb6306 oper SHRD 

      ...

      Mutex 4dfb28c60(1910, 0) idn 96fb6306 oper GET_EXCL 

      Mutex 4dfb28c60(756, 0) idn 96fb6306 oper GET_EXCL 

      Mutex 4ddceda68(0, 1) idn 96fb6306 oper SHRD 

      Mutex 4ddd01230(0, 1) idn 96fb6306 oper SHRD 

      ...

      .... Thousands more..."

     Symptom #7
If you further investigate you will find that the "problem" query's SQL TEXT is not reported 

    ** Row Source Not Available ** 

      ** SQL Text Not Available ** 

      Sampled # 

      SQL ID Planhash of Executions % Activity 

      ----------------------- -------------------- -------------------- -------------- 

      Event % Event Top Row Source % RwSrc 

      ------------------------------ ------- --------------------------------- ------- 

      c5brdpybgqss6 N/A 0 64.17 

      CPU + Wait for CPU 63.65 ** Row Source Not Available ** 63.65 

      ** SQL Text Not Available ** 

      2091112056 0 10.00 

      CPU + Wait for CPU 9.90 ** Row Source Not Available ** 9.90 

      ** SQL Text Not Available ** 

@Symptom #8

CHANGESTesting or usage after upgrading to 11.1.0.x from 10g or earlier
Using or switching to CHAR NLS_LENGTH_SEMANTICS vs. the default value of BYTE
Comment: NLS_LENGTH_SEMANTICS is set at the Column level for Tables, Views, Indexes, or Packages/Procedures for Sting based datatypes including [N]CHAR ; [N]VARCHAR2 ; [N]CLOB
CAUSEYou are most likely hitting 
Bug 7648406 CHILD CURSOR IS NOT SHARED IF NLS_LENGTH_SEMANTICS=CHAR

Bug 7648406 is caused by pseudo cursors which are not being shared as expected due to NLS_LENGTH_SEMANTICS=CHAR being set. 

   This bug can potentially result in thousands of Child Cursors for a single Parent Cursor which show as SHRD mutexes for "library cache: mutex X"
Another variation is
BUG 8523183 AQ APPLICATION STARTUP RESULTS IN HIGH SESSION CPU CONSUMPTION
More information can be found in
NOTE 783120.1 High cursor version count when NLS_LENGTH_SEMANTICS=CHAR Can Lead To ORA-4031 or ORA-600[17059] Errors

   You will find that there are a large number of cursors associated with SYS.KOTTD$ table. 

   Executing the following query checks for pseudo cursors with high version counts 

  connect / as sysdba
 
  select s.kglnaobj, sc.* from v$sql_shared_cursor sc, x$kglob s  where sc.sql_id=s.kglobt03 and INDX =CHILD_NUMBER and s.kglobt03 = '3zjuyvs42c8hs';
 
Results indicate that we have cursor mismatch on AUTH_CHECK_MISMATCH and LANGUAGE_MISMATCH for those cursors with high version counts. 
For more excellent information on this issue see
"Cursor: Pin S Wait On X" Contention Mutex Sleep Reason Primarily ' kkslce [KKSCHLPIN2]' Document 1268724.1
For a more comprehensive description ofWAITEVENT: "library cache: mutex X" please review document 727400.1 which includes many bug listings
SOLUTIONApply the patch for Bug 7648406  or request a backport if necessary
This is fixed in 11.2
REFERENCESBUG:7648406 - CHILD CURSOR IS NOT SHARED IF SET NLS_LENGTH_SEMANTICS=CHAR. 
 
BUG:8523183 - AQ APPLICATION STARTUP RESULTS IN HIGH SESSION CPU CONSUMPTION 
 
NOTE:1268724.1 - "Cursor: Pin S Wait On X" Contention Mutex Sleep Reason Primarily ' kkslce [KKSCHLPIN2]' 
 
NOTE:727400.1 - WAITEVENT: "library cache: mutex X" 
 
NOTE:783120.1 - High cursor version count when NLS_LENGTH_SEMANTICS=CHAR Can Lead To ORA-4031 or ORA-600[17059] Errors 
 
NOTE:831902.1 - High CPU consumption from AQ Enqueue and Dequeue Sessions after Application Startup

   
           相关内容
          
             产品
            
       Oracle Database Products > Oracle Database > Oracle Database > Oracle Database - Enterprise Edition > RDBMS > Globalization (NLS) issues
Oracle Database Products > Oracle Database > Oracle Database > Oracle Database - Enterprise Edition > RDBMS > Generic issues-rollback redo logs db creation

             错误
            
      ORA-600 [17059];  ORA-4031