When PL/SQL is slow, the question is where the time goes: which subprogram, called how often, and how much of it is SQL. The hierarchical profiler, DBMS_HPROF, records every call between START_PROFILING and STOP_PROFILING, and ANALYZE stores the results in tables, with calls and times per function, including the SQL statements inside them.
Code for This Guide
The main examples are in the examples/pkg-performance folder of the Oracle Database 26ai code repository on GitHub, each with its output. They use NIMBUS, the sample schema of a fictional airline, which you can install with the scripts in the setup/nimbus folder.
They come from Oracle Database 26ai SQL and PL/SQL Book.
Syntax
dbms_hprof.create_tables(force_it => true); -- DBMSHP_ tables, once v_trace := dbms_hprof.start_profiling; -- the code to profile dbms_hprof.stop_profiling; v_run := dbms_hprof.analyze(trace_id => v_trace, run_comment => '...');
START_PROFILING records into DBMSHP_TRACE_DATA, and ANALYZE writes results to DBMSHP_RUNS, DBMSHP_FUNCTION_INFO, and DBMSHP_PARENT_CHILD_INFO.
Profile a Loop
The block calls ROUTE_MINUTES once per airport, and the function runs a query each time:
Setup:
create or replace function route_minutes (p_origin varchar2) return number is n number; begin select sum(block_minutes) into n from routes where origin = p_origin; return n; end; /
Example:
declare
v_trace number;
v_run number;
v_total number := 0;
begin
dbms_hprof.create_tables(force_it => true); -- DBMSHP_ tables in this schema
v_trace := dbms_hprof.start_profiling; -- profile into the database
for a in (select airport_code from airports) loop
v_total := v_total + nvl(route_minutes(a.airport_code), 0);
end loop;
dbms_hprof.stop_profiling;
v_run := dbms_hprof.analyze(trace_id => v_trace, run_comment => 'route minutes');
dbms_output.put_line('total ' || v_total);
end;
/
select function, calls
from dbmshp_function_info
where runid = (select max(runid) from dbmshp_runs)
and calls > 1
order by calls desc, function;Output:
total 24188 PL/SQL procedure successfully completed. FUNCTION CALLS __________________________ ________ ROUTE_MINUTES 22 __static_sql_exec_line1 22
The profile shows ROUTE_MINUTES called 22 times, once per airport, and the static SQL on its line 1, the SELECT, executed 22 times too. Time columns in DBMSHP_FUNCTION_INFO show where the time went. The example drops the function afterward.
Things to Know
- SQL statements appear as their own entries, so you can see how much time is SQL and how much PL/SQL.
- SUBTREE_ELAPSED_TIME includes the time of everything a function calls; FUNCTION_ELAPSED_TIME only its own.
- Profile a realistic workload, then fix the functions with the most time, not the most calls.
Cleanup of the profiler tables:
drop table dbmshp_parent_child_info cascade constraints purge; drop table dbmshp_function_info cascade constraints purge; drop table dbmshp_runs cascade constraints purge; drop table dbmshp_trace_data cascade constraints purge; drop sequence dbmshp_runnumber; drop sequence dbmshp_tracenumber;
Related Guides
Conclusion
DBMS_HPROF profiles PL/SQL call by call, SQL included, and stores calls and times per function in tables. Profile slow code, sort by time, and start tuning where the time really goes.
