Unleashing DBMS_PROFILER

Anyone who’s been involved with Oracle over the past decade has seen a huge improvement in the ability to capture performance data. We can explain, trace, debug, advise, and profile. Most of the attention still seems to be on SQL, and probably rightly so because that is the end purpose of a database, right? Select, insert, update and delete data is what it’s all about. However, what frequently goes hand in hand with SQL is (no surprise here) PL/SQL.

Quite often, performance tuning examples dwell on what’s taking place with SQL statements, and along with that, reporting on wait events. The examples show the use of explain plans, TKPROF’d trace files, and at a higher level, AWR or STATSPACK reports. But what’s going on with the PL/SQL? That’s where DBMS_PROFILER comes into play. Other utilities such as DBMS_DEBUG are related to profiling, and some tools, such as Forms Builder, enable developers to debug or step through code a line at a time.

All those “little” things you do inside a block of code – instring this, substring that, concatenate strings, over and over if inside a loop – how much time is being spent on that? By using DBMS_PROFILER, you can see where all of the time goes, and not just all of the SQL time. Further, not only can you see the results by querying from a table (or tables), but you can generate an HTML-based report with the results neatly arrayed just like within an AWR report. So, what does it take to use DBMS_PROFILER?

Oracle’s documentation mentions this built-in in two places: the PL/SQL User’s Guide and Reference guide and the PL/SQL Packages and Types Reference guide. The overview in the 10g packages and types reference guide states:

This package enables the collection of profiler (perfoprmance) [sic] data for performance improvement or for determining code coverage for PL/SQL applications. Application developers can use code coverage data to focus their incremental testing efforts.

With this interface, you can generate profiling information for all named library units that are executed in a session. The profiler gathers information at the PL/SQL virtual machine level. This information includes the total number of times each line has been executed, the total amount of time that has been spent executing that line, and the minimum and maximum times that have been spent on a particular execution of that line.

Not only do we get performance, we get “perfoprmance.” Maybe that’s undocumented performance? Anyway, the steps include installing the package (if not already done), creating three tables via a provided script, invoking the package’s subprograms (e.g., start, stop and flush), and viewing the results.

If performing “SQL> desc dbms_profiler” as SYS or SYSTEM doesn’t return any output, then install the package by running the profload.sql script as SYS in $ORACLE_HOME/rdbms/admin. To create the tables, run the proftab.sql script (same place, BUT as the user performing the profiling, NOT as SYS). This script creates three tables and one sequence, and is re-runnable (it attempts to drop the objects before creating them). The three tables are PLSQL_PROFILER_RUNS, PLSQL_PROFILER_UNITS, and PLSQL_PROFILER_DATA. The subprograms are shown below. Ref: Chapter 73 of Oracle® Database PL/SQL Packages and Types Reference 10g Release 2 (10.2)

Now that the framework is in place, we’re ready to give it a spin. Let’s use a BULK version row-by-row block of code for testing, and this comes from Example 11-3 in the 10g PL/SQL user’s guide. Instead of 500 (too small of a value, may get 0 seconds returned for the bulk step), we’ll use 500,000 iterations. On a warmed-up system, the times are around 25 seconds versus 4 seconds.

CREATE TABLE parts1 (pnum INTEGER, pname VARCHAR2(15));

CREATE TABLE parts2 (pnum INTEGER, pname VARCHAR2(15));

DECLARE

  TYPE NumTab IS TABLE OF parts1.pnum%TYPE INDEX BY PLS_INTEGER;

  TYPE NameTab IS TABLE OF parts1.pname%TYPE INDEX BY PLS_INTEGER;

  pnums  NumTab;

  pnames NameTab;

–Not big enough: iterations CONSTANT PLS_INTEGER := 500;

  iterations CONSTANT PLS_INTEGER := 500000;

  t1 INTEGER;

  t2 INTEGER;

  t3 INTEGER;

BEGIN

  FOR j IN 1..iterations LOOP  — load index-by tables

     pnums(j) := j;

     pnames(j) := ‘Part No. ‘ || TO_CHAR(j);

  END LOOP;

  t1 := DBMS_UTILITY.get_time;

  FOR i IN 1..iterations LOOP  — use FOR loop

     INSERT INTO parts1 VALUES (pnums(i), pnames(i));

  END LOOP;

  t2 := DBMS_UTILITY.get_time;

  FORALL i IN 1..iterations  — use FORALL statement

     INSERT INTO parts2 VALUES (pnums(i), pnames(i));

  t3 := DBMS_UTILITY.get_time;

  DBMS_OUTPUT.PUT_LINE(‘Execution Time (secs)’);

  DBMS_OUTPUT.PUT_LINE(‘———————‘);

  DBMS_OUTPUT.PUT_LINE(‘FOR loop: ‘ || TO_CHAR((t2 – t1)/100));

  DBMS_OUTPUT.PUT_LINE(‘FORALL:   ‘ || TO_CHAR((t3 – t2)/100));

  COMMIT;

END;

/

The other modification that needs to be made is the addition of the start and stop calls for DBMS_PROFILER. Add in “DBMS_PROFILER.START_PROFILER(sysdate, ‘where’);” and “DBMS_PROFILER.STOP_PROFILER” statements where appropriate and repeat the run (create the tables once, then add delete or truncate statements at the beginning). In the example below (only the BEGIN section is shown, DECLARE stays the same except for adding two “run” variables), I added three captures: time to load the tables, and times for each of the inserts.

  run_comment VARCHAR2(30) := to_char(sysdate);

  run_comment1 VARCHAR2(30);

BEGIN

  DBMS_PROFILER.START_PROFILER

  (run_comment,’Load tables’);

  FOR j IN 1..iterations LOOP  — load index-by tables

     pnums(j) := j;

     pnames(j) := ‘Part No. ‘ || TO_CHAR(j);

  END LOOP;

  DBMS_PROFILER.STOP_PROFILER;

  t1 := DBMS_UTILITY.get_time;

  DBMS_PROFILER.START_PROFILER(run_comment,’For Loop’);

  FOR i IN 1..iterations LOOP  — use FOR loop

     INSERT INTO parts1 VALUES (pnums(i), pnames(i));

  END LOOP;

  DBMS_PROFILER.STOP_PROFILER;

  t2 := DBMS_UTILITY.get_time;

  DBMS_PROFILER.START_PROFILER(run_comment,’Forall’);

  FORALL i IN 1..iterations  — use FORALL statement

     INSERT INTO parts2 VALUES (pnums(i), pnames(i));

  DBMS_PROFILER.STOP_PROFILER;

  t3 := DBMS_UTILITY.get_time;

  DBMS_OUTPUT.PUT_LINE(‘Execution Time (secs)’);

  DBMS_OUTPUT.PUT_LINE(‘———————‘);

  DBMS_OUTPUT.PUT_LINE(‘FOR loop: ‘ || TO_CHAR((t2 – t1)/100));

  DBMS_OUTPUT.PUT_LINE(‘FORALL:   ‘ || TO_CHAR((t3 – t2)/100));

  COMMIT;

END;

/

What are the results? We could query the tables directly, but that’s not very interesting. Using Toad, the data appears as so:

Kind of dull in a way. But there is a way to have the format shown in HTML. MetaLink note 243755.1, “Implementing and Using the PL/SQL Profiler,” contains a downloadable ZIP file, with a SQL script to take a run and generate HTML output. You can run profiler.sql as is and enter a run ID, or pass the ID in as a parameter.

SQL> @profiler

     RUNID RUN_DATE           RUN_COMMENT

———- —————— ———–

         2 17-SEP-08 17:36:28 17-SEP-08

         3 17-SEP-08 17:36:29 17-SEP-08

         4 17-SEP-08 17:36:59 17-SEP-08

Usage:

sqlplus apps/

SQL> START profiler.sql 

Enter value for 1:

The script generates a file named profiler_X.html, with X being the selected run ID. The contents of run ID 3 (using the for loop) appear as so:

Looks better, but what happened statement by statement? For that, we need to add in one item, and that is compile with debug. I’ll turn the anonymous block into a procedure and capture the start and stop overall for the looping process (don’t care about the inserts as that is overhead for both parts).

CREATE or REPLACE PROCEDURE profiler_demo

AS

  TYPE NumTab IS TABLE OF parts1.pnum%TYPE INDEX BY PLS_INTEGER;

  TYPE NameTab IS TABLE OF parts1.pname%TYPE INDEX BY PLS_INTEGER;

  pnums  NumTab;

  pnames NameTab;

  iterations CONSTANT PLS_INTEGER := 500000;

  t1 INTEGER;

  t2 INTEGER;

  t3 INTEGER;

  run_comment VARCHAR2(30) := to_char(sysdate);

  run_comment1 VARCHAR2(30);

BEGIN

  execute immediate ‘truncate table parts1 reuse storage’;

  execute immediate ‘truncate table parts2 reuse storage’;

  FOR j IN 1..iterations LOOP  — load index-by tables

     pnums(j) := j;

     pnames(j) := ‘Part No. ‘ || TO_CHAR(j);

  END LOOP;

  t1 := DBMS_UTILITY.get_time;

  DBMS_PROFILER.START_PROFILER(run_comment,’Start of Loops’);

  FOR i IN 1..iterations LOOP  — use FOR loop

     INSERT INTO parts1 VALUES (pnums(i), pnames(i));

  END LOOP;

  t2 := DBMS_UTILITY.get_time;

  FORALL i IN 1..iterations  — use FORALL statement

     INSERT INTO parts2 VALUES (pnums(i), pnames(i));

  DBMS_PROFILER.STOP_PROFILER;

  t3 := DBMS_UTILITY.get_time;

  DBMS_OUTPUT.PUT_LINE(‘Execution Time (secs)’);

  DBMS_OUTPUT.PUT_LINE(‘———————‘);

  DBMS_OUTPUT.PUT_LINE(‘FOR loop: ‘ || TO_CHAR((t2 – t1)/100));

  DBMS_OUTPUT.PUT_LINE(‘FORALL:   ‘ || TO_CHAR((t3 – t2)/100));

  COMMIT;

END;

/

Compile the procedure with DEBUG (alter procedure profiler_demo compile_debug) and then run profiler again. The output will be exactly what we’re looking for in terms of line by line detail and timings. You have to admit this is MUCH better than pouring through a formatted trace file to see where all of the time went.

In Closing

The DBMS_PROFILER package has been around since at least Oracle8i days. For some reason, it seems to get short shrift in many of the tuning books and online discussion forums. After seeing how easy it is to implement, perhaps you’ll add this built-in to your tuning arsenal. Other variations of using this include joining the profiler tables to USER_SOURCE or ALL_SOURCE yourself (which is what takes place in the profiler script; use that as a starting point if so desired), drilling down to the worst or most time consuming lines, and using three scripts contained in the plsql/demo directory (profdemo, profrep and profsum.sql).

Also buried inside the demo directory are the remnants of a Java-based viewing utility. There was a profview.html in older versions (not present at least in 10g Windows), a Windows batch file (profview_nt.bat), and a jar file (profview.jar). The batch file will error out with a failure to load the Main-Class manifest from profview.jar. The command to run the viewer (assuming you can fix the manifest error, or happen to have an older version of this and want to modernize it) is java riw. Overall, the HTML output is probably the easiest and quickest means of viewing the profile information in a better-than-text-only interface.

» See All Articles by Columnist Steve Callan