<< Back to previous view

[QA-56] "cursor: mutex X" Created: 27/Jul/13  Updated: 28/Jul/13

Status: Open
Project: Questions & Answers
Fix Version/s: None

Type: Oracle - Database Tuning Priority: Major
Reporter: ubTools Support Assignee: ubTools Support
Resolution: Unresolved Votes: 0

Product Version: 11.2.0.3.7
Operating System: Solaris
Host Name: .
Database Name: .

 Description   
The customer has upgraded from Oracle 10.2.0.5 to Oracle 11.2.0.3.7. They encountered library cache lock problem.

Some excerpt from the AWR:

Elapsed:	 	 15.01 (mins)	 	 
DB Time:	 	 6,548.72 (mins)	 	 
.....
Top 5 Timed Foreground Events

Event	Waits	Time(s)	Avg wait (ms)	% DB time	Wait Class
library cache lock	425	364,186	856909	92.69	Concurrency
enq: TX - row lock contention	288	11,500	39930	2.93	Application
TCP Socket (KGAS)	136,317	9,552	70	2.43	Network
DB CPU	 	4,167	 	1.06	 
db file sequential read	742,541	2,176	3	0.55	User I/O


 Comments   
Comment by ubTools Support [ 27/Jul/13 10:42 AM ]
Some excerpt from the HANGANALYZE trace:
Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (opusdata.opusdata)
                   os id: 25465
              process id: 256, oracle@<hostname>
              session id: 39
        session serial #: 61345
    }
    is waiting for 'library cache lock' with wait info:
    {
                      p1: 'handle address'=0x22038dff68
                      p2: 'lock address'=0x21ef361978
                      p3: '100*mode+namespace'=0x520002
            time in wait: 5 min 33 sec
           timeout after: never
                 wait id: 5128
                blocking: 0 sessions
            wait history:
              * time between current wait and wait #1: 0.001507 sec
              1.       event: 'SQL*Net message from client'
                 time waited: 0.003166 sec
                     wait id: 5127            p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #1 and #2: 0.000002 sec
              2.       event: 'SQL*Net message to client'
                 time waited: 0.000002 sec
                     wait id: 5126            p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
              * time between wait #2 and #3: 0.000011 sec
              3.       event: 'SQL*Net message from client'
                 time waited: 0.003906 sec
                     wait id: 5125            p1: 'driver id'=0x54435000
                                              p2: '#bytes'=0x1
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (opusdata.opusdata)
                   os id: 22379
              process id: 500, oracle@<hostname>
              session id: 8008
        session serial #: 62080
    }
    which is waiting for 'cursor: mutex X' with wait info:
    {
                      p1: 'idn'=0xd4d88873
                      p2: 'value'=0x1
                      p3: 'where'=0x400000000
            time in wait: 0.000000 sec
      heur. time in wait: 1 min 3 sec
           timeout after: never
                 wait id: 7092018
                blocking: 426 sessions
            wait history:
              * time between current wait and wait #1: 0.000007 sec
              1.       event: 'cursor: mutex X'
                 time waited: 0.000002 sec
                     wait id: 7092017         p1: 'idn'=0xd4d88873
                                              p2: 'value'=0x1
                                              p3: 'where'=0x400000000
              * time between wait #1 and #2: 0.000009 sec
              2.       event: 'cursor: mutex X'
                 time waited: 0.000002 sec
                     wait id: 7092016         p1: 'idn'=0xd4d88873
                                              p2: 'value'=0x1
                                              p3: 'where'=0x400000000
              * time between wait #2 and #3: 0.000007 sec
              3.       event: 'cursor: mutex X'
                 time waited: 0.000003 sec
                     wait id: 7092015         p1: 'idn'=0xd4d88873
                                              p2: 'value'=0x1
                                              p3: 'where'=0x400000000
    }
 
Chain 1 Signature: 'cursor: mutex X'<='library cache lock'
Chain 1 Signature Hash: 0xfbcb6c60
.....
              process id: 3136, oracle@<hostname>
.....
    is waiting for 'library cache lock' with wait info:
.....
    and is blocked by 'instance: 1, os id: 22379, session id: 8008',

There are many other sessions waiting on library cache lock in the trace. And, they are blocked by SID#8008 which is waiting on cursor: mutex X. SID#8008 blocks 426 sessions.

Comment by ubTools Support [ 27/Jul/13 01:03 PM ]
Unfortunately, the blocker session SID#8008 exited. But, a new blocker SID#7579 appeared. Some excerpt from its ERRORSTACK LEVEL 3 trace:
KGX Atomic Operation Log 3c6bb9388
       Mutex 22c1df2c18(7579, 0) idn d4d88873 oper EXCL
       Cursor Parent uid 7579 efd 15 whr 1 slp 0
       oper=OPERATION_DEFAULT pt1=0 pt2=0 pt3=0
       pt4=0 u41=0 stt=0
      KGX Atomic Operation Log 3c6bb93d8
       Mutex 22c1df2d30(0, 1) idn d4d88873 oper GET_EXCL
       hash table uid 7579 efd 15 whr 4 slp 36782
       oper=OPERATION_DEFAULT pt1=0 pt2=0 pt3=0
       pt4=0 u41=0 stt=0

Mutex IDN 0xd4d88873 is hold in EXCL mode at mutex address 0x22c1df2c18. The holder SID is 7579. The mutex type is Cursor Parent
The same mutex IDN is requested in EXCL(oper GET_EXCL) mode at mutex address 0x22c1df2d30 and waited. The mutex type is hash table
See Oracle note Understanding and Reading Systemstates (Doc ID 423153.1) for interpreting.

Waiting session holds the same mutex IDN in EXCL mode but in the different mutex address and the different mutex type. No other holder encountered in the SYSTEMSTATE trace.

Comment by ubTools Support [ 28/Jul/13 01:26 PM ]
Some excerpt from AWR:
Foreground Wait Events
.....
Event	Waits	%Time -outs	Total Wait Time (s)	Avg wait (ms)	Waits /txn	% DB time
.....
cursor: mutex X	8,066,619	0	835	0	138.17	0.21
.....
Mutex Sleep Summary

ordered by number of sleeps desc

Mutex Type	Location	Sleeps	Wait Time (ms)
hash table	kkshhcdel [KKSHBKLOC4]	8,061,510	0

The mutex sleep location is kkshhcdel [KKSHBKLOC4]. Nothing found about it in Metalink.

Comment by ubTools Support [ 28/Jul/13 05:33 PM ]
Workaround:

Change the SQL text.

Comment by ubTools Support [ 28/Jul/13 05:36 PM ]
The customer will open an SR to Oracle Support. I'll update this issue later with SR result.




Generated at Fri Mar 29 12:53:49 UTC 2024 using JIRA Standard Edition, Version: 3.12.3-#302.