-
July 2025 (1)
-
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)
Tuesday, July 1, 2025
Oracle dbms_hprof: Uncatchable Time in PL/SQL Nested Program Units
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.
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.
HPROF_PLSQL_PROC_TEST.HPROF_PLSQL_PROC_TEST.PROC_NESTED (Line 13)
Look HProf raw file, we can see that time "P#X 139321" is not attributed to any program (PL/SQL or SQL):
The unaccounted time amounts to 12852034 (12865442-13408), almost no time is profiled.
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) |
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:
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;
/
Subscribe to:
Posts (Atom)