Blog List

• July 2025 (2)
  
  1. "library cache: bucket mutex X" on V$ Fixed Views: Case Test
  1. Oracle dbms_hprof: Uncatchable Time in PL/SQL Nested Program Units
• June 2025 (1)
  
  1. ORA-01002: fetch out of sequence: One Case Test
• May 2025 (1)
  
  1. Oracle ORA-00600 [pfrsfm: stack mismatch] and [pfrsfm: stack mismatch] Reproducing
• February 2025 (1)
  
  1. One Oracle CLOB Space Usage Test
• November 2024 (1)
  
  1. Oracle Self-tune checkpointing lag of log switch
• October 2024 (1)
  
  1. Find the skipped rows in select for update skip locked
• September 2024 (1)
  
  1. One OracleJVM TIME_MODEL Test
• April 2024 (3)
  
  1. Oracle AQ Dequeue 'KTC latch subh' Memory Leak and Dequeue Long Running Test
  2. One Test of Oracle Object Collection MEMBER OF Function
  3. In Memoriam of Prof. Niklaus Wirth: One Email on Program Debugging
• January 2024 (1)
  
  1. One Test on the Different Errors of Oracle Global Temporary Tables vs. Private Temporary Tables
• October 2023 (1)
  
  1. ORA-28268: Exceeded the maximum allowed size for Context information in a session
• September 2023 (3)
  
  1. Oracle Index Root Modification CBC Latch Contention: Workaround Studies
  2. Oracle 19.18 Wait Event 'latch: cache buffers chains' P3: block number
  3. Oracle Index Range Scan with LIKE Condition on Wildcard '_'
• August 2023 (1)
  
  1. Oracle SYS_GUID Composition
• June 2023 (1)
  
  1. One Deadlock of 'row cache lock' and 'library cache lock'
• April 2023 (3)
  
  1. Oracle Multi-Consumer AQ dequeue with dbms_aq.listen Wait Events (I)
  2. Oracle Multi-Consumer AQ dequeue with dbms_aq.listen Performance Model (II)
  3. Oracle Multi-Consumer AQ dequeue with dbms_aq.listen Performance Analysis and Workaround (III)
• March 2023 (2)
  
  1. One Test of Oracle JSON Plsql PGA Memory Leak
  2. One Test of ORA-00600: [KGL-heap-size-exceeded] With AQ Subscriber
• February 2023 (1)
  
  1. Oracle Scalar Subquery Caching and Non-deterministic Functions
• January 2023 (1)
  
  1. Oracle dbms_crypto.randombytes and Enhancement Suggestion
• December 2022 (2)
  
  1. OracleJVM JAVA_JIT_ENABLED Linux /dev/shm mount noexec EPERM and Performance
  2. One Test of Oracle too many parse errors with ORA-12850 and ORA-12872
• October 2022 (2)
  
  1. How many times SYSDATE is called in SQL and Plsql ?
  2. Oracle WITH subquery_factoring_clause TEMP TABLE TRANSFORMATION and log file sync
• September 2022 (2)
  
  1. Update Restart and Undo Extends
  2. Proposal for ORA-04030 incident/trace files Enhancement to list Plsql package Memory Usage
• August 2022 (2)
  
  1. Oracle Global Temporary Table ORA-01555 and Undo Retention
  2. Oracle Global Temporary Table ORA-01555 and XML Data Size
• July 2022 (1)
  
  1. Plsql ORA-00600 by JDBC Call Exception Catch
• June 2022 (1)
  
  1. Tests of Oracle ORA-01866: the datetime class is invalid
• May 2022 (2)
  
  1. How volatile is ORA-00600 [qernsRowP] ?
  2. One Case of ORA-00036: Maximum Number Of Recursive SQL Levels (50) Exceeded
• April 2022 (2)
  
  1. Oracle Write Consistency and ORA-30926: "unable to get a stable set of rows in the source tables"
  2. Oracle Write Consistency and ORA-00600: [13030], [20]
• March 2022 (1)
  
  1. Index Skip Scan With First Column of Composite Index Specified
• February 2022 (2)
  
  1. Oracle Kill Session Crashes DB Instance
  2. How to determine session's CURRVAL of an oracle sequence without error and without modify ?
• January 2022 (1)
  
  1. Oracle SQL Monitoring Shared Pool "keomg: entry list " Memory Leak
• December 2021 (1)
  
  1. How to count the inserts and updates from merge ?
• November 2021 (1)
  
  1. Oracle dbms_aq.dequeue_array Shared Pool "KTC Latch Subh" Memory Leak
• October 2021 (2)
  
  1. Oracle Temp Space Usage Monitoring and View v$tempseg_usage
  2. Oracle sessiontimezone Format Changed After Calling dbms_scheduler/dbms_job Subprograms
• July 2021 (1)
  
  1. Oracle Program and Table dc_objects "row cache lock"
• June 2021 (1)
  
  1. Oracle dbms_alert and its Wait Events
• May 2021 (1)
  
  1. Oracle 19c new shared pool "SO private sga" and "SO private so latch" Performance Impacts
• April 2021 (3)
  
  1. Oracle PLITBLM "library cache: mutex X"
  2. The Third Test of ORA-04025: maximum allowed library object lock
  3. Oracle forall DML save exceptions and ORA-04030: out of process memory (callheap,psdalf:RPI allocations)
