dbms_profiler

dbms_profiler

Click here for the paper I presented at IOUG in 2006 on Trace Analyzer.

 

PL/SQL developers are always trying to optimize their code to perform more efficiently.  As of Oracle 8.1.5, a utility exists that assists developers with this process, dbms_profiler, one of the most under-utilized utilities within Oracle.  

 

The basic idea behind profiling is for the developer to understand where their code is spending the most time, so they can detect and optimize it.  The profiling utility allows Oracle to collect data in memory structures and then dumps it into tables as application code is executed.  dbms_profiler is to PL/SQL, what tkprof and Explain Plan are to SQL. 

Installation

The profiling tools are not a part of the base installation of Oracle, so that will require more on the part of the developer.  Two tables need to be installed along with the Oracle supplied PL/SQL package. 

 

In the $ORACLE_HOME/rdbms/admin directory, two files exist that create the environment needed for the profiler to execute. 

 

·     proftab.sql - Creates three tables and a sequence and must be executed before the profload.sql file.

·     profload.sql - Creates the package header and package body for DBMS_PROFILER.  This script must be executed as the SYS user.

Once the environment is established, the three tables created by proftab.sql contain the vital information needed to benchmark PL/SQL performance.   Queries against these tables will provide the insight needed to optimize the PL/SQL code. 

 

The plsql_profiler_runs table contains information related to a profiling session.  Things, such as when the run was started, who started it, and how long the run lasted are contained in this table.  This table has the following important columns:

 

·     runid - This is the unique run identifier given to each profiler execution.

·     related_run - Runid of related run that can be called by the programmer.

·     run_owner - User who started the run.

·     run_date - Timestamp of the date of the run.

·     run_comment – User provided text concerning anything about this run that they wish to specify.  This is used mainly for documentation, since run_id is hard to remember.

·     run_total_time – Total elapsed time for this run.

The plsql_profiler_units table defines each PL/SQL component (unit) that was executed during a profiler run.  Benchmarks for each of the units are stored in this table in the following columns:

 

·     runid - References plsql_profiler_runs(runid).

·     unit_number - Internally generated library unit number.

·     unit_type - Library unit type (PACKAGE, PROCEDURE, etc).

·     unit_owner - Library unit owner name (the owner of the object).

·     unit_name - Library unit name (the name of the object as defined in the user_objects view).

·     unit_timestamp – Time when the unit was created.  The “unit”, being the procedural object (procedure, function, package).  This column holds the same data as the created column in the user_objects view.

·     total_time – Total time used by this unit for the given run.

The primary key for this table is runid, unit_number.

 

The plsql_profiler_data table is where the real performance benchmarks are stored.  This table contains the execution statistics for each line of code contained in our PL/SQL unit.  This table can be joined to the user_source view and can extract the actual line of code for each benchmark.  The primary key includes runid, unit_number, and line#.

 

The plsql_profiler_data table has the following important columns as indicated by the results of the following query:

 

select runid, unit_number, line#, total_occur, total_time,   

       min_time, max_time

from plsql_profiler_data;

 

 

     RUNID UNIT_NUMBER      LINE# TOTAL_OCCUR TOTAL_TIME   MIN_TIME   MAX_TIME

---------- ----------- ---------- ----------- ---------- ---------- ----------

         1           1          8           3   33284677     539733   28918759

         1           1         80           2    1134222     516266     617955

         1           1         89           0          0          0          0

         1           1         90           0          0          0          0

         1           1         92           0          0          0          0

         1           1         95           0          0          0          0

         1           1        103           0          0          0          0

         1           1        111           0          0          0          0

         1           1        112           0          0          0          0

         1           1        116           1    1441523    1441523    1441523

         1           1        119           0          0          0          0

         1           1        121           1    1431466    1431466    1431466

         1           1        123           1     136330     136330     136330

         1           1        132           1     978895     978895     978895

         1           1        140           0          0          0          0

         1           1        141           0          0          0          0

         1           1        143           0          0          0          0

         1           1        146           1    2905397    2905397    2905397

         1           1        152           2    1622552     574374    1048177

         1           1        153           0          0          0          0

         1           1        157           1     204495     204495     204495

         1           1        160           0          0          0          0

 

The line# above is used to tie these execution benchmarks back to a line of source in the user_source view.

 

The profload.sql file contains calls to two other files:

 

·     dbmspbp.sql – This file creates the actual sys.dbms_profiler package.  This must be created as the SYS user which is the main drawback of this utility.

·     prvtpbp.plb – This file creates the sys.dbms_profiler_lib library object and it is wrapped.  Again, this must be executed as the SYS user.

