Hi Guys
We are having a datagaurd （1 master 2 standbys ）.
Recently we found that there is high current disk queue length on Standby1 server, I want to check if this is due to oracle process.
Then I create a statspack and found the top wait event is library cache lock.
Also, I found on trace log there are lots of dead lock of SYS._NEXT_OBJECT.
I suspect the dead lock is the cause of the library cache lock wait and high current disk queue length as well, but donn't know how to deal with the dead lock. Could you guys help to give some advises?
master:
log_archive_dest_1 string LOCATION=D:\ORADATA\xxxx_archive_log_bak VALID_FOR=(ALL_LOGFILES,ALL_ROLES) DB_UNIQUE_NAME=xxxx
log_archive_dest_2 SERVICE="xxxx1" LGWR SYNC AFFIRM delay=0 optional compression=disable max_failure=0 max_connections=1 reopen=300 db_unique_name="xxxx1" net_timeout=30 valid_for=(all_logfiles,primary_role)
log_archive_dest_3 string service=xxxx2 async valid_for=(online_logfile, primary_role) db_unique_name=xxxx2
statspack:
STATSPACK Statistics Report for Physical Standby
Database
~~~~~~~~
DB Unique Name Instance Startup Time Release RAC
------------------------------ ------------ --------------- ----------- ---
xxxx xxxx 09-Sep-16 20:28 11.2.0.4.0 NO
Host Name: xx-xxx-02 Num CPUs: 24 Phys Memory (MB): 65,346
~~~~
Snapshot Snap Id Snap Time Sessions Curs/Sess Comment
~~~~~~~~ ---------- ------------------ -------- --------- -------------------
Begin Snap: 1 28-Dec-16 17:59:12 237 1.9
End Snap: 2 28-Dec-16 18:06:22 241 1.2
Elapsed: 7.17 (mins)
Cache Sizes Begin End
~~~~~~~~~~~ ---------- ----------
Buffer Cache: 10,688M Std Block Size: 8K
Shared Pool: 5,312M Log Buffer: 9,344K
Load Profile Total Per Second
~~~~~~~~~~~~ ------------------ -----------------
DB time(s): 885.9 2.1
DB CPU(s): 293.9 0.7
Redo MB applied: 553.0 1.3
Logical reads: 20,759,877.0 48,278.8
Physical reads: 2,719,093.0 6,323.5
Physical writes: 114,500.0 266.3
User calls: 187,390.0 435.8
Parses: 25,080.0 58.3
Hard parses: 305.0 0.7
W/A MB processed: 462.5 1.1
Logons: 78.0 0.2
Executes: 64,973.0 151.1
Rollbacks: 130.0 0.3
Instance Efficiency Indicators
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %:
Buffer Hit %: 99.62 Optimal W/A Exec %: 100.00
Library Hit %: 97.89 Soft Parse %: 98.78
Execute to Parse %: 61.40 Latch Hit %: 97.41
Parse CPU to Parse Elapsd %: 61.58 % Non-Parse CPU: 99.25
Shared Pool Statistics Begin End
------ ------
Memory Usage %: 86.35 86.32
% SQL with executions>1: 80.81 80.97
% Memory for SQL w/exec>1: 80.85 80.95
Top 5 Timed Events Avg %Total
~~~~~~~~~~~~~~~~~~ wait Call
Event Waits Time (s) (ms) Time
----------------------------------------- ------------ ----------- ------ ------
library cache lock 80 1,059 13238 38.6
CPU time 281 10.2
direct path read 13,984 253 18 9.2
db file parallel write 16,217 248 15 9.1
RFS random i/o 6,214 219 35 8.0
-------------------------------------------------------------
Host CPU (CPUs: 24)
~~~~~~~~ Load Average
Begin End User System Idle WIO WCPU
------- ------- ------- ------- ------- ------- --------
2.94 0.67 96.40
Instance CPU
~~~~~~~~~~~~
% of total CPU for Instance: 3.03
% of busy CPU for Instance: 84.13
%DB time waiting for CPU - Resource Mgr:
Memory Statistics Begin End
~~~~~~~~~~~~~~~~~ ------------ ------------
Host Mem (MB): 65,346.2 65,346.2
SGA use (MB): 25,931.7 25,931.7
PGA use (MB): 1,475.5 1,471.3
% Host Mem used for SGA+PGA: 41.9 41.9
-------------------------------------------------------------
Recovery Progress Stats DB/Inst: xxxx/xxxx End Snap: 2
-> End Snapshot Time: 28-Dec-16 18:06:22
-> ordered by Recovery Start Time desc, Units, Item asc
Recovery Start Time Item Sofar Units Redo Timestamp
------------------- ----------------- -------------- ------- ------------------
09-Sep-16 20:32:36 Log Files 6,842 Files
09-Sep-16 20:32:36 Active Apply Rate 237 KB/sec
09-Sep-16 20:32:36 Average Apply Rat 110 KB/sec
09-Sep-16 20:32:36 Maximum Apply Rat 9,943 KB/sec
09-Sep-16 20:32:36 Redo Applied 1,028,935 Megabyt
09-Sep-16 20:32:36 Last Applied Redo 0 SCN+Tim 28-Dec-16 18:06:27
09-Sep-16 20:32:36 Active Time 4,196,301 Seconds
09-Sep-16 20:32:36 Apply Time per Lo 611 Seconds
09-Sep-16 20:32:36 Checkpoint Time p 1 Seconds
09-Sep-16 20:32:36 Elapsed Time 9,495,230 Seconds
09-Sep-16 20:32:36 Standby Apply Lag 0 Seconds
-------------------------------------------------------------
Time Model System Stats DB/Inst: xxxx/xxxx Snaps: 1-2
-> Ordered by % of DB time desc, Statistic name
Statistic Time (s) % DB time
----------------------------------- -------------------- ---------
sql execute elapsed time 594.7 67.1
DB CPU 293.9 33.2
parse time elapsed 4.4 .5
hard parse elapsed time 2.7 .3
PL/SQL execution elapsed time 0.9 .1
connection management call elapsed 0.2 .0
hard parse (sharing criteria) elaps 0.0 .0
repeated bind elapsed time 0.0 .0
failed parse elapsed time 0.0 .0
DB time 885.9
background elapsed time 2,033.8
background cpu time 13.9
-------------------------------------------------------------
Wait Events DB/Inst: xxxx/xxxx Snaps: 1-2
-> s - second, cs - centisecond, ms - millisecond, us - microsecond
-> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
-> Only events with Total Wait Time (s) >= .001 are shown
-> ordered by Total Wait Time desc, Waits desc (idle events last)
Avg
%Time Total Wait wait
Event Waits -outs Time (s) (ms)
---------------------------------------- ------------ ------ ---------- ------
library cache lock 80 0 1,059 13238
direct path read 13,984 0 253 18
db file parallel write 16,217 0 248 15
RFS random i/o 6,214 0 219 35
Disk file operations I/O 6,707 0 138 21
checkpoint completed 426 0 110 259
control file sequential read 43,950 0 106 2
flashback log file write 667 0 102 153
recovery read 3,058 0 52 17
log file sequential read 15,570 0 51 3
control file parallel write 669 0 47 70
db file sequential read 1,504 0 27 18
enq: CF - contention 70 0 20 293
buffer busy waits 20 0 14 699
enq: KO - fast object checkpoint 25 0 7 264
reliable message 61 0 1 21
flashback log switch 2 0 1 523
db file async I/O submit 871 0 1 1
RFS write 7,625 0 1 0
SQL*Net message from dblink 1,108 0 1 1
read by other session 41 0 1 18
log file single write 9 0 1 70
direct path write 10 0 1 50
rdbms ipc reply 3 0 0 117
RFS dispatch 7,639 0 0 0
flashback log file read 16 0 0 14
parallel recovery read buffer free 26 73 0 8
SQL*Net more data to client 5,509 0 0 0
SQL*Net break/reset to client 18 0 0 8
db file single write 3 0 0 42
db file parallel read 2 0 0 60
flashback log file sync 3 0 0 34
RFS ping 7 0 0 4
RFS create 3 0 0 8
os thread startup 1 0 0 8
latch: checkpoint queue latch 26 0 0 0
latch: row cache objects 143 0 0 0
latch: cache buffers chains 116 0 0 0
SQL*Net message to dblink 1,108 0 0 0
RFS close 3 0 0 1
SQL*Net message from client 164,444 0 121,707 740
parallel recovery slave next change 642,224 100 10,002 16
EMON slave idle wait 251 100 1,067 4250
DIAG idle wait 839 100 845 1007
shared server idle wait 15 100 450 30015
Streams AQ: emn coordinator idle wait 42 100 421 10015
class slave wait 391 97 383 979
parallel recovery control message reply 5,935 8 130 22
MRP redo arrival 807 0 40 50
SQL*Net more data from client 8,573 0 11 1
deadlock trace log:
*** 2017-01-03 16:17:48.944
A deadlock among DDL and parse locks is detected.
This deadlock is usually due to user errors in
the design of an application or from issuing a set
of concurrent statements which can cause a deadlock.
This should not be reported to Oracle Support.
The following information may aid in finding
the errors which cause the deadlock:
ORA-04020: deadlock detected while trying to lock object SYS._NEXT_OBJECT
--------------------------------------------------------
object waiting waiting blocking blocking
handle session lock mode session lock mode
-------- -------- -------- ---- -------- -------- ----
00007FFC4FE607B8 00007FFC317BCC28 00007FFC479CC350 X 00007FFC317BCC28 00007FFC47F05F20 X
--------------------------------------------------------
---------- DUMP OF WAITING AND BLOCKING LOCKS ----------
--------------------------------------------------------
------------- WAITING LOCK -------------
----------------------------------------
SO: 0x00007FFC479CC350, type: 78, owner: 0x00007FFC298AC478, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x00007FFC34CF4050, name=LIBRARY OBJECT LOCK, file=kgl.h LINE:8751, pg=0
LibraryObjectLock: Address=00007FFC479CC350 Handle=00007FFC4FE607B8 RequestMode=X CanBeBrokenCount=2325 Incarnation=2325 ExecutionCount=0
User=00007FFC317BCC28 Session=00007FFC317BCC28 ReferenceCount=0 Flags=BRO/[0000] SavepointNum=8907ec
LibraryHandle: Address=00007FFC4FE607B8 Hash=a9f32132 LockMode=X PinMode=0 LoadLockMode=0 Status=0
ObjectName: Name=SYS._NEXT_OBJECT
FullHashValue=ab04aaf45fdf00ce763962dda9f32132 Namespace=TABLE/PROCEDURE(01) Type=CURSOR(00) Identifier=1 OwnerIdn=0
Statistics: InvalidationCount=0 ExecutionCount=0 LoadCount=0 ActiveLocks=1 TotalLockCount=1 TotalPinCount=0
Counters: BrokenCount=2326 RevocablePointer=2326 KeepDependency=0 Version=0 BucketInUse=27684 HandleInUse=27684 HandleReferenceCount=0
Concurrency: DependencyMutex=00007FFC4FE60868(0, 0, 0, 0) Mutex=00007FFC4FE608F8(0, 57890580, 1754, 0)
Flags=RON/PIN/TIM/[00012801]
WaitersLists:
Lock=00007FFC4FE60848[00007FFC479CC3C0,00007FF89A5B5E20]
Pin=00007FFC4FE60828[00007FFC4FE60828,00007FFC4FE60828]
LoadLock=00007FFC4FE608A0[00007FFC4FE608A0,00007FFC4FE608A0]
Timestamp: Current=03-30-2010 10:07:48
HandleReference: Address=00007FFC4FE60970 Handle=00007FFC4BF937A0 Flags=OWN[200] ------------- BLOCKING LOCK ------------
----------------------------------------
SO: 0x00007FFC47F05F20, type: 78, owner: 0x00007FFC298AC478, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0x00007FFC34CF4050, name=LIBRARY OBJECT LOCK, file=kgl.h LINE:8751, pg=0
LibraryObjectLock: Address=00007FFC47F05F20 Handle=00007FFC4FE607B8 Mode=X CanBeBrokenCount=1 Incarnation=1 ExecutionCount=0
User=00007FFC317BCC28 Session=00007FFC317BCC28 ReferenceCount=1 Flags=CNB/[0001] SavepointNum=ca9
LibraryHandle: Address=00007FFC4FE607B8 Hash=a9f32132 LockMode=X PinMode=0 LoadLockMode=0 Status=0
ObjectName: Name=SYS._NEXT_OBJECT
FullHashValue=ab04aaf45fdf00ce763962dda9f32132 Namespace=TABLE/PROCEDURE(01) Type=CURSOR(00) Identifier=1 OwnerIdn=0
Statistics: InvalidationCount=0 ExecutionCount=0 LoadCount=0 ActiveLocks=1 TotalLockCount=1 TotalPinCount=0
Counters: BrokenCount=2326 RevocablePointer=2326 KeepDependency=0 Version=0 BucketInUse=27684 HandleInUse=27684 HandleReferenceCount=0
Concurrency: DependencyMutex=00007FFC4FE60868(0, 0, 0, 0) Mutex=00007FFC4FE608F8(0, 57890580, 1754, 0)
Flags=RON/PIN/TIM/[00012801]
WaitersLists:
Lock=00007FFC4FE60848[00007FFC479CC3C0,00007FF89A5B5E20]
Pin=00007FFC4FE60828[00007FFC4FE60828,00007FFC4FE60828]
LoadLock=00007FFC4FE608A0[00007FFC4FE608A0,00007FFC4FE608A0]
Timestamp: Current=03-30-2010 10:07:48
HandleReference: Address=00007FFC4FE60970 Handle=00007FFC4BF937A0 Flags=OWN[200] --------------------------------------------------------
This lock request was aborted.
kpoaqsnj: error 4020 occured: jobs=0