• March 2021 (2)
  
  1. Oracle Temp File Read Time Stats Problem
  2. Oracle deallocate_unused_clause and its effect
• January 2021 (1)
  
  1. DBMS_SCHEDULER Job Not Running and Used Slaves
• November 2020 (3)
  
  1. OracleJVM integer Array Size Limit and Out of Memory Error
  2. Oracle LOB Chunksize and Buffersize
  3. One case of dbms_alert.signal deadlock
• September 2020 (1)
  
  1. The Second Test of ORA-600 [4156] Rolling Back To Savepoint
• August 2020 (1)
  
  1. Row Cache Object and Row Cache Mutex Case Study
• May 2020 (3)
  
  1. 12cR2 Index Usage Tracking Manual Flushing
  2. One "row cache lock" Test Case
  3. ORA-600 [504] LATCH HIERARCHY ERROR Deadlock
• April 2020 (3)
  
  1. Index Service ITL and Recursive Transaction
  2. Index Block Split Point Distribution
  3. Cache Buffer Chains Latch Contention Case Study-3: index root block Modification Blocking
• February 2020 (2)
  
  1. Cache Buffer Chains Latch Contention Case Study-2: Reverse Primary Key Index
  2. Cache Buffer Chains Latch Contention Case Study-1: Reverse Key Index
• January 2020 (1)
  
  1. Oracle Unique Index Non-Consistency Read with RowCR
• December 2019 (2)
  
  1. Oracle Database and Java Datetime Conversion Differences across Daylight Saving Time (DST)
  2. Oracle 19.4 OracleJVM JAVA_JIT_ENABLED Not Working on AIX
• August 2019 (2)
  
  1. Oracle 18 New Wait Event: 'index (re)build lock or pin object'
  2. PDML Disabled on Nonpartitioned IOT
• April 2019 (1)
  
  1. LOB ORA-22924: snapshot too old and Fix
• November 2018 (5)
  
  1. Oracle row cache objects Event: 10222, Dtrace Script (I)
  2. Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-1) (II)
  3. Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-2) (III)
  4. Row Cache and Sql Executions (IV)
  5. Latch: row cache objects Contentions and Scalability (V)
• October 2018 (2)
  
  1. Oracle ROWCACHE Views and Contents
  2. Result Cache: RC Enqueue and Contention (V)
• July 2018 (3)
  
  1. row cache mutex in Oracle 12.2.0.1.0
  2. plshprof command-line utility in Oracle 12.2.0.1.0
  3. 12c Online Statistics Gathering for Direct Path Insert and 3 Side Effects
• April 2018 (1)
  
  1. TM Lock and No Transaction Commit, TX & TM Locks and No Transaction Visible
• March 2018 (2)
  
  1. 'enq: RO - fast object reuse' and 'enq: KO - fast object checkpoint' Final Blocker
  2. Oracle 12.1 Wait Event: 'log file sync: SCN ordering' Demo
• February 2018 (1)
  
  1. SYS.LOADER_DIR_OBJS Query: Privileges and Performance
• January 2018 (4)
  
  1. Oracle Logical Read: Current Gets Access Path and Cost
  2. Oracle Logical Read: Consistent Gets Access Path and Cost
  3. Oracle Physical Read Access Path and Cost
  4. Oracle Latch Misses, Spin_gets, Sleeps and Recurrent_Misses
• October 2017 (2)
  
  1. ORA-04025 library object lock on DATABASE Truncate Triggers
  2. Result Cache: 0 rows updated Invalidations (IV)
• September 2017 (2)
  
  1. Result Cache: RC Latch Contention and PL/SQL Exception Handler (III)
  2. Result Cache: RC Latch Contention and RESULT_CACHE_MAX_SIZE(II)
• July 2017 (3)
  
  1. nls_database_parameters, dc_props, latch: row cache objects
  2. v$database select and control file sequential read
  3. Getting Oracle Transaction Commit SCN
• May 2017 (8)
  
  1. JDBC, Oracle object/collection, dbms_pickler, NOPARALLEL sys.type$ query
  2. PLSQL Context Switch Functions and Cost
  
  
  3. Oracle Datetime (1) - Concepts
  4. Oracle Datetime (2) - Examples
  5. Oracle Datetime (3) - Assignments
  6. Oracle Datetime (4) - Comparisons
  7. Oracle Datetime (5) - SQL Arithmetic
  8. Oracle Datetime (6) - PLSQL Arithmetic
• March 2017 (3)
  
  1. Oracle 12c PL/SQL Function in the WITH Clause: wrong result
  2. Oracle abstract_lob Memory Leak
  3. PL/SQL Function Result Cache Invalidation (I)
• February 2017 (1)
  
  1. Oracle JVM Java OutOfMemoryError and lazy GC
• January 2017 (1)
  
  1. ORA-600 [4156] SAVEPOINT and PL/SQL Exception Handling
• November 2016 (1)
  
  1. "library cache: mutex X" and Application Context
• September 2016 (2)
  
  1. PL/SQL Multidimensional Collection Memory Usage and Performance
  1. dbms_session.get_package_memory_utilization and limitations
• August 2016 (1)
  
  1. ORA-04025 library object lock on AQ queue and SQL cursor
• June 2016 (1)
  
  1. SQL Parsing in serializable transaction throws ORA-08177: can't serialize access for this transaction
