The basic idea behind profiling with dbms_profiler 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. 

The dbms_profiler procedures are not a part of the base installation of Oracle.  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.

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 plsql_profiler_data table is where the real performance benchmarks are stored from executing dbms_profiler.  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

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.

Using the dbms_profiler Scripts

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

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

 

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.

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. 

 select line#,
  decode (a.total_occur,null,0,0,0,           
  a.total_time/a.total_occur/1000) as Avg,

See code depot

  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  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.