Figure 8.1 depicts the relationships between the three profiler tables, as well as the indirect relationship to the dba_source or user_source view (Source).  Note that everything begins with a RUN and drills down to the real performance data for a particular PL/SQL line of code. 

 

 

Figure 8.1 – Relationships between dbms_profiler tables

The environment is now configured, and the profiling utility is ready to be put to work.    

Starting a Profiling Session

The profiler does not begin capturing performance information until the call to start_profiler is executed. 

 

SQL> exec dbms_profiler.start_profiler('Test of raise procedure by Scott');

 

PL/SQL procedure successfully completed.

 

The profiler captures data on a session-by-session basis.  This means that if the user SCOTT started the profiler by executing the command above, only PL/SQL objects that were executed and owned by SCOTT[M1]  will be profiled, and consequently have data in the profiler tables described earlier.  The SCOTT user is only used as an example; it could be any database user.

Flushing Data during a Profiling Session

The flush command enables the developer to dump statistics during program execution without stopping the profiling utility.  The only other time Oracle saves data to the underlying tables is when the profiling session is stopped, as shown below: 

 

SQL> exec dbms_profiler.flush_data();

 

PL/SQL procedure successfully completed.

 

A developer could use the flush procedure with dbms_debug and step, line by line, through a procedure, flushing performance benchmarks along the way.   Or, if you have a very long running PL/SQL program, flushing data can be very useful in the performance tuning process.

Stopping a Profiling Session

Stopping a profiler execution is done after an adequate period of time of gathering performance benchmarks – determined by the developer.  Once the developer stops the profiler, all the remaining (unflushed) data is loaded into the profiler tables.

 

SQL> exec dbms_profiler.stop_profiler();

 

PL/SQL procedure successfully completed.

 

The dbms_profiler package also provides procedures that suspend and resume profiling (pause_profiler(), resume_profiler()).

 

Now that the profiler has stopped, the data is available for diagnostics from within Oracle, and we can begin working with it.

Working with Captured Profiler Data

The profiler utility populates three tables with information, plsql_profiler_runs, plsql_profiler_units, and plsql_profiler_data.  Each “run” is initiated by a user and contains zero or more “units”.  Each unit contains “data” about its execution – the guts of the performance data benchmarks. 

 

The performance information for a line in a unit needs to be tied back to the line source in user_source.  Once that join is made, the developer will have all of the information that they need to optimize, enhance, and tune their application code, as well as the SQL.

Useful Scripts

To extract high-level data, including the length of a particular run, the script (profiler_runs.sql) below can be executed:

 

< profiler_runs.sql

 

column runid format 990

column type format a15

column run_comment format a20

column object_name format a20

 

select a.runid,

     substr(b.run_comment, 1, 20) as run_comment,

     decode(a.unit_name, '', '<anonymous>',

           substr(a.unit_name,1, 20)) as object_name,

     TO_CHAR(a.total_time/1000000000, '99999.99') as sec,

     TO_CHAR(100*a.total_time/b.run_total_time, '999.9') as pct

     from plsql_profiler_units a, plsql_profiler_runs b

     where a.runid=b.runid

     order by a.runid asc;

 

 

RUNID UNIT_NUMBER OBJECT_NAME          TYPE            SEC       PCT

----- ----------- -------------------- --------------- --------- ------

    1           1 <anonymous>                                .00     .0

    1           2 <anonymous>                               1.01     .0

    1           3 BMC$PKKPKG           PACKAGE BODY      6921.55   18.2

    1           4 <anonymous>                                .02     .0

    2           1 <anonymous>                                .00     .0

    2           2 <anonymous>                                .01     .0

 

6 rows selected.

 

 

Note that anonymous PL/SQL blocks are also included in the profiler tables.  Anonymous blocks are less useful from a tuning perspective since they cannot be tied back to a source object in user_source.  Anonymous PL/SQL blocks are simply runtime source objects and do not have a corresponding dictionary object (package, procedure, function).  For this reason, the anonymous blocks should be eliminated from most reports.

 

From the data displayed above, the next step is to focus on the lines within the package body, testproc, that are taking the longest.  The script (profiler_top10_lines.sql) below displays the line numbers and their performance benchmarks of the top 10 worst performing lines of code.

 

 

< profiler_top10_lines.sql

 

select line#, total_occur, 

  decode (total_occur,null,0,0,0,total_time/total_occur/1000,0) as avg,

  decode(total_time,null,0,total_time/1000) as total_time,

  decode(min_time,null,0,min_time/1000) as min,

  decode(max_time,null,0,max_time/1000) as max

  from plsql_profiler_data

  where runid = 1  

  and unit_number = 3       -- testproc

  and rownum < 11           -- only show Top 10

  order by total_time desc ;

 

 

     LINE# TOTAL_OCCUR        AVG TOTAL_TIME        MIN        MAX