• May 2016 (1)
  
  1. Oracle Fixed Table Practice
• April 2016 (1)
  
  1. sql_id and idn to shared pool subpool
• February 2016 (1)
  
  1. Native Code Files: Ora-7445 [Ioc_pin_shared_executable_object()] Reproducing
• January 2016 (3)
  
  1. Performance of Oracle Object Collection Comparisons - Part2
  2. Performance of Oracle Object Collection Comparisons - Part1
  3. Foreign Keys and Library Cache Locks: Analysis
• December 2015 (1)
  
  1. Oracle bigfile tablespace pre-allocation and session blocking
• November 2015 (1)
  
  1. Oracle 12c single session "library cache lock (cycle)" deadlock
• September 2015 (2)
  
  1. SQL DML Exceptions, Rollbacks and PL/SQL Exception Handlers
  2. Limit PGA Memory Usage
• August 2015 (1)
  
  1. Latch _SPIN_COUNT: adaptive
• July 2015 (2)
  
  1. Redo Practice
  2. UNDO Practice
• June 2015 (1)
  
  1. Temporary LOB Memory Allocation and Freeing in JAVA
• April 2015 (2)
  
  1. IBM AIX POWER7 CPU Usage and Throughput
  2. Oracle 11.2.0.4.0 AWR "Tablespace IO Stats" Column Names Shifted
• January 2015 (1)
  
  1. open_cursors, session_cached_cursors: cursordump
• December 2014 (1)
  
  1. Local prefixed vs. nonprefixed indexes: Column Null Values
• November 2014 (2)
  
  1. reverse key index: the remedy is worse than the symptoms
  2. Low High Water Mark, High High Water Mark, and Parallel Query
• May 2014 (3)
  
  1. Oracle 11g AUTO_SAMPLE_SIZE performance on Small Tables
  2. java stored procedure calls and latch: row cache objects, and performance
  3. java stored procedure calls and latch: row cache objects
• March 2014 (2)
  
  1. dbms_aq.dequeue - latch: row cache objects on AIX
  2. Hot Block Identification and latch: cache buffers chains
• November 2013 (3)
  
  1. Remove Stale Native Code Files on AIX
  2. PGA, SGA memory usage watching from UNIX
  3. ORA-04030 incident file and alert.log
• September 2013 (1)
  
  1. Execution Switching between "direct path read" and "db file scattered read"
• June 2013 (2)
  
  1. Oracle PL/SQL Collection Memory Reclaim 
  2. dbms_alert lock hash collision
• April 2013 (2)
  
  1. cursor: pin S wait on X
  2. Shared Pool - Free Memory, Fragmentation ?
• March 2013 (3)
  
  1. Shared Pool - SQLA and KGLH0
  2. Shared Pool - Memory Allocation - unbalanced
  3. Shared Pool - KKSSP
• December 2012 (1)
  
  1. Delete Restart and new Active Undo Extent
• November 2012 (2)
  
  1. One Oracle AQ Deadlock
  2. Oracle Java OutOfMemoryError
• July 2012 (1)
  
  1. One Mutex Collision Test
• May 2012 (1)
  
  1. Why shared pool is doubled ?
• April 2012 (1)
  
  1. High system time utilization on fast machine
• February 2012 (1)
  
  1. Is latch misses statistic gathered or deduced ?
• November 2011 (2)
  
  1. One Oracle 12g Pre-announce of bug fix in dbms_debug_jdwp
  2. Oracle 11gR2 single session "library cache pin"
• July 2011 (1)
  
  1. Redo/Undo explosion from thick declared table insert
• May 2011 (3)
  
  1. ORA-04027: self-deadlock during automatic validation
  2. Foreign Key on Nested Table
  3. Update Restart and new Active Undo Extent
• April 2011 (1)
  
  1. dbms_session package_memory_utilization

"library cache: bucket mutex X" on V$ Fixed Views: Case Test

Oracle DB experienced heavy "library cache: bucket mutex X" when V$ Fixed Views were queried frequently,
which impeded Oracle normal functions like background processes Mnnn and MZnn.

Note: Tested on Oracle 19c.

1. Test Setup

In the following code, we query V$LIBCACHE_LOCKS (similar behavior for DBA_KGLLOCK), which is a union of X$KGLLK and X$KGLPN.

create or replace procedure test_bucket_mutex(p_job_id number, p_loop_count number) as
begin
  for i in 1..p_loop_count loop
    for c in (select * from V$LIBCACHE_LOCKS where rownum <= p_job_id) loop
      null;
    end loop;
  end loop;
end;
/

-- exec test_bucket_mutex(1, 1);

create or replace procedure test_bucket_mutex_jobs(p_job_count number, p_loop_count number) as
begin
  for i in 1..p_job_count loop
    dbms_scheduler.create_job (
      job_name        => 'TEST_JOB_'||i,
      job_type        => 'PLSQL_BLOCK',
      job_action      => 'begin test_bucket_mutex('||i||', '||p_loop_count||'); end;',    
      start_date      => systimestamp,
      --repeat_interval => 'systimestamp',
      auto_drop       => true,
      enabled         => true);
  end loop;
end;
/

2. Test Run

Run a test with 16 Jobs:

exec test_bucket_mutex_jobs(16, 1e4);

AWR shows:

