This Blog will demonstrate uncatchable time in PL/SQL nested procedures and packages, which often caused misleading in elapsed time accounting, and in locating time consumption in 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;
/

On Oracle

Tuesday, July 1, 2025

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

1. Test Code

2. Test Run with Unwrapped PL/SQL

Parents and Children Elapsed Time (microsecs) Data

3. Test Run with Wrapped PL/SQL

Parents and Children Elapsed Time (microsecs) Data

4. Wrapped PL/SQL

5. PL/SQL Package Test Cdoe

Subtree	Ind%	Function	Ind%	Descendants	Ind%	Calls	Ind%	Function Name
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)

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)