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;
/
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 733. 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; /
