library cache: mutex X
lcmx is an event which occur due to shared pool contention in SGA.
Shared pool is used to share the SQL area to be reused by multiple cursors. Every objects in shared pool are interrelated.
In order to understand any shared pool events, it is a prerequisite to understand CURSOR
cursor is an object in programming world to allocate a connection or pipeline to execute SQL queries or PLSQL. cursor can be used to create a connection, execute, fetch, pin, invalidate and reload etc.
To get an idea on the cursor, below example demonstrates a practical example,
Number of parse calls increase for sql statement as per the individual parameter or setting.
Child number increase as per the different settings used to execute the same sql.
kIsH@STAX<>alter session set "_hash_join_enabled"=false;
Session altered.
kIsH@STAX<>select count(*) from xtbl;
COUNT(*)
----------
1000000
kIsH@STAX<>alter session set "_hash_join_enabled"=true;
Session altered.
kIsH@STAX<>select count(*) from xtbl;
COUNT(*)
----------
1000000
kIsH@STAX<>SELECT sql_id from v$sql where sql_text like '%select count(*) from xtbl%';
SQL_ID
-------------
fmhv6xyq0tzg6
fmhv6xyq0tzg6
kIsH@STAX<>set lines 200 pages 1000
kIsH@STAX<>SELECT SQL_ID,VERSION_COUNT,LOADED_VERSIONS,LOADS,INVALIDATIONS,PARSE_CALLS from v$sqlarea WHERE sql_id='fmhv6xyq0tzg6';
SQL_ID VERSION_COUNT LOADED_VERSIONS LOADS INVALIDATIONS PARSE_CALLS
------------- ------------- --------------- ---------- ------------- -----------
fmhv6xyq0tzg6 2 2 2 0 2
kIsH@STAX<>SELECT SQL_ID,CHILD_NUMBER,LOADED_VERSIONS,LOADS,INVALIDATIONS,PARSE_CALLS from v$sql WHERE sql_id='fmhv6xyq0tzg6';
SQL_ID CHILD_NUMBER LOADED_VERSIONS LOADS INVALIDATIONS PARSE_CALLS
------------- ------------ --------------- ---------- ------------- -----------
fmhv6xyq0tzg6 0 1 1 0 1
fmhv6xyq0tzg6 1 1 1 0 1
kIsH@STAX<>alter session set optimizer_mode=first_rows;
Session altered.
kIsH@STAX<>select count(*) from xtbl;
COUNT(*)
----------
1000000
kIsH@STAX<>SELECT SQL_ID,CHILD_NUMBER,LOADED_VERSIONS,LOADS,INVALIDATIONS,PARSE_CALLS from v$sql WHERE sql_id='fmhv6xyq0tzg6';
SQL_ID CHILD_NUMBER LOADED_VERSIONS LOADS INVALIDATIONS PARSE_CALLS
------------- ------------ --------------- ---------- ------------- -----------
fmhv6xyq0tzg6 0 1 1 0 1
fmhv6xyq0tzg6 1 1 1 0 1
fmhv6xyq0tzg6 2 1 1 0 1
Example: Consider table X. This table has a column c. There are millions of rows r in X.
If there is a maintenance activity on column c. If c is either dropped or existing attributes are modified for the column, then all relational objects become invalid and SQL statements which rely on the column data are affected. When the cursor become invalid, they need to be recompiled and reloaded into the shared pool again which has to go through latch, pin and locks. Cursor should be compiled to make the object valid. During compilation process, the cursor is pinned and locked to prevent other process from modifying them which further leads to cursor pin events, if the process holds the lock for long time. Thus, concurrency is maintained.
https://alphaoragroup.com/?p=18617
Primary reason for lcmx is inefficient parsing of sql statements
- Hard parse
- High number of Child cursors
- Cursor Invalidations
- Cursor Recompilation and Reloads
WHO PGM W_CHAINS SQL_ID TOTAL CHART_WCLASS STATE TAASH IAAS
------- ----- ---------------------------------------- ------------- ---------- -------------------- ---------- ------ ----------
SYS TNS V library cache: mutex X 11c4s0a35j48v 1506123 c/_\c/_\c/_\c/_\c/_ LONG_WAIT 20 .000077683
1-V3 \c/_\c/_\c/_\c/_\c/_
\c/_\c/_\c/_\c/_\c/_
\c/_\c/_\c/_\c/_\c/_
\c/_\c/_\c/_\c/_\c/_
\c/_\c/_\c/_\c/_\c/_
\c/_\c/_\c/_\c/_\c/_
\c/_\c/_\c
SYS TNS V latch free 11c4s0a35j48v 1329348 OOOOOOOOOOOOOOOOOOO LONG_WAIT 20 .000088013
1-V3 OOOOOOOOOOOOOOOOOOOO
OOOOOOOOOOOOOOOOOOOO
OOOOOOOOOOOOOOOOOOOO
OOOOOOOOOOOOOOOOOOOO
OOOOOOOOOOOOOOOOOOOO
OOOOOOOOOOOO
SYS TNS V library cache: mutex X 766025 c/_\c/_\c/_\c/_\c/_ LONG_WAIT 20 .000152737
1-V3 \c/_\c/_\c/_\c/_\c/_
\c/_\c/_\c/_\c/_\c/_
\c/_\c/_\c/_\c/_
SYS TNS V On CPU 11c4s0a35j48v 476114 ################### BURN_CPU 20 .000245739
1-V3 ####################
#######
SYS TNS V |latch free [|]<~~~ latch free| 11c4s0a35j48v 391262 OOOOOOOOOOOOOOOOOOO LONG_WAIT 20 .000299032
1-V3 OOOOOOOOOOOOOOOOOOO
SYS TNS V On CPU d8dxvkk7hxvq0 353550 ################### BURN_CPU 20 .000330929
1-V3 ###############
6 rows selected.
kIsH@STAX<>alter session set tracefile_identifier='lbm1';
Session altered.
kIsH@STAX<>alter session set events 'immediate trace name library_cache level 12';
Session altered.
kIsH@STAX<>select count(*) from kish.xtbl;
COUNT(*)
----------
1000000
kIsH@STAX<>alter session set "_hash_join_enabled"=false;
Session altered.
kIsH@STAX<>select count(*) from kish.xtbl;
COUNT(*)
----------
1000000
kIsH@STAX<>alter session set events 'immediate trace name library_cache off';
Session altered.
Bucket: #=69360 Mutex=0x764078a8(777389080576, 6, 0, 6)
LibraryHandle: Address=0x6cd99550 Hash=3970ef0 LockMode=0 PinMode=0 LoadLockMode=0 Status=VALD Subpool=1
ObjectName: Name=CDB$ROOT.KISH.XTBL
FullHashValue=e2ae0aa2266ca38b5dd42deb03970ef0 Namespace=TABLE/PROCEDURE(01) Type=TABLE(02) ContainerId=1 ContainerUid=1 Identifier=74650 OwnerIdn=108
Statistics: InvalidationCount=0 ExecutionCount=0 LoadCount=1 ActiveLocks=0 TotalLockCount=4 TotalPinCount=4
Counters: BrokenCount=1 RevocablePointer=1 KeepDependency=0 Version=0 BucketInUse=1 HandleInUse=1 HandleReferenceCount=0
Concurrency: DependencyMutex=0x6cd99600(0, 2, 0, 0) Mutex=0x6cd996a0(181, 47, 0, 6)
Flags=PIN/TIM/[00002801] Flags2=[0000]
WaitersLists:
Lock=0x6cd995e0[0x6cd995e0,0x6cd995e0]
Pin=0x6cd995c0[0x6cd995c0,0x6cd995c0]
LoadLock=0x6cd99638[0x6cd99638,0x6cd99638]
Timestamp: Current=12-14-2022 17:26:06
HandleReference: Address=0x6cd99720 Handle=0x6cd662f8 Flags=OWN[200]
ReferenceList:
Reference: Address=0x6bef89b8 Handle=0x6c650728 Flags=DEP[01]
Timestamp=12-14-2022 17:26:06 InvalidatedFrom=0
Reference: Address=0x76e4f428 Handle=0x6cdc58b0 Flags=DEP[01]
Timestamp=12-14-2022 17:26:06 InvalidatedFrom=0
LibraryObject: Address=0x74631438 HeapMask=0000-0701-0701-0000 Flags=EXS/LOC[0004] Flags2=/CSO[8000000] Flags3=/DVC[0020] PublicFlags=[0000]
DataBlocks:
Block: #='0' name=KGLH0^3970ef0 pins=0 Change=NONE
Heap=0x6ccd8ff8 Pointer=0x74631518 Extent=0x74631378 Flags=I/-/-/A/-/-/-
FreedLocation=0 Alloc=1.531250 Size=3.976562 LoadTime=01-24-2023 15:35:43
Block: #='8' name=KGLS^3970ef0 pins=0 Change=NONE
Heap=0x74631810 Pointer=0x6a0d9440 Extent=0x6a0d8760 Flags=I/-/-/A/-/-/-
FreedLocation=0 Alloc=5.078125 Size=7.898438 LoadTime=01-24-2023 15:35:43
Block: #='9' name=KGLS^3970ef0 pins=0 Change=NONE
Heap=0x74631968 Pointer=0x6a0d7590 Extent=0x6a0d6760 Flags=I/-/-/A/-/-/-
FreedLocation=0 Alloc=0.429688 Size=3.937500 LoadTime=01-24-2023 15:35:43
Block: #='10' name=KGLS^3970ef0 pins=0 Change=NONE
Heap=0x74631a00 Pointer=0x6a0d6670 Extent=0x6a0d5760 Flags=I/-/-/A/-/-/-
FreedLocation=0 Alloc=4.601562 Size=7.898438 LoadTime=01-24-2023 15:35:43
Bucket: #=99385 Mutex=0x7652d370(777389080576, 9, 0, 6)
LibraryHandle: Address=0x6f53e270 Hash=73218439 LockMode=0 PinMode=0 LoadLockMode=0 Status=VALD Subpool=1
ObjectName: Name=select count(*) from kish.xtbl
FullHashValue=175ea436befe4c3153afc49073218439 Namespace=SQL AREA(00) Type=CURSOR(00) ContainerId=1 ContainerUid=1 Identifier=1931576377 OwnerIdn=0
Statistics: InvalidationCount=0 ExecutionCount=4 LoadCount=3 ActiveLocks=0 TotalLockCount=4 TotalPinCount=1
Counters: BrokenCount=1 RevocablePointer=1 KeepDependency=2 Version=0 BucketInUse=3 HandleInUse=3 HandleReferenceCount=0
Concurrency: DependencyMutex=0x6f53e320(0, 2, 0, 0) Mutex=0x6f53e3c0(181, 50, 0, 6)
Flags=RON/PIN/TIM/PN0/DBN/[10012841] Flags2=[0000]
WaitersLists:
Lock=0x6f53e300[0x6f53e300,0x6f53e300]
Pin=0x6f53e2e0[0x6f53e2e0,0x6f53e2e0]
LoadLock=0x6f53e358[0x6f53e358,0x6f53e358]
Timestamp: Current=01-24-2023 21:05:43
HandleReference: Address=0x6f53e450 Handle=(nil) Flags=[00]
ReferenceList:
Reference: Address=0x6bef7670 Handle=0x6c650300 Flags=ROD[21]
Reference: Address=0x7463ac68 Handle=0x6cd99978 Flags=ROD[21]
LibraryObject: Address=0x75f46708 HeapMask=0000-0001-0001-0000 Flags=EXS[0000] Flags2=[0000] Flags3=[0000] PublicFlags=[0000]
DataBlocks:
Block: #='0' name=KGLH0^73218439 pins=0 Change=NONE
Heap=0x6f27f0e0 Pointer=0x75f467e8 Extent=0x75f46648 Flags=I/-/P/A/-/-/-
FreedLocation=0 Alloc=5.445312 Size=7.953125 LoadTime=01-24-2023 15:35:43
ChildTable: size='16'
Child: id='0' Table=0x75f47570 Reference=0x75f47108 Handle=0x6cdc58b0
Child: id='1' Table=0x75f47570 Reference=0x6bef9768 Handle=0x6c650728
NamespaceDump:
Parent Cursor: sql_id=57by4k1tk311t parent=0x75f467e8 maxchild=2 plk=n ppn=n prsfcnt=0 obscnt=0
CursorDiagnosticsNodes:
ChildNode: ChildNumber=1 ID=3 reason=Optimizer mismatch(12) size=2x476 _hash_join_enabled= false true
ChildNode: ChildNumber=0 ID=3 reason=Optimizer mismatch(12) size=2x476 _hash_join_enabled= true false KGLH0 is a heap object which is connected to the Shared Pool’s SQL Area. KGLH0 is used by each child cursor.
When there are many of child cursors and the parent cursor is not shared, large allocation in KGLH0 can happen.
sqlplus /nolog
connect / as sysdba
oradebug setmypid
oradebug unlimit
oradebug dump heapdump 536870914
oradebug tracefile_name
oradebug close_trace
sqlplus /nolog
connect / as sysdba
alter system set events '10235 level 65536';
exit
Then wait a while for the ORA-4031 (or at least the memory allocations) to occur, and then execute:
sqlplus /nolog
connect / as sysdba
oradebug setmypid
oradebug unlimit
oradebug dump heapdump 536870914
oradebug tracefile_name
oradebug close_trace
once done you can disable the event using
alter system set events '10235 off';kIsH@STAX<>SELECT NAMESPACE,sum(GETS),sum(PINS),sum(RELOADS),sum(INVALIDATIONS) from dba_hist_librarycache GROUP BY NAMESPACE ORDER BY sum(GETS) DESC;
NAMESPACE SUM(GETS) SUM(PINS) SUM(RELOADS) SUM(INVALIDATIONS)
--------------- ---------- ---------- ------------ ------------------
SQL AREA 1359605 1810760712 5253 10401
TABLE/PROCEDURE 511634 902108609 2282 9
SCHEMA 247617 0 0 0
DBLINK 170599 0 0 0
BODY 164637 901113014 45 0
SQL AREA STATS 84322 84322 0 0
SQL AREA BUILD 83669 0 0 0
TRIGGER 62821 62821 0 0
EDITION 60946 60946 0 0
CLUSTER 23775 27501 0 0
INDEX 15179 12515 0 0
FED APP 5481 5481 0 0
CMP 2787 2787 0 0
OBJECT ID 2506 0 0 0
DIRECTORY 621 657 0 0
ACCOUNT_STATUS 549 0 0 0
APP STATE 324 0 0 0
PDB 270 0 0 0
QUEUE 255 345 0 0
PDBOPER 147 0 0 0
DBINSTANCE 90 0 0 0
SUBSCRIPTION 88 88 0 0
RULESET 45 135 0 0
USER PRIVILEGE 2 4 0 0
APP CONTEXT 2 4 0 0
XML SCHEMA 1 0 0 0
26 rows selected.
kIsH@STAX<>var x varchar2(10)
kIsH@STAX<>exec :x := 369
PL/SQL procedure successfully completed.
kIsH@STAX<>SELECT count(*) from t1 where N1=:x;
COUNT(*)
----------
1
kIsH@STAX<>select * from table(dbms_xplan.display_cursor());
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 93uqjw965fzpy, child number 0
-------------------------------------
SELECT count(*) from t1 where N1=:x
Plan hash value: 3724264953
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 3 (100)| |
| 1 | SORT AGGREGATE | | 1 | 3 | | |
|* 2 | TABLE ACCESS FULL| T1 | 1 | 3 | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("N1"=TO_NUMBER(:X))
19 rows selected.
kIsH@STAX<>var x varchar2(20)
kIsH@STAX<>exec :x := 369
PL/SQL procedure successfully completed.
kIsH@STAX<>SELECT count(*) from t1 where N1=:x;
COUNT(*)
----------
1
kIsH@STAX<>select * from table(dbms_xplan.display_cursor());
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID 93uqjw965fzpy, child number 0
-------------------------------------
SELECT count(*) from t1 where N1=:x
Plan hash value: 3724264953
---------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
---------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 3 (100)| |
| 1 | SORT AGGREGATE | | 1 | 3 | | |
|* 2 | TABLE ACCESS FULL| T1 | 1 | 3 | 3 (0)| 00:00:01 |
---------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("N1"=TO_NUMBER(:X))
19 rows selected.