RE: cursor: mutex S + library cache lock + library cache: mutex X = disaster
- From: Iggy Fernandez <iggy_fernandez@xxxxxxxxxxx>
- To: "frasebook4@xxxxxxxxx" <frasebook4@xxxxxxxxx>, ORACLE-L <oracle-l@xxxxxxxxxxxxx>
- Date: Tue, 4 Nov 2014 19:17:41 -0800
Looks like you solved the mystery.
Your solution ties in nicely to one of the clues in the AWR report. "Connection
management call elapsed time" was 71.1% of DB time. That's the "Amount of
elapsed time spent performing session connect and disconnect calls"
(http://docs.oracle.com/cd/E11882_01/server.112/e40402/dynviews_3015.htm#REFRN30340)
Statistic Name Time (s)
% of DB Time------------------------------------------
------------------ ------------parse time elapsed
1,217,693.8 99.6connection management call elapsed time
868,991.0 71.1DB CPU
43,677.7 3.6
Date: Tue, 4 Nov 2014 18:08:57 -0300
Subject: Re: cursor: mutex S + library cache lock + library cache: mutex X =
disaster
From: frasebook4@xxxxxxxxx
To: oracle-l@xxxxxxxxxxxxx
First of all, thank you all for the invaluable help, i wouldn't have hit the
spot without it.
Well, I think i've stumbled upon this:
Database Hangs With Excessive Cursor Mutex S Waits Due to Sys.Aud$ Cursors (Doc
ID 1423386.1)
https://support.oracle.com/epmos/faces/DocumentDisplay?id=1423386.1&_adf.ctrl-state=g572lalmx_67&_afrLoop=317155210393324
As Mr. poder adviced, I run:
sys@xxxxxx@db01>@ash/dashtop event,top_level_call_name,sql_opname,p1text,p1
"(event like '%mutex%' or event like '%library%')" "TIMESTAMP'2014-11-01
15:30:00'" "TIMESTAMP'2014-11-01 16:30:00'"
%This EVENT TOP_LEVEL_CALL_NAME SQL_OPNAME P1TEXT
P1 TotalSeconds FIRST_SEEN LAST_SEEN------
-----------------------------------------------------------------------------------------------------------------------------------------------------88%
cursor: mutex S LOGOFF idn
1097020010 135070 2014-11-01 15:36:31 2014-11-01 16:21:3912%
library cache lock LOGOFF handle
address 14818538720 17790 2014-11-01 15:36:41 2014-11-01 16:21:39
0% library cache: mutex X LOGOFF idn
98868131 160 2014-11-01 16:20:59 2014-11-01 16:21:39
sys@xxxxxx@db01>SELECT * FROM v$db_object_cache WHERE hash_value = 1097020010;
==============================OWNER :NAME :
insert into sys.aud$( sessionid,entryid,statement,ntimestamp#,
userid,userhost,terminal,action#,returncode, logoff$lread,logoff$pread,
logoff$lwrite,logoff$dead,
logoff$time,comment$text,spare1,clientid,sessioncpu,proxy$sid,user$guid,
instance#,process#,auditid,dbid)
values(:1,:2,:3,SYS_EXTRACT_UTC(SYSTIMESTAMP), :4,:5,:6,:7,:8,
:9,:10,:11,:12, cast(SYS_EXTRACT_UTC(systimestamp) as date),
:13,:14,:15,:16,:17,:18, :19,:20,:21,:22)DB_LINK
:NAMESPACE : SQL AREATYPE : CURSORSHARABLE_MEM
: 40952LOADS : 1EXECUTIONS : 315LOCKS
: 0PINS : 0KEPT : NOCHILD_LATCH
: 0INVALIDATIONS : 0HASH_VALUE : 1097020010LOCK_MODE
: NONEPIN_MODE : NONESTATUS : VALIDTIMESTAMP
: 2014-11-01/16:35:59PREVIOUS_TIMESTAMP :LOCKED_TOTAL :
318PINNED_TOTAL : 637==============================
So it appears i have some patching to do.
I'd like to clarify, When I saw all kind of blockers and objects,I referred to
this information:
select sample_time,session_id,event,p1,blocking_session,current_obj#from
dba_hist_active_sess_history swhere sample_time between to_date('20141101
15:30:00','yyyymmdd hh24:mi:ss') and to_date('20141101 16:30:00','yyyymmdd
hh24:mi:ss')and event = 'cursor: mutex S'and
session_type='FOREGROUND'order by 1;
SAMPLE_TIME SESSION_ID EVENT P1
BLOCKING_SESSION
CURRENT_OBJ#---------------------------------------------------------------------------
---------- ----------------------------------------------------------------
---------- ---------------- ------------11/1/2014 3:36:31.946 PM 776
cursor: mutex S 1097020010 71 6257111/1/2014 3:36:51.986 PM 840
cursor: mutex S 1097020010 71 5676511/1/2014 3:36:51.986 PM 815
cursor: mutex S 1097020010 71 -111/1/2014 3:36:51.986 PM 719
cursor: mutex S 1097020010 479 -111/1/2014 3:36:51.986 PM 83
cursor: mutex S 1097020010 195 -111/1/2014 3:36:51.986 PM 584
cursor: mutex S 1097020010 535 -111/1/2014 3:36:51.986 PM 552
cursor: mutex S 1097020010 4 1826211/1/2014 3:36:51.986 PM 531
cursor: mutex S 1097020010 72 -111/1/2014 3:36:51.986 PM 526
cursor: mutex S 1097020010 362 -111/1/2014 3:36:51.986 PM 245
cursor: mutex S 1097020010 872 -111/1/2014 3:36:51.986 PM 880
cursor: mutex S 1097020010 362 -111/1/2014 3:36:51.986 PM 649
cursor: mutex S 1097020010 535 -111/1/2014 3:37:02.006 PM 700
cursor: mutex S 1097020010 840 -111/1/2014 3:37:02.006 PM 710
cursor: mutex S 1097020010 142 -111/1/2014 3:37:02.006 PM 649
cursor: mutex S 1097020010 142 -1(...)
But I think I was looking into the wrong information, And missing the important
one (p1)
If nobody has nothing else to say about this matter, I then thank you kindly.
Nico
2014-11-04 1:03 GMT-03:00 Tanel Poder <tanel@xxxxxxxxxxxxxx>:
Note that I had a bug in the dashtop.sql that I just fixed and I've reuploaded
the script here:
http://blog.tanelpoder.com/files/scripts/ash/dashtop.sql
-- Tanel PoderEnkitec (The Exadata Experts)Services | Training |
Troubleshooting | Exadata Book
On Mon, Nov 3, 2014 at 10:01 PM, Tanel Poder <tanel@xxxxxxxxxxxxxx> wrote:
You can look into ASH data from around your problem time - the P1 parameter for
cursor/mutex waits shows the library cache object hash value (or likely the
libcache hash bucket if it's less than 131072).
SQL> @ash/dashtop event,top_level_call_name,sql_opname,p1text,p1 "event like
'cursor%'" "TIMESTAMP'2014-11-03 00:40:05'" "TIMESTAMP'2014-11-03 21:41:05'"
Other related posts:
