Re: cursor: mutex S + library cache lock + library cache: mutex X = disaster
- From: nico torres <frasebook4@xxxxxxxxx>
- To: ORACLE-L <oracle-l@xxxxxxxxxxxxx>
- Date: Tue, 4 Nov 2014 18:08:57 -0300
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:39
12% 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 AREA
TYPE : CURSOR
SHARABLE_MEM : 40952
LOADS : 1
EXECUTIONS : 315
LOCKS : 0
PINS : 0
KEPT : NO
CHILD_LATCH : 0
INVALIDATIONS : 0
HASH_VALUE : 1097020010
LOCK_MODE : NONE
PIN_MODE : NONE
STATUS : VALID
TIMESTAMP : 2014-11-01/16:35:59
PREVIOUS_TIMESTAMP :
LOCKED_TOTAL : 318
PINNED_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 s
where 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 62571
11/1/2014 3:36:51.986 PM 840 cursor: mutex S 1097020010 71 56765
11/1/2014 3:36:51.986 PM 815 cursor: mutex S 1097020010 71 -1
11/1/2014 3:36:51.986 PM 719 cursor: mutex S 1097020010 479 -1
11/1/2014 3:36:51.986 PM 83 cursor: mutex S 1097020010 195 -1
11/1/2014 3:36:51.986 PM 584 cursor: mutex S 1097020010 535 -1
11/1/2014 3:36:51.986 PM 552 cursor: mutex S 1097020010 4 18262
11/1/2014 3:36:51.986 PM 531 cursor: mutex S 1097020010 72 -1
11/1/2014 3:36:51.986 PM 526 cursor: mutex S 1097020010 362 -1
11/1/2014 3:36:51.986 PM 245 cursor: mutex S 1097020010 872 -1
11/1/2014 3:36:51.986 PM 880 cursor: mutex S 1097020010 362 -1
11/1/2014 3:36:51.986 PM 649 cursor: mutex S 1097020010 535 -1
11/1/2014 3:37:02.006 PM 700 cursor: mutex S 1097020010 840 -1
11/1/2014 3:37:02.006 PM 710 cursor: mutex S 1097020010 142 -1
11/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 Poder*
> Enkitec (The Exadata Experts)
> Services <http://enkitec.com> | Training
> <http://blog.tanelpoder.com/seminar/> | Troubleshooting
> <http://blog.tanelpoder.com/> | Exadata Book
> <http://www.amazon.com/Expert-Oracle-Exadata-Apress/dp/1430233923>
>
>
> 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:
