-
July 2025 (2)
-
June 2025 (1)
-
May 2025 (1)
-
February 2025 (1)
-
November 2024 (1)
-
October 2024 (1)
-
September 2024 (1)
-
April 2024 (3)
-
January 2024 (1)
-
October 2023 (1)
-
September 2023 (3)
-
August 2023 (1)
-
June 2023 (1)
-
April 2023 (3)
-
March 2023 (2)
-
February 2023 (1)
-
January 2023 (1)
-
December 2022 (2)
-
October 2022 (2)
-
September 2022 (2)
-
August 2022 (2)
-
July 2022 (1)
-
June 2022 (1)
-
May 2022 (2)
-
April 2022 (2)
-
March 2022 (1)
-
February 2022 (2)
-
January 2022 (1)
-
December 2021 (1)
-
November 2021 (1)
-
October 2021 (2)
-
July 2021 (1)
-
June 2021 (1)
-
May 2021 (1)
-
April 2021 (3)
-
March 2021 (2)
-
January 2021 (1)
-
November 2020 (3)
-
September 2020 (1)
-
August 2020 (1)
-
May 2020 (3)
-
April 2020 (3)
-
February 2020 (2)
-
January 2020 (1)
-
December 2019 (2)
-
August 2019 (2)
-
April 2019 (1)
-
November 2018 (5)
- Oracle row cache objects Event: 10222, Dtrace Script (I)
- Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-1) (II)
- Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-2) (III)
- Row Cache and Sql Executions (IV)
- Latch: row cache objects Contentions and Scalability (V)
-
October 2018 (2)
-
July 2018 (3)
-
April 2018 (1)
-
March 2018 (2)
-
February 2018 (1)
-
January 2018 (4)
-
October 2017 (2)
-
September 2017 (2)
-
July 2017 (3)
-
May 2017 (8)
- JDBC, Oracle object/collection, dbms_pickler, NOPARALLEL sys.type$ query
- PLSQL Context Switch Functions and Cost
- Oracle Datetime (1) - Concepts
- Oracle Datetime (2) - Examples
- Oracle Datetime (3) - Assignments
- Oracle Datetime (4) - Comparisons
- Oracle Datetime (5) - SQL Arithmetic
- Oracle Datetime (6) - PLSQL Arithmetic
-
March 2017 (3)
-
February 2017 (1)
-
January 2017 (1)
-
November 2016 (1)
-
September 2016 (2)
-
August 2016 (1)
-
June 2016 (1)
-
May 2016 (1)
-
April 2016 (1)
-
February 2016 (1)
-
January 2016 (3)
-
December 2015 (1)
-
November 2015 (1)
-
September 2015 (2)
-
August 2015 (1)
-
July 2015 (2)
-
June 2015 (1)
-
April 2015 (2)
-
January 2015 (1)
-
December 2014 (1)
-
November 2014 (2)
-
May 2014 (3)
-
March 2014 (2)
-
November 2013 (3)
-
September 2013 (1)
-
June 2013 (2)
-
April 2013 (2)
-
March 2013 (3)
-
December 2012 (1)
-
November 2012 (2)
-
July 2012 (1)
-
May 2012 (1)
-
April 2012 (1)
-
February 2012 (1)
-
November 2011 (2)
-
July 2011 (1)
-
May 2011 (3)
-
April 2011 (1)
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.
In the following code, we query V$LIBCACHE_LOCKS (similar behavior for DBA_KGLLOCK), which is a union of X$KGLLK and X$KGLPN.
Run a test with 16 Jobs:
During the test, we can monitor "library cache: bucket mutex X" waits by:
Open one Sqlplus window, execute bpftrace on its process (UNIX pid 293988):
If we query normal tables, there are much less kglGetBucketMutex and kglGetMutex:
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).
(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)
(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)
We can also use following GDB script to trace "library cache: bucket mutex X":
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).
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 |
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.
In following code, we have one procedure which calls a nested procedure:
Run above procedure with dbms_hprof, and create html hprofile:
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.
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)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 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) Look HProf raw file, we can see that time "P#X 139321" is not attributed to any program (PL/SQL or SQL):
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 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:HProf shows that the top call: HPROF_PLSQL_PROC_TEST has time = 12865442, but all its Children has only 13408.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; /
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; /
Subscribe to:
Posts (Atom)