Top 10 Foreground Events by Total Wait Time

Event	Waits	Total Wait Time (sec)	Avg Wait	% DB time	Wait Class
library cache: bucket mutex X	939,402	17.1K	18.22ms	59.8	Concurrency
DB CPU		7062.2		24.7
library cache: mutex X	5,139	69.3	13.48ms	.2	Concurrency
control file sequential read	20,874	2.9	137.27us	.0	System I/O
db file sequential read	3,195	1.8	557.97us	.0	User I/O
Disk file operations I/O	2,602	.2	72.88us	.0	User I/O
cursor: pin S	8	.1	17.55ms	.0	Concurrency
log file sync	20	.1	6.52ms	.0	Commit
direct path write	59	0	217.10us	.0	User I/O
latch free	1	0	10.66ms	.0	Other

SQL ordered by Elapsed Time

Elapsed Time (s)	Executions	Elapsed Time per Exec (s)	%Total	%CPU	%IO	SQL Id	SQL Module	SQL Text
28,575.23	159,710	0.18	99.89	24.66	0.00	9sz3zkc69bpjh	DBMS_SCHEDULER	SELECT * FROM V$LIBCACHE_LOCKS...
1,790.62	1	1,790.62	6.26	24.82	0.00	0f1dxm6hd2c2u	DBMS_SCHEDULER	DECLARE job BINARY_INTEGER := ...
1,790.18	1	1,790.18	6.26	24.65	0.00	5vp17fw0hgrz1	DBMS_SCHEDULER	DECLARE job BINARY_INTEGER := ...

Mutex Sleep Summary

Mutex Type	Location	Sleeps	Wait Time (ms)
Library Cache	kglic1 49	1,696,792	15,671,698
Library Cache	kglic4 145	172,634	1,423,319
Library Cache	kglGetHandleReference 123	8,262	61,133
Library Cache	kglReleaseHandleReference 124	1,176	8,110
Library Cache	kglhdgn1 62	9	71
Cursor Pin	kksLockDelete [KKSCHLPIN6]	9	138
Cursor Pin	kksfbc [KKSCHLFSP2]	2	2
Row Cache	[14] kqrScan	1	0

Top SQL with Top Row Sources

SQL ID	Plan Hash	Executions	% Activity	Row Source	% Row Source	Top Event	% Event	SQL Text
9sz3zkc69bpjh	2131580607	2794	98.87	FIXED TABLE - FULL	49.95	library cache: bucket mutex X	30.36	SELECT * FROM V$LIBCACHE_LOCKS...
				FIXED TABLE - FULL	48.57	library cache: bucket mutex X	31.00

During the test, we can monitor "library cache: bucket mutex X" waits by:

select 'BLOCKING_SESSION'   sess, program, event, mod(s.p1, power(2, 17)) "buckt muext(child_latch)", s.p1, s.p2, s.p3, s.sql_id, q.sql_text, m.*, s.*, q.* 
from v$session s, v$mutex_sleep_history m, v$sqlarea q
 where s.sid = m.blocking_session and s.sql_id = q.sql_id and m.sleep_timestamp > sysdate-5/1440 and m.sleeps > 3
union all
select 'REQUESTING_SESSION' sess, program, event, mod(s.p1, power(2, 17)) "buckt muext(child_latch)", s.p1, s.p2, s.p3, s.sql_id, q.sql_text, m.*, s.*, q.* 
from v$session s, v$mutex_sleep_history m, v$sqlarea q
 where s.sid = m.requesting_session and s.sql_id = q.sql_id and m.sleep_timestamp > sysdate-5/1440 and m.sleeps > 3;

select bs.session_id, bs.session_serial#, bs.program, bs.event, bs.p1, bs.blocking_session, bs.blocking_session_serial#, bs.sql_id
      ,s.sample_time, s.session_id, s.session_serial#, s.program, s.event, s.p1, s.blocking_session, s.blocking_session_serial#, s.sql_id
  from v$active_session_history bs, v$active_session_history s
where s.event  = 'library cache: mutex X'
  and bs.event = 'library cache: bucket mutex X'
  and s.sample_time = bs.sample_time
  and mod(s.p1, power(2, 17)) = bs.p1
  and s.session_id != bs.session_id
  and s.sample_time > sysdate-5/1440
order by s.sample_time desc, bs.session_id, s.session_id;

select sql_id, last_active_time, executions, disk_reads, direct_writes, buffer_gets, rows_processed, sql_text, v.* 
from v$sqlarea v where sql_id in ('9sz3zkc69bpjh');

3. "library cache: bucket mutex X" Tracing

Open one Sqlplus window, execute bpftrace on its process (UNIX pid 293988):

bpftrace -e 'uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetBucketMutex+2, 
             uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetMutex+2 / pid==293988 /
   {@ustack_cnt[probe] = count();}' 

Run query to fetch rows with rownum limit:

SQL > select * from V$LIBCACHE_LOCKS where rownum <= 10;
  10 rows selected.

Here bpftrace output:

	@ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetBucketMutex+2]: 123462
	@ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetMutex+2]:       269774

Same bpftrace output for count query:

SQL > select count(*) from V$LIBCACHE_LOCKS where rownum <= 10;
    COUNT(*)
  ----------
          10

Run query without rownum limit, we get the similar output due to FIXED TABLE FULL on X$KGLLK and X$KGLPN.

