RE: cursor: mutex S + library cache lock + library cache: mutex X = disaster
Date: Tue, 4 Nov 2014 19:17:41 -0800
Message-ID: <BLU179-W88D9F9A915A293C66ED67EB870_at_phx.gbl>
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.6Date: Tue, 4 Nov 2014 18:08:57 -0300
Subject: Re: cursor: mutex S + library cache lock + library cache: mutex X = disaster From: frasebook4_at_gmail.com
To: oracle-l_at_freelists.org
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_at_xxxxxx_at_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_at_xxxxxx_at_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_at_tanelpoder.com>: 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_at_tanelpoder.com> 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> _at_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'"
-- http://www.freelists.org/webpage/oracle-lReceived on Wed Nov 05 2014 - 04:17:41 CET