Wednesday, July 30, 2025

Reading CLOB Line by Line with SQL and Plsql

This blog will demonstrate different implementations of reading CLOB line by line in SQL and Plsql.
For both SQL and Plsql, we show one slow and one fast version.

Then we run tests, compare and investigate their performance difference.

In next Blog: Reading CLOB Line by Line with SQL and Plsql: ChatGPT and Gemini Implementations
we will give a look of SQL and Plsql implementations provided by ChatGPT and Gemini.

Note: Tested on Oracle 19c.


1. Test Setup


1.1 Create Table and Filling Procedure


drop table test_tab_lob cascade constraints;

create table test_tab_lob(id number, mylob clob, note varchar2(100));

create or replace procedure create_test_data(p_id number, p_cnt number, p_last_line_no_LF number := 0) as 
  LF     constant varchar2(1)  := chr(10);
  l_mylob         clob; 
begin
  insert into test_tab_lob values (p_id, empty_clob(), 'CLOB Line Count = '||p_cnt||', Line_Last_Line_No_LF = '||p_last_line_no_LF) 
         returning mylob into l_mylob;
  
  for i in 1..p_cnt loop
      dbms_lob.append(dest_lob => l_mylob, src_lob => rpad('Line_'||i||'-', least(10+i-1, 1000), 'X')||LF);  
  end loop;
  if p_last_line_no_LF = 1 then 
    dbms_lob.append(dest_lob => l_mylob, src_lob => rpad('Line_Last_Line_No_LF-', 20, 'Y'));  -- add last line without LF
  end if;
  dbms_output.put_line(length(l_mylob));
  commit;
end;
/


1.2. Create Test Data


---- Smoking Test with LF at the end of Last Line
exec create_test_data(1, 5);

---- Smoking Test without LF at the end of Last Line
exec create_test_data(2, 5, 1);

---- CLOB with 1000 Lines
exec create_test_data(3, 1000);

---- CLOB with 10*1000 Lines
exec create_test_data(4, 10*1000);

---- CLOB with 100*1000 Lines
exec create_test_data(5, 100*1000);


1.3. Check Table CLOB Size


select id, length(mylob), note, round(dbms_lob.getlength(mylob)/1024/1024, 2) LOB_MB from test_tab_lob t;

    ID LENGTH(MYLOB) NOTE                                                             LOB_MB
  ---- ------------- ------------------------------------------------------------ ----------
     1            65 CLOB Line Count = 5, Line_Last_Line_No_LF = 0                         0
     2            85 CLOB Line Count = 5, Line_Last_Line_No_LF = 1                         0
     3        510455 CLOB Line Count = 1000, Line_Last_Line_No_LF = 0                    .49
     4       9519455 CLOB Line Count = 10000, Line_Last_Line_No_LF = 0                  9.08
     5      99609455 CLOB Line Count = 100000, Line_Last_Line_No_LF = 0                94.99


with sq as (select /*+ materialize */ segment_name, index_name from dba_lobs where owner='K' and table_name='TEST_TAB_LOB')
select t.segment_name, tablespace_name, header_file, relative_fno, header_block, bytes, blocks, extents, round(bytes/1024/1024) mb from dba_segments t, sq 
where t.segment_name = sq.segment_name or t.segment_name = sq.index_name;

  SEGMENT_NAME                      TABLESPACE_NAME      HEADER_FILE RELATIVE_FNO HEADER_BLOCK      BYTES     BLOCKS    EXTENTS         MB
  --------------------------------- -------------------- ----------- ------------ ------------ ---------- ---------- ---------- ----------
  SYS_IL0005911971C00002$$          U1                            22         1024      2830970   10485760       1280         25         10
  SYS_LOB0005911971C00002$$         U1                            22         1024      2830962 1143996416     139648        201       1091

(see Blog: "One Oracle CLOB Space Usage Test": 
"https://ksun-oracle.blogspot.com/2025/02/one-oracle-clob-space-usage-test.html")


2. SQL Recursive Query


2.1 SQL Slow Recursive


In Post: "Reading clob line by line with pl\sql"
(https://stackoverflow.com/questions/11647041/reading-clob-line-by-line-with-pl-sql),
there is one ANSI Standard Recursive Query to read clob line by line:

create or replace procedure SQL_SLOW (p_id number) as
  --v_tmp clob := 'aaaa'||chr(10)||'bbb'||chr(10)||'ccccc';
  v_tmp clob;
  l_cnt number := 0;
  l_len number := 0;
begin
  select mylob into v_tmp from test_tab_lob where id = p_id;
  for rec in (with clob_table(c) as (select v_tmp c from dual)
            select regexp_substr(c, '.+', 1, level) text,level line
             from clob_table
          connect by level <= regexp_count(c, '.+')) 
  loop
    --dbms_output.put_line(rec.text);
    l_cnt := l_cnt+1;
    l_len := l_len+length(rec.text);
  end loop;
  dbms_output.put_line('CNT = '||l_cnt ||', Length = '||l_len);
end;
/

-- exec SQL_SLOW(1);
This code has Quadratic Performance (O(n^2)). Each line is read from first CLOB line position, hence n*n/2 scans.
Session shows intensive Oracle Wait Event "direct path read".

With perf tool, we observe following top Oracle subroutine calls:

$ > perf top -p 2450579 -d 2 

    PerfTop:     744 irqs/sec  kernel: 0.0%  exact:  0.0% lost: 0/0 drop: 0/0 [4000Hz cpu-clock:uhpppH],  (target_pid: 2450579)
-------------------------------------------------------------------------------------------------------------------------------------

    10.72%  oracle         [.] lxregmatch
     3.88%  oracle         [.] sxorchk
     3.17%  oracle         [.] lxregmatpush
     3.04%  oracle         [.] lxoCntByte
     2.71%  oracle         [.] lxpoCmpStr


2.2 SQL Fast Recursive


create or replace procedure SQL_FAST (p_id number) as
  l_cnt number := 0;
  l_len number := 0;
begin
  for c in (
    with 
      --lob as (select 1 id, length(mylob)+1 lob_len, mylob||chr(10) mylob from 
      --    (select to_clob('abc'||chr(10)||'x1'||chr(10)||chr(10)||'x2'||chr(10)||'x3') mylob from dual))
      lob as (select id, length(mylob)+1 lob_len, mylob||chr(10) mylob from test_tab_lob where id = p_id)
     ,recur_tab(id, lob_len, mylob, line, total_len, lf_pos, lf_pos_prior, lvl) as (
        select id, lob_len, mylob, dbms_lob.substr(mylob, instr(mylob, chr(10), 1, 1)-1, 1) line
              ,0 total_len, instr(mylob, chr(10), 1, 1) lf_pos, 0 lf_pos_prior, 0 lvl 
          from lob
        union all
        select id, lob_len, mylob, dbms_lob.substr(mylob, lf_pos - 1 - lf_pos_prior, lf_pos_prior+1) line
              ,total_len + length(line) + 1 total_len
              ,instr(mylob, chr(10), lf_pos+1, 1) lf_pos, lf_pos lf_pos_prior, lvl+1 lvl
          from recur_tab where total_len <= length(mylob))
    select t.*, length(line) line_len, dbms_lob.substr(line, length(line), 1) line_text 
      from recur_tab t where line is not null and lf_pos_prior > 0)
  loop
    l_cnt := l_cnt+1;
    l_len := l_len+length(c.line);
  end loop;
  dbms_output.put_line('CNT = '||l_cnt ||', Length = '||l_len);
end;
/

-- exec SQL_FAST(1);
The above code has Linear Prformance (O(n)). Each line is read from next CLOB line position, hence n scans.

Post: "Oracle: Read from CLOB column line by line and insert to the table"
(https://dba.stackexchange.com/questions/10893/oracle-read-from-clob-column-line-by-line-and-insert-to-the-table)
also has some similar code, which wrote:
"This is not a full answer because it only works if your clob is less than 4000 chars."


3. Plsql Implementations


3.1 Plsql Fast Version


In Post: "Reading clob line by line with pl\sql"
(https://stackoverflow.com/questions/11647041/reading-clob-line-by-line-with-pl-sql),
there is one Plsql code: "procedure parse_clob" as follows:

create or replace procedure PLSQL_FAST (p_id number) is
  p_clob         clob;
  l_offset       pls_integer:=1;
  l_line         varchar2(32767);
  l_total_length pls_integer := length(p_clob);
  l_line_length  pls_integer;
  l_cnt          number := 0;
  l_len          number := 0;
begin
  select mylob into p_clob from test_tab_lob where id = p_id;
  l_total_length := length(p_clob);
  dbms_output.put_line('l_total_length = '|| l_total_length); 
  while l_offset <= l_total_length loop
    l_line_length := instr(p_clob, chr(10), l_offset) - l_offset;
    if l_line_length < 0 then
      l_line_length := l_total_length + 1 - l_offset;
    end if;
    l_line:=substr(p_clob, l_offset, l_line_length);
    --dbms_output.put_line(l_line); --do line processing
    l_offset:=l_offset + l_line_length + 1;
    
    l_cnt := l_cnt + 1;
    l_len := l_len + l_line_length;
  end loop;
  
  dbms_output.put_line('CNT = '||l_cnt ||', Length = '||l_len);
end;
/

-- exec PLSQL_FAST(1);
Each line is read from next CLOB line offset.


3.2. Plsql Slow Version


create or replace procedure PLSQL_SLOW(p_id number) is
  p_clob         clob;
  l_offset       pls_integer := 1;
  l_line         varchar2(32767);
  l_total_length pls_integer := length(p_clob);
  l_line_length  pls_integer;
  l_lf_pos       pls_integer;
  l_cnt          number := 0;
  l_len          number := 0;
begin
  select mylob into p_clob from test_tab_lob where id = p_id;
  l_total_length := length(p_clob);
  dbms_output.put_line('l_total_length = '|| l_total_length); 
  while l_offset <= l_total_length loop
    l_lf_pos      := instr(p_clob, chr(10));
    l_line_length := l_lf_pos - 1;
    --dbms_output.put_line('l_offset = '||l_offset); 
    --dbms_output.put_line('l_line_length = '||l_line_length); 
    
    -- In the case of CLOB last line without CHR(10), l_line_length < 0.
    -- instr: If substring not found, INSTR will return 0, hence l_line_length = - l_offset. 
    if l_line_length < 0 then
      l_line_length := l_total_length + 1 - l_offset;
    end if;
    l_line := substr(p_clob, 1, l_line_length);
    --dbms_output.put_line('New l_line_length = '||l_line_length); 
    --dbms_output.put_line(l_line); --do line processing
    l_offset := l_offset + l_line_length + 1;
    p_clob := substr(p_clob, l_lf_pos + 1);
    
    l_cnt := l_cnt + 1;
    l_len := l_len + l_line_length;
  end loop;
  
  dbms_output.put_line('CNT = '||l_cnt ||', Length = '||l_len);
end;
/

-- exec PLSQL_SLOW(1);
CLOB loop calling of substr triggers many dynamic LOB Creations/Destructions in session PL/SQL
(Oracle subroutine "__intel_avx_rep_memcpy": UNIX memcpy).

perf tool shows top Oracle calls:

$ > perf top -p 2450579 -d 2 

  PerfTop:    3878 irqs/sec  kernel: 0.0%  exact:  0.0% lost: 0/0 drop: 0/37 [4000Hz cpu-clock:uhpppH],  (target_pid: 2450579)
-------------------------------------------------------------------------------------------------------------------------------------

    26.05%  oracle         [.] __intel_avx_rep_memcpy
     6.36%  oracle         [.] kcbgcur
     4.76%  oracle         [.] kcbgtcr
     4.05%  oracle         [.] kcbchg1_main
     3.55%  oracle         [.] kcbrls
Post "Testing Oracle's Use of Optane Persistent Memory, Part 1 - Low Latency Commits"
(https://tanelpoder.com/posts/testing-oracles-use-of-optane-persistent-memory/)
wrote: "This is the ìmemcpyî (actually __intel_avx_rep_memcpy)"


4. Test Outcome


4.1. SQL Slow


SQL > exec SQL_SLOW(3);
  CNT = 1,000, Length = 509,455
  Elapsed: 00:04:45.59

SQL > exec SQL_SLOW(4);
  CNT = 10,000, Length = 9,509,455
  Elapsed: 09:49:48.05

SQL > exec SQL_SLOW(5);
-- Not finished after 10 hours


4.2. SQL Fast


SQL > exec SQL_FAST(3);
  CNT = 1,000, Length = 509,455
  Elapsed: 00:00:00.67

SQL > exec SQL_FAST(4);
  CNT = 10,000, Length = 9,509,455
  Elapsed: 00:00:02.78

SQL > exec SQL_FAST(5);
  CNT = 100,000, Length = 99,509,455
  Elapsed: 00:00:39.74


4.3. Plsql Fast


SQL > exec PLSQL_FAST(3);
  CNT = 1,000, Length = 509,455
  Elapsed: 00:00:01.20

SQL > exec PLSQL_FAST(4);
  CNT = 10,000, Length = 9,509,455
  Elapsed: 00:00:04.93

SQL > exec PLSQL_FAST(5);
  CNT = 100,000, Length = 99,509,455
  Elapsed: 00:00:45.29


4.4. Plsql Slow


SQL > exec PLSQL_SLOW(3);
  CNT = 1,000, Length = 509,455
  Elapsed: 00:00:01.36

SQL > exec PLSQL_SLOW(4);
  CNT = 10,000, Length = 9,509,455
  Elapsed: 00:03:22.48

SQL > exec PLSQL_SLOW(5);
  CNT = 100,000, Length = 99,509,455
  Elapsed: 06:16:49.58


4.5. Performance Summary


CLOB_Lines = 1,000
   Code          Elapsed
   -----------   -----------
   SQL_SLOW      00:04:45.59
   SQL_FAST      00:00:00.67
   PLSQL_SLOW    00:00:01.36
   PLSQL_FAST    00:00:01.20    

CLOB_Lines = 10,000
   Code          Elapsed
   -----------   -----------
   SQL_SLOW      09:49:48.05    *** 9 hours
   SQL_FAST      00:00:02.78
   PLSQL_SLOW    00:03:22.48
   PLSQL_FAST    00:00:04.93 

CLOB_Lines = 100,000
   Code          Elapsed
   -----------   -----------
   SQL_SLOW      > 10 hours   *** > 10 hours
   SQL_FAST      00:00:39.74
   PLSQL_SLOW    06:16:49.58  *** 6 hours
   PLSQL_FAST    00:00:45.29 

Thursday, July 10, 2025

"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

EventWaitsTotal Wait Time (sec)Avg Wait% DB timeWait Class
library cache: bucket mutex X939,40217.1K18.22ms59.8Concurrency
DB CPU 7062.2 24.7 
library cache: mutex X5,13969.313.48ms.2Concurrency
control file sequential read20,8742.9137.27us.0System I/O
db file sequential read3,1951.8557.97us.0User I/O
Disk file operations I/O2,602.272.88us.0User I/O
cursor: pin S8.117.55ms.0Concurrency
log file sync20.16.52ms.0Commit
direct path write590217.10us.0User I/O
latch free1010.66ms.0Other

SQL ordered by Elapsed Time

Elapsed Time (s)Executions Elapsed Time per Exec (s) %Total%CPU%IO SQL IdSQL ModuleSQL Text
28,575.23159,7100.1899.8924.660.009sz3zkc69bpjh DBMS_SCHEDULER SELECT * FROM V$LIBCACHE_LOCKS...
1,790.6211,790.626.2624.820.000f1dxm6hd2c2u DBMS_SCHEDULER DECLARE job BINARY_INTEGER := ...
1,790.1811,790.186.2624.650.005vp17fw0hgrz1 DBMS_SCHEDULER DECLARE job BINARY_INTEGER := ...

Mutex Sleep Summary

Mutex TypeLocationSleepsWait Time (ms)
Library Cachekglic1 491,696,79215,671,698
Library Cachekglic4 145172,6341,423,319
Library CachekglGetHandleReference 1238,26261,133
Library CachekglReleaseHandleReference 1241,1768,110
Library Cachekglhdgn1 62971
Cursor PinkksLockDelete [KKSCHLPIN6]9138
Cursor Pinkksfbc [KKSCHLFSP2]22
Row Cache[14] kqrScan10

Top SQL with Top Row Sources

SQL IDPlan HashExecutions% ActivityRow Source% Row SourceTop Event% EventSQL Text
9sz3zkc69bpjh2131580607279498.87 FIXED TABLE - FULL49.95library cache: bucket mutex X30.36 SELECT * FROM V$LIBCACHE_LOCKS...
FIXED TABLE - FULL48.57library cache: bucket mutex X31.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)

Tuesday, July 1, 2025

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)3cfwwbgj9ft44SELECT /*+ End */ COUNT(*) FROM DUAL
6253 48.5% 6253 100% 0 N/A 100 100% HPROF_PLSQL_PROC_TEST.__static_sql_exec_line18 (Line 18)8tuspbw8fxyrnSELECT /*+ 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)3cfwwbgj9ft44SELECT /*+ End */ COUNT(*) FROM DUAL
6517 48.6% 6517 100% 0 N/A 100 100% HPROF_PLSQL_PROC_TEST.__static_sql_exec_line18 (Line 18)8tuspbw8fxyrnSELECT /*+ 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;
/