History | Log In     View a printable version of the current page.  
   HOME       BROWSE PROJECT       FIND ISSUES   
    QUICK SEARCH:  
Issue Details (XML | Word | Printable)

Key: QA-56
Type: Oracle - Database Tuning Oracle - Database Tuning
Status: Closed Closed
Resolution: Answered
Priority: Major Major
Assignee: ubTools Support
Reporter: ubTools Support
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
Questions & Answers

"cursor: mutex X"

Created: 27/Jul/13 10:25 AM   Updated: 07/Mar/25 08:18 AM
Fix Version/s: None

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


 Description  « Hide
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


 All   Comments   Change History      Sort Order: Ascending order - Click to sort in descending order
[ Permlink | « Hide ]
ubTools Support - 27/Jul/13 10:42 AM - edited
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.


[ Permlink | « Hide ]
ubTools Support - 27/Jul/13 01:03 PM - edited
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.


Change by ubTools Support - 27/Jul/13 01:56 PM
Field Original Value New Value
Comment [ The next step is to search Mutex 22c1df2d30 in SYSTEMSTATE trace to find the blocker. ]

[ Permlink | « Hide ]
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.


Change by ubTools Support - 28/Jul/13 03:57 PM
Comment [ An excerpt from ERRORSTACK LEVEL3 3 trace of SID#2413:

{noformat}
      KGX Atomic Operation Log 220b3014f8
       Mutex 22c1df2c18(2413, 0) idn d4d88873 oper EXCL
       Cursor Parent uid 2413 efd 5 whr 1 slp 0
       oper=OPERATION_DEFAULT pt1=0 pt2=0 pt3=0
       pt4=0 u41=0 stt=0
      KGX Atomic Operation Log 220b301548
       Mutex 22c1df2d30(0, 1) idn d4d88873 oper GET_EXCL
       hash table uid 2413 efd 5 whr 4 slp 36444
       oper=OPERATION_DEFAULT pt1=22bcfe1bc8 pt2=22bcfe1f80 pt3=22bcfe1ba8
       pt4=0 u41=0 stt=0
{noformat}

It is the same mutex 0x22c1df2d30(oper GET_EXCL) is requested in EXCL mode for IDN 0xd4d88873.
]

Change by ubTools Support - 28/Jul/13 03:57 PM
Comment [ The customer reproduced the problem next day by running the original SQL.

An excerpt from HANGANALYZE LEVEL3 trace:

{noformat}
    Oracle session identified by:
    {
                instance: 1 (opusdata.opusdata)
                   os id: 14155
              process id: 527, oracle@allianzsun21
              session id: 2413
        session serial #: 18262
    }
    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: 8 min 49 sec
           timeout after: never
                 wait id: 4724362
                blocking: 0 sessions
             current sql: <originalSQLText>
             short stack: ksedsts()+380<-ksdxfstk()+52<-ksdxcb()+3524<-sspuser()+140<-__sighndlr()+12<-
call_user_handler()+992<-sigacthandler()+104<-__pollsys()+8<-_pollsys()+260<-_pselect()+496<-_select()+160<-
skgpwwait()+664<-ksliwat()+1752<-kslwaitctx()+144<-kgxWait()+484<-kgxExclusive()+308<-kkshhcdel()+276<-
kksfbc()+6244<-kkspsc0()+1320<-kksParseCursor()+100<-opiosq0()+1904<-kpooprx()+212<-kpoal8()+536<-
opiodr()+1164<-ttcpip()+916<-opitsk()+1640<-opiino()+924<-opiodr()+1164<-opidrv()+1032<-sou2o()+88<-
opimai_real()+504<-ssthrdmain()+3
            wait history:
              * time between current wait and wait #1: 0.000007 sec
              1. event: 'cursor: mutex X'
                 time waited: 0.000003 sec
                     wait id: 4724361 p1: 'idn'=0xd4d88873
                                              p2: 'value'=0x1
                                              p3: 'where'=0x400000000
              * time between wait #1 and #2: 0.000008 sec
              2. event: 'cursor: mutex X'
                 time waited: 0.000003 sec
                     wait id: 4724360 p1: 'idn'=0xd4d88873
                                              p2: 'value'=0x1
                                              p3: 'where'=0x400000000
              * time between wait #2 and #3: 0.000006 sec
              3. event: 'cursor: mutex X'
                 time waited: 0.000003 sec
                     wait id: 4724359 p1: 'idn'=0xd4d88873
                                              p2: 'value'=0x1
                                              p3: 'where'=0x400000000
    }
 
Chain 12 Signature: 'cursor: mutex X'
Chain 12 Signature Hash: 0xad67b469
{noformat}
 
As seen above, the original SQL waited again although the original SQL text has been replaced with a new SQL text yesterday. ]

Change by ubTools Support - 28/Jul/13 04:05 PM
Comment [ *Workaround:*

Change the SQL text of SQL waiting for _cursor: mutex X_. The SQL text is available in the ERRORSTACK trace.
]

Change by ubTools Support - 28/Jul/13 04:42 PM
Summary Self lock on "cursor: mutex X" "cursor: mutex X"
Description The customer has upgraded from Oracle 10.2.0.5 to Oracle 11.2.0.3.7. The encountered _library cache lock_ problem.

Some excerpt from the AWR:

{noformat}
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
{noformat}


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:

{noformat}
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
{noformat}



[ Permlink | « Hide ]
ubTools Support - 28/Jul/13 05:33 PM
Workaround:

Change the SQL text.


[ Permlink | « Hide ]
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.

Change by ubTools Support - 07/Mar/25 08:18 AM
Status Open [ 1 ] Closed [ 6 ]
Resolution Answered [ 10 ]


Powered by Atlassian JIRA the Professional Issue Tracker. (Standard Edition, Version: 3.12.3-#302) - Bug/feature request - Atlassian news - Contact Administrators