SQL >  select * from V$LIBCACHE_LOCKS;
  1226 rows selected.
        
	@ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetBucketMutex+2]: 123488
	@ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetMutex+2]:       269939

Same bpftrace output for count query:

SQL > select count(*) from V$LIBCACHE_LOCKS;
    COUNT(*)
  ----------
        1226

To get Parameter P1 and P3 of "library cache: bucket mutex X", we can use bpftrace script:

bpftrace -e 'uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetBucketMutex+2 / pid==293988 /
   {@ustack_cnt["kglGetBucketMutex", reg("si"), reg("r8")] = count();}'

Pick a few output lines (first number is P1, second is P3):

  @ustack_cnt[kglGetBucketMutex, 6574, 145]: 2
  @ustack_cnt[kglGetBucketMutex, 5442, 49]:  2
  @ustack_cnt[kglGetBucketMutex, 3311, 49]:  2

Then we can find them in v$db_object_cache:

select child_latch, hash_value, mod(hash_value, power(2, 17)) bucket_p1, owner, substr(name, 1, 50) name, namespace, type 
from v$db_object_cache t where child_latch in (
6574,
5442,
3311
);  

CHILD_LATCH HASH_VALUE  BUCKET_P1 OWNER NAME                                          NAMESPACE            TYPE
----------- ---------- ---------- ----- --------------------------------------------- -------------------- ----------
       3311 1185156335       3311 SYS   java/util/function/DoubleBinaryOperator       TABLE/PROCEDURE      JAVA CLASS
       5442 1797395778       5442       UPDATE SYS.WRI$_ADV_                          SQL AREA             CURSOR
       6574  363993518       6574       WITH binds as           (select :dbid         SQL AREA             CURSOR

To get Parameter P3 of library cache: bucket mutex X, we can use bpftrace script:

bpftrace -e 'uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetBucketMutex+2 / pid==293988 /
   {@ustack_cnt["kglGetBucketMutex", reg("r8")] = count();}'
   
  @ustack_cnt[kglGetBucketMutex, 64]:  1
  @ustack_cnt[kglGetBucketMutex, 62]:  9
  @ustack_cnt[kglGetBucketMutex, 49]:  57846
  @ustack_cnt[kglGetBucketMutex, 145]: 65558

We can see that bpftrace output [kglGetBucketMutex, 49] and [kglGetBucketMutex, 145] big numbers match "kglic1 49" and "kglic1 145" big stats in AWR - Mutex Sleep Summary.

If we query normal tables, there are much less kglGetBucketMutex and kglGetMutex:

SQL > select count(*) from dba_objects;

    COUNT(*)
  ----------
     2004127
   
bpftrace -e 'uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetBucketMutex+2, 
             uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetMutex+2 / pid==293988 /
   {@ustack_cnt[probe] = count();}'
   
  @ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetBucketMutex+2]: 1
  @ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetMutex+2]:       15

4. GV$LIBCACHE_LOCKS and DBA_KGLLOCK DDL and Xplan

Both V$LIBCACHE_LOCKS and SYS.DBA_KGLLOCK are union of X$KGLLK and X$KGLPN. Any queries on them are FIXED TABLE FULL on X$KGLLK and X$KGLPN (rownum limit has no effect).

------ V$LIBCACHE_LOCKS ------
SELECT INST_ID, 'LOCK', KGLLKADR, KGLLKUSE, KGLLKSES, KGLLKHDL, KGLLKPNC, KGLLKCNT, KGLLKMOD, KGLLKREQ, KGLLKSPN, CON_ID
  FROM X$KGLLK
UNION
SELECT INST_ID, 'PIN',  KGLPNADR, KGLPNUSE, KGLPNSES, KGLPNHDL, KGLPNLCK, KGLPNCNT, KGLPNMOD, KGLPNREQ, KGLPNSPN, CON_ID
  FROM X$KGLPN
  
select * from V$LIBCACHE_LOCKS where rownum <= :B1;

Plan hash value: 2131580607
 
---------------------------------------------------------------------------------------------------
| Id  | Operation             | Name              | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT      |                   | 20956 |  2414K|       |   868   (1)| 00:00:01 |
|*  1 |  COUNT STOPKEY        |                   |       |       |       |            |          |
|   2 |   VIEW                | GV$LIBCACHE_LOCKS | 20956 |  2414K|       |   868   (1)| 00:00:01 |
|*  3 |    SORT UNIQUE STOPKEY|                   | 20956 |  2361K|  3656K|   868   (1)| 00:00:01 |
|   4 |     UNION-ALL         |                   |       |       |       |            |          |
|*  5 |      FIXED TABLE FULL | X$KGLLK           | 18837 |  1048K|       |     0   (0)| 00:00:01 |
|*  6 |      FIXED TABLE FULL | X$KGLPN           |  2119 |   132K|       |     0   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------

------ DBA_KGLLOCK ------

CREATE OR REPLACE FORCE NONEDITIONABLE VIEW SYS.DBA_KGLLOCK
(KGLLKUSE, KGLLKHDL, KGLLKMOD, KGLLKREQ, KGLLKTYPE)
BEQUEATH DEFINER
AS 
  select kgllkuse, kgllkhdl, kgllkmod, kgllkreq, 'Lock' kgllktype from x$kgllk
    union all
  select kglpnuse, kglpnhdl, kglpnmod, kglpnreq, 'Pin'  kgllktype from x$kglpn;
  
  
select * from DBA_KGLLOCK where rownum <= :B1;

Plan hash value: 3293675002
 
-----------------------------------------------------------------------------------
| Id  | Operation           | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |             | 20956 |   982K|     0   (0)| 00:00:01 |
|*  1 |  COUNT STOPKEY      |             |       |       |            |          |
|   2 |   VIEW              | DBA_KGLLOCK | 20956 |   982K|     0   (0)| 00:00:01 |
|   3 |    UNION-ALL        |             |       |       |            |          |
|   4 |     FIXED TABLE FULL| X$KGLLK     | 18837 |   423K|     0   (0)| 00:00:01 |
|   5 |     FIXED TABLE FULL| X$KGLPN     |  2119 | 48737 |     0   (0)| 00:00:01 |
-----------------------------------------------------------------------------------

5. Related Work

(1). Dynamic_plan_table, x$kqlfxpl and extreme library cache latch contention (Posted by Riyaj Shamsudeen on March 13, 2009)
(https://orainternals.wordpress.com/tag/kglic/)

We traced following two queries with above bpftrace scripts,
and the output shows that kglGetBucketMutex requests are proptional to rownum limit (:B1).
(For V$LIBCACHE_LOCKS and DBA_KGLLOCK, kglGetBucketMutex requests are constant, irrelvant to rownum limit)

select count(*) from GV$SQL_PLAN where rownum <= :B1;       --FIXED TABLE FULL on X$KQLFXPL
select count(*) from GV$ALL_SQL_PLAN where rownum <= :B1;   --FIXED TABLE FULL on X$ALL_KQLFXPL

Here the test output:

bpftrace -e 'uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetBucketMutex+2,
             uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetMutex+2 / pid==299591 /
   {@ustack_cnt[probe] = count();}'
Attaching 2 probes...

select count(*) from GV$SQL_PLAN where rownum <= 1;
  @ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetBucketMutex+2]: 47
  @ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetMutex+2]:       111

select count(*) from GV$SQL_PLAN where rownum <= 10;
  @ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetBucketMutex+2]: 117
  @ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetMutex+2]:       287

select count(*) from GV$SQL_PLAN where rownum <= 100;
  @ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetBucketMutex+2]: 436
  @ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetMutex+2]:       974

select count(*) from GV$SQL_PLAN where rownum <= 1000;
  @ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetBucketMutex+2]: 3523
  @ustack_cnt[uprobe:/orabin/app/oracle/product/19.27.0.0.250415-212/bin/oracle:kglGetMutex+2]:       7725

