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.
See my articles more often when you search Google.