---------- ----------- ---------- ---------- ---------- ----------

       156           1              5008.457   5008.457   5008.457

        27           1               721.879    721.879    721.879

      2113           1               282.717    282.717    282.717

        89           1               138.565    138.565    138.565

      2002           1               112.863    112.863    112.863

      1233           1                94.984     94.984     94.984

        61           1                94.984     94.984     94.984

       866           1                94.984     94.984     94.984

       481           1                92.749     92.749     92.749

       990           1                90.514     90.514     90.514

 

10 rows selected.

 

Taking it one step further, the query below (profiler_line_source.sql) will extract the actual source code for the top 10 worst performing lines. 

 

< profiler_line_source.sql

 

 select line#,

  decode (a.total_occur,null,0,0,0,           

  a.total_time/a.total_occur/1000) as Avg,

  substr(c.text,1,20) as Source

  from plsql_profiler_data a, plsql_profiler_units b, user_source c

     where a.runid       = 1  

     and a.unit_number   = 3

     and a.runid         = b.runid

     and a.unit_number   = b.unit_number

     and b.unit_name     = c.name

     and a.line#         = c.line

     and rownum          < 11  

     order by a.total_time desc ;

 

 

 

 

     LINE#        AVG SOURCE

---------- ---------- --------------------

       156   5008.457   select sum(bytes) into reusable_var from dba_free_space;

        27    721.879   execute immediate dml_str USING  current_time

      2113    282.717   select OBJ#, TYPE# from SYS.OBJ$;

        89    138.565   OBJ_TYPES(BOBJ(I)) := BTYP(I);

      2002    112.863   select count(*) into reusable_var from dba_objects

      1233     94.984   delete from pkk_daily_activity

        61     94.984   update_stats_table(33, reusable_var, null);

       866     94.984   latest_executions := reusable_var - total_executions;

       481     92.749   time_number := hours + round(minutes * 100/60/100,2);

       990     90.514   update_stats_table(45, LOBS, null); 

 

10 rows selected.

 

 

Notice from the output above that most of the information needed to diagnose and fix PL/SQL performance issues is provided.  For lines containing SQL statements, the tuner can optimize the SQL perhaps by adding optimizer hints, eliminating full table scans, etc.  Consult Chapter 5 for more details on using tkprof utility to diagnose SQL issues.

 

Other useful scripts that are hidden within the Oracle directory structure ($ORACLE_HOME/PLSQL/DEMO) include a few gems that help report and analyze profiler information.  

 

·     profdemo.sql -A demo script for collecting PL/SQL profiler data.

·     profsum.sql - A collection of useful SQL scripts that are executed against profiler tables. 

·     profrep.sql – Creates views and a package (unwrapped) that populates the views based on the three underlying profiler tables. 

Best Practices for Using dbms_profiler  Everywhere

·     Wrap only for production - Wrapping code is desired for production environments but not for profiling.  It is much easier to see the unencrypted form of the text in our reports than it is to connect line numbers to source versions.  Use dbms_profiler before you wrap your code in a test environment, wrap it, and then put it in production.     

·     Eliminate system packages most of the time - Knowing the performance data for internal Oracle processing does not buy you much since you cannot change anything.  However, knowing the performance problem is within the system packages will save you some time of trying to tune your own code when the problem is elsewhere.

·     When analyzing lines of code, it is best to concentrate on the following:

 

·     Lines of code that are frequently executed - For example, a loop that executes 5000 times is a great candidate for tuning.  Guru Oracle tuners typically look for that “low hanging fruit” in which one line or a group of lines of code are executed much more than others.  The benefits of tuning one line of code that is executed often far outweigh tuning those lines that may cost more yet are executed infrequently in comparison.

·     Lines of code with a high value[M2]  for average time executed – The minimum and maximum values of execution time are interesting although not as useful as the average execution time.  Min and max only tell us how much the execution time varies depending on database activity.  Line by line, a PL/SQL developer should focus on those lines that cost the most on an average execution basis.  dbms_profiler does not provide the average, but it does provide enough data to allow it to be computed (Total Execution Time / # Times Executed).

·     Lines of code that contain SQL syntax - The main resource consumers are those lines that execute SQL.  Once the data is sorted by average execution time, the statements that are the worst usually contain SQL.  Optimize and tune the SQL through utilities, such as Explain Plan, tkprof, and third party software.