(2). Oracle PLITBLM "library cache: mutex X"
(https://ksun-oracle.blogspot.com/2021/04/oracle-plitblm-library-cache-mutex-x.html)

(3). Row Cache Object and Row Cache Mutex Case Study
(https://ksun-oracle.blogspot.com/2020/08/row-cache-object-and-row-cache-mutex.html)

(4). ORACLE MUTEXES, FRITS HOOGLAND (https://fritshoogland.wordpress.com/wp-content/uploads/2020/04/mutexes-2.pdf)

6. GDB script

We can also use following GDB script to trace "library cache: bucket mutex X":

---------------- bucket_mutex_1, gdb -x bucket_mutex_1 -p 293988 ----------------

set pagination off
set logging file bucket_mutex_1.log
set logging overwrite on
set logging on
set $kmutexget = 1
set $kbucketget = 1

break kglGetBucketMutex
command 
printf "------kglGetBucketMutex (%i) ---> Bucket (rsi): %d (%X), Location(r8d): %d (%X)\n", $kbucketget++, $rsi, $rsi, $r8d, $r8d
backtrace 4
continue
end

break kglGetMutex
command 
printf "------kglGetMutex (%i) ---> Mutex addr (rsi): %d (%X), Location(r8d): %d (%X)\n", $kmutexget++, $rsi, $rsi, $r8d, $r8d
continue
end

7. kglMutexLocations[] array

For all kglMutexLocations, we can try to list them with following command.
They often appear in AWR section "Mutex Sleep Summary" for Mutex Type: "Library Cache"
(or V$MUTEX_SLEEP / V$MUTEX_SLEEP_HISTORY.location).

define PrintkglMutexLocations
  set pagination off
  set $i = 0
  while $i < $arg0
    x /s *((uint64_t *)&kglMutexLocations + $i)
    set $i = $i + 1
  end
end

(gdb) PrintkglMutexLocations 150

0x15f42524:     "kglic1    49"
0x15f42a24:     "kglic2 127"
0x15f42b68:     "kglic3       144"
0x15f42b7c:     "kglic4       145"

(Only "kglic" Mutex are shown here)

Oracle dbms_hprof: Uncatchable Time in PL/SQL Nested Program Units

This Blog will demonstrate dbms_hprof uncatchable time in PL/SQL nested procedures and packages, which often caused misleading in elapsed time accounting, and in locating time consumption PL/SQL programs.

Note: Tested on Oracle 19c.

1. Test Code

In following code, we have one procedure which calls a nested procedure:

create or replace procedure hprof_plsql_proc_test(p_cnt_outer number, p_cnt_inner number)
is
  type t_rec is record(
             id      pls_integer
            ,name    varchar2(1000)
           );
  type t_rec_tab is table of t_rec index by pls_integer;

  l_rec       t_rec;
  l_rec_tab   t_rec_tab;
  l_row_cnt   number;

  procedure proc_nested(p_cnt_outer number, p_cnt_inner number)
  is
  begin
    for i in 1..p_cnt_outer loop    
      l_rec_tab := t_rec_tab();
      select /*+ Start */ count(*) into l_row_cnt from dual;
      for i in 1..p_cnt_inner loop
        l_rec := t_rec(
                id      => 1
               ,name    => lpad('A', 900, 'B')||i
              );
        l_rec_tab(i) := l_rec;
      end loop;
      select /*+ End */ count(*) into l_row_cnt from dual;
    end loop;
  end;

begin
  dbms_output.put_line('hprof_plsql_proc_test('||p_cnt_outer||', '||p_cnt_inner||')');

  proc_nested(p_cnt_outer, p_cnt_inner);
end;
/

2. Test Run with Unwrapped PL/SQL

Run above procedure with dbms_hprof, and create html hprofile:

create or replace directory TEST_DIR as '/testdb/oradata/hprof/';

set serveroutput on
declare
  l_test_dir        varchar2(100) := 'TEST_DIR';
  l_hprof_file_name varchar2(100) := 'hprof_plsql_proc_test_UnWrapped_1.hpf';
  l_runid           number;
begin
  dbms_hprof.start_profiling (
    location => l_test_dir,
    filename => l_hprof_file_name);

  hprof_plsql_proc_test(1e2, 1e5);

  dbms_hprof.stop_profiling;

  l_runid := dbms_hprof.analyze (
     location    => l_test_dir,
     filename    => l_hprof_file_name,
     run_comment => 'hprof_plsql_proc_test Test');

  dbms_output.put_line('l_runid=' || l_runid);
end;
/

HProf shows that HPROF_PLSQL_PROC_TEST elapsed time is sum of all its Children.

But for Subtreee PROC_NESTED, the sum of all its Children (6635+6253=12888) is much less than Subtreee time (12642594), 12629706 (12642594 - 12888) is unaccounted.

Parents and Children Elapsed Time (microsecs) Data

HPROF_PLSQL_PROC_TEST.HPROF_PLSQL_PROC_TEST (Line 1)



Subtree
Ind%
Function
Ind%
Descendants
Ind%
Calls
Ind%
Function Name
SQL ID
SQL TEXT

12652694
 100%
10088
 0.1%
12642606
 100%
1
 0.5%
HPROF_PLSQL_PROC_TEST.HPROF_PLSQL_PROC_TEST (Line 1)
Parents:
12652694
 100%
10088
 100%
12642606
 100%
1
 100%
ORACLE.root 
Children:
12642594
 100%
12629706
 100%
12888
 100%
1
 100%
HPROF_PLSQL_PROC_TEST.HPROF_PLSQL_PROC_TEST.PROC_NESTED (Line 13)
12
 0.0%
2
 100%
10
 100%
1
 100%
SYS.DBMS_OUTPUT.PUT_LINE (Line 109)



HPROF_PLSQL_PROC_TEST.HPROF_PLSQL_PROC_TEST.PROC_NESTED (Line 13)



Subtree
Ind%
Function
Ind%
Descendants
Ind%
Calls
Ind%
Function Name
SQL ID
SQL TEXT

12642594
 100%
12629706
99.8%
12888
 0.1%
1
 0.5%
HPROF_PLSQL_PROC_TEST.HPROF_PLSQL_PROC_TEST.PROC_NESTED (Line 13)
Parents:
12642594
 100%
12629706
 100%
12888
 100%
1
 100%
HPROF_PLSQL_PROC_TEST.HPROF_PLSQL_PROC_TEST (Line 1)
Children:
6635
51.5%
6635
 100%
0
N/A
100
 100%
HPROF_PLSQL_PROC_TEST.__static_sql_exec_line26 (Line 26)
3cfwwbgj9ft44
SELECT /*+ End */ COUNT(*) FROM DUAL
6253
48.5%
6253
 100%
0
N/A
100
 100%
HPROF_PLSQL_PROC_TEST.__static_sql_exec_line18 (Line 18)
8tuspbw8fxyrn
SELECT /*+ Start */ COUNT(*) FROM DUAL


Look HProf raw file, we can see that time "P#X 139321" is not attributed to any program (PL/SQL or SQL):


P#C PLSQL."K"."HPROF_PLSQL_PROC_TEST"::7."HPROF_PLSQL_PROC_TEST.PROC_NESTED"#3048d2af80817a01 #13
P#X 8
P#C SQL."K"."HPROF_PLSQL_PROC_TEST"::7."__static_sql_exec_line18" #18."8tuspbw8fxyrn"
P#! SELECT /*+ Start */ COUNT(*) FROM DUAL
P#X 46
P#R
P#X 139321
P#C SQL."K"."HPROF_PLSQL_PROC_TEST"::7."__static_sql_exec_line26" #26."3cfwwbgj9ft44"
P#! SELECT /*+ End */ COUNT(*) FROM DUAL
P#X 73
 



3. Test Run with Wrapped PL/SQL


Install wrapped PL/SQL (see Section 4. Wrapped PL/SQL), and run it with dbms_hprof, then create html hprofile:


set serveroutput on
declare
  l_test_dir        varchar2(100) := 'AAA_RAC_XCHNG';
  l_hprof_file_name varchar2(100) := 'hprof_plsql_proc_test_Wrapped_1.hpf';
  l_runid           number;
begin
  dbms_hprof.start_profiling (
    location => l_test_dir,
    filename => l_hprof_file_name);

  hprof_plsql_proc_test(1e2, 1e5);

  dbms_hprof.stop_profiling;

  l_runid := dbms_hprof.analyze (
     location    => l_test_dir,
     filename    => l_hprof_file_name,
     run_comment => 'hprof_plsql_proc_test Test');

  dbms_output.put_line('l_runid=' || l_runid);
end;
/
 

HProf shows that the top call: HPROF_PLSQL_PROC_TEST has time = 12865442, but all its Children has only 13408.

The unaccounted time amounts to 12852034 (12865442-13408), almost no time is profiled.

Parents and Children Elapsed Time (microsecs) Data

HPROF_PLSQL_PROC_TEST.HPROF_PLSQL_PROC_TEST (Line 1)



Subtree
Ind%
Function
Ind%
Descendants
Ind%
Calls
Ind%
Function Name
SQL ID
SQL TEXT

12865442
 100%
12852034
99.9%
13408
 0.1%
1
 0.5%
HPROF_PLSQL_PROC_TEST.HPROF_PLSQL_PROC_TEST (Line 1)
Parents:
12865442
 100%
12852034
 100%
13408
 100%
1
 100%
ORACLE.root 
Children:
6879
51.3%
6879
 100%
0
N/A
100
 100%
HPROF_PLSQL_PROC_TEST.__static_sql_exec_line26 (Line 26)
3cfwwbgj9ft44
SELECT /*+ End */ COUNT(*) FROM DUAL
6517
48.6%
6517
 100%
0
N/A
100
 100%
HPROF_PLSQL_PROC_TEST.__static_sql_exec_line18 (Line 18)
8tuspbw8fxyrn
SELECT /*+ Start */ COUNT(*) FROM DUAL
12
 0.1%
1
 100%
11
 100%
1
 100%
SYS.DBMS_OUTPUT.PUT_LINE (Line 109)




4. Wrapped PL/SQL



testdb $ wrap iname=hprof_plsql_proc_test.sql

testdb $ cat hprof_plsql_proc_test.plb
create or replace procedure k.hprof_plsql_proc_test wrapped
a000000
1f
abcd
abcd
abcd
abcd
abcd
abcd
abcd
abcd
abcd
abcd
abcd
abcd
abcd
abcd
abcd
7
3ab 233
YPWOC06TiznHzO1ynQEtqQmVKQ4wg41eLq5qfHRDNA/uugXMeaR4dUB33xnjiWxc7OHa6eMo
UnVwftozxoagoNnUy3AmGAHaM04S3mtcStgl57sTzcETVdi/D/YMuQNVnbkzODjH3tjldCfI
PWWEpIT9hgkzLRHd2fupk5Tn1CdHN5xnByVWGlMXbg0XqPL8cLg3kk3KpynTkMdP/OTRPeru
FKHxhWT06ICM2KGCeErLNw6LpKb6pfPCjSTeew4TUaHEPIncmHDrvctMqtP8r80M9J+x6KGz
64t61S0hhflZb7OPfZe4rwEDMXHejzaIG4z3mqIWXFPkcpJbiXgDHUdLqNuT9OHHHYbubIn4
sM0cQAuFXGwuV19NmMwZe8c7p93lw/WcqgsRNdp0AHNiQlXStnkAQhfEfK0uMyUJCY4+mdYh
4+57oeDnwsrl9j/AjJrZBXpd9/2We+5ua5Gyl4Ihj8bZJFql/feu8r/TLX6Tey4Yl199A6wM
dNZOnVlpsUFAMi4MM2tACZ7pNXedjIJkwX0xaWMdxwiydIiGxw==

/
 


5. PL/SQL Package Test Cdoe


The similar behaviour can be demonstrated for nested procedure/function in PL/SQL package.


create or replace package hprof_plsql_pkg_test
is
  procedure proc_outer(p_cnt_outer number, p_cnt_inner number);
end;
/

create or replace package body hprof_plsql_pkg_test
is
  type t_rec is record(
             id      pls_integer
            ,name    varchar2(1000)
           );
  type t_rec_tab is table of t_rec index by pls_integer;

  l_rec       t_rec;
  l_rec_tab   t_rec_tab;
  l_row_cnt   number;

  procedure proc_nested(p_cnt_outer number, p_cnt_inner number)
  is
  begin
    for i in 1..p_cnt_outer loop    
      l_rec_tab := t_rec_tab();
      select /*+ Start */ count(*) into l_row_cnt from dual;
      for i in 1..p_cnt_inner loop
        l_rec := t_rec(
                id      => 1
               ,name    => lpad('A', 900, 'B')||i
              );
        l_rec_tab(i) := l_rec;
      end loop;
      select /*+ End */ count(*) into l_row_cnt from dual;
    end loop;
  end;
  
  procedure proc_outer(p_cnt_outer number, p_cnt_inner number)
  is
  begin
    proc_nested(p_cnt_outer, p_cnt_inner);
  end;
end;
/