IT Training Courses
Microsoft Gold IT Training Partner
800-326-1044
IT Training Newsletters Developer's Corner

Developer's Corner

Oracle PL/SQL Debugging Tools

Part I: Using DBMS_TRACE

by Mike Marion
SQLSoft+ Senior Instructor/Developer

As the Oracle PL/SQL developer's first debugging tool, the DBMS_OUTPUT package is easy enough to use. The PUT_LINE procedure allows you to display debugging messages composed of any combination of string literals and variable values from any place in your code at anytime. It's enough to make an old coder (like me) wax poetically about the COBOL DISPLAY command! You can even turn the debugging messages on and off dynamically in your code using the ENABLE and DISABLE procedures. But eventually, you will run into the limitations and issues of DBMS_OUTPUT, including:

  • Maximum debugging buffer size is 1,000,000 bytes.
  • Tells you what the values of your variables are, but not necessarily how they got to be that way.
  • Proliferation of DBMS_OUTPUT.PUT_LINE calls obfuscates the work of the actual code.

What Debugging Tools Are Available?

First of all, we are not going to discuss SQL debugging tools. We will save the discussion of TKPROF, AUTOTRACE, Explain Plan and the like for another set of articles. And, we will also not be discussing any of the various trace facilities available to the DBA to watch the execution of the internal components of the database server itself.

So our hunt for PL/SQL debugging tools (other than DBMS_OUTPUT) begins. Alright, maybe our DBA knows some good tools, or maybe we'll ask our peer group… SQL*Navigator, Toad, PL/SQL Developer, even Oracle Forms and Reports… All of these are excellent GUI development environments. All include wonderful debugging tools, but none are free, and your boss is out of budget. Well, how do these GUIs get all of this information? Believe or not, Oracle does provide some useful tools for finding out what our PL/SQL code is doing. The two most useful are:

  • DBMS_PROFILER – This package compiles statistics about your test runs, the program units executed, and the lines of code executed. At the line level, you get to see how many times a particular line was executed, the total amount of time those executions took, and the minimum and maximum execution times for the given line. Because these stats are stored in permanent tables, you can compare different runs of the same code over time to see (any) improvement.
  • DBMS_TRACE – This package allows you to see the actual execution sequence of the lines of code as they were executed within a program unit for a particular run. You have options as to the type(s) of lines you want to trace: calls to procedures and functions only, exceptions only, SQL statements only, or any combination (or all) of the above. Again, this information is stored in permanent tables so you can compare runs from different times.

Each of these tools demands a discussion of its own. Each one needs a lot of setup, much of it requiring the privileges of the DBA. I will discuss DBMS_TRACE (the shorter discussion) in this article. I will save DBMS_PROFILER for an upcoming Developer's Corner.

Warning: This article is an overview of the processes and tasks involved when using DBMS_TRACE. It is not an exhaustive discussion of all the options and settings available. Nor is this article a detailed, step-by-step description of all the processes and tasks involved. If you are interested is pursuing such information, please consider SQLSoft+'s course ora10g102, Oracle Database 10g: PL/SQL Application Tuning. That 4-day course provides the working knowledge you need to perform the tracing of your code.

Features of the DBMS_TRACE Package

The DBMS_TRACE Package has many features to control the tracing of your code. You can imagine that trying to debug parts of large systems can generate large volumes to trace information at the line level. These features give you granular control over what program units are traced during you test run.

  • You control when the trace starts and ends with procedure calls.
  • When the trace is started, you specify what types of statements to trace.
  • You can pause and resume the tracing at any point(s) you desire.
  • You can place comments on your runs to differentiate them later.
  • You can place an approximate limit on the total number of trace records generated.
  • Only program units compiled with the DEBUG option are traced.
  • You can verify that the DBMS_TRACE version matches the database version. Incompatibility here can cause issues during debugging runs.

DBA Setup Tasks

Your DBA must prepare the Oracle Server to allow PL/SQL tracing. This includes the following tasks, which must be done while logged into the SYS user:

  • Execute the script (found in the administrator directory of the server) that installs the DBMS_TRACE package. The script will also create the appropriate public synonym and grant the execute privileges necessary.
  • Execute the script (found in the administrator directory of the server) that installs the PLSQL_TRACE tables used by everyone. The script drop the tables first (those drop commands will fail the first time the script is run).
  • Manually create the synonyms for the PLSQL_TRACE tables, and grant the necessary Select, Insert, Update and Delete privileges to the appropriate developers.

At this point, developers (that have been granted the privileges mentioned above) can start making debugging runs.

Enable Modules for Trace

Each program unit (procedure, function, or package) you wish to debug must be enabled for tracing. To accomplish that, the program unit must be compiled with the DEBUG option. (You can also set the session debug flag on, so that all compiles done in the session automatically have the DEBUG option.) Package specifications and bodies can be enabled separately, if desired. The easiest way to do this is probably an ALTER command such as the following:

SQL> ALTER PACKAGE personnel COMPILE DEBUG;
Package altered.
SQL> ALTER PACKAGE personnel COMPILE DEBUG BODY;
Package body altered.

Set the Trace Options

Setting the "focus" of the trace run is done when you start tracing. This is accomplished by calling the DBMS_TRACE.SET_PLSQL_TRACE procedure. You have several options for setting focus:

trace_all_calls trace_enabled_calls
trace_all_exceptions trace_enabled_exceptions
trace_all_sql trace_enabled_sql
trace_all_lines trace_enabled_lines

The options are actually constants in the DBMS_TRACE package, and they are additive. They are like bit switches. You can add these constants together to get any combination of settings. Note: if you specify both a trace_all_ option and a trace_enabled_ option, the "all" option wins.

SQL> exec DBMS_TRACE.set_plsql_trace(DBMS_TRACE.trace_all_lines
      + DBMS_TRACE.trace_all_sql + DBMS_TRACE.trace_all_calls);

PL/SQL procedure successfully completed.

Limit the Trace Lines

If you are concerned about how many trace lines will be generated, you can put an approximate limit on the number of lines allowed during this trace run.

SQL> exec DBMS_TRACE.limit_plsql_trace(5000);
PL/SQL procedure successfully completed.

Run the Test

Now, run the program unit you want to debug. This will place the trace lines in the trace tables for later querying. Then stop the tracing when done.

SQL> exec DBMS_TRACE.set_plsql_trace(DBMS_TRACE.trace_all_lines
      + DBMS_TRACE.trace_all_sql + DBMS_TRACE.trace_all_calls);
PL/SQL procedure successfully completed.
SQL> exec personnel.fire_employee(123456789);
PL/SQL procedure successfully completed.
SQL> exec DBMS_TRACE.clear_plsql_trace;
PL/SQL procedure successfully completed.

Pause/Resume Trace

When desired, you can pause and resume the trace around a procedure or function call to eliminate unwanted trace lines from program units you don't need to debug…

SQL> exec DBMS_TRACE.pause_plsql_trace;
PL/SQL procedure successfully completed.
SQL> exec personnel.fire_employee(123456789);
PL/SQL procedure successfully completed.
SQL> exec DBMS_TRACE.resume_plsql_trace;
PL/SQL procedure successfully completed.

Run Number and Comment

When your test/trace is done, you will need to know what trace runnumber was assigned to the run by DBMS_TRACE. To find this out, run the GET_PLSQL_TRACE_RUNNUMBER function. In the example below, the current runnumber is displayed to the SQL*Plus session for future use.

You can also place a comment on the run. Use the COMMENT_PLSQL_TRACE procedure. This comment is available later, so you can remember what you did.

BEGIN
   DBMS_TRACE.set_plsql_trace(DBMS_TRACE.trace_all_lines);
   DBMS_TRACE.comment_plsql_trace(‘Trace of firing procedure’);
   DBMS_OUTPUT.put_line('Trace#'||
       DBMS_TRACE.get_plsql_trace_runnumber||' is starting...');


   personnel.fire_employee(123456789);

   DBMS_TRACE.clear_plsql_trace;
END;
/
Trace #3 is starting...
PL/SQL procedure successfully completed.

Extract Trace Information

Once the CLEAR_PLSQL_TRACE procedure stops the run, you can then execute queries to see what happened. The first stop is the PLSQL_TRACE_RUNS table. To see what runs are available, who ran them and when, try a query like this:

SQL> col run_owner format a12
SQL> col run_comment format a20 word_wrapped
SQL> SELECT runid, to_char(run_date,'mm/dd/yy hh24:mi:ss') run_time
  2   run_owner, run_comment
  3  FROM plsql_trace_runs
  4  ORDER BY runid;

     RUNID RUN_TIME          RUN_OWNER    RUN_COMMENT
---------- ----------------- ------------ --------------------
         1 12/05/05 22:01:01 PLSQL100
         2 12/05/05 22:22:39 PLSQL100
         3 12/05/05 22:23:00 PLSQL100
         4 12/05/05 22:36:31 PLSQL100
         5 12/05/05 22:39:08 PLSQL100     Trace of firing procedure

To see the execution sequence of the lines of code, you need to look at the PLSQL_TRACE_EVENTS table. For example, use a scattergun approach to see the lines of code executed during the run…

SQL> col comm format a30 word_wrapped heading 'Command'
SQL> col seq format 999
SQL> col calling format a32
SQL> col ekind format 999
SQL> col eline format 999
SQL> SELECT event_seq seq, event_line eline, event_kind ekind,
  2   event_unit||'.'||event_proc_name calling, event_comment comm
  3  FROM plsql_trace_events
  4  WHERE runid = 5
  5  AND ekind != 51 –-this eliminates a lot of clutter
  6  ORDER BY event_seq;

 SEQ ELINE EKIND CALLING                      Command
---- ----- ----- ---------------------------- --------------------------
   1          38 .                            PL/SQL Trace Tool started
   2          40 .                            Trace flags changed
   3    21    50 DBMS_TRACE.                  Return from procedure call
   6    67    50 DBMS_TRACE.                  Return from procedure call
   8    72    50 DBMS_TRACE.                  Return from procedure call
  10     4    45 <anonymous>.                 Procedure Call
  13   109    45 DBMS_TRACE.                  Procedure Call
  15    57    45 DBMS_TRACE.                  Procedure Call
  17    12    50 DBMS_TRACE.                  Return from procedure call
  20    58    50 DBMS_TRACE.                  Return from procedure call
  24   112    45 DBMS_TRACE.                  Procedure Call
  26    30    50 DBMS_TRACE.                  Return from procedure call
  29   113    50 DBMS_TRACE.                  Return from procedure call
  31     4    45 <anonymous>.                 Procedure Call
  39   121    45 DBMS_OUTPUT.                 Procedure Call
  55   173    50 DBMS_OUTPUT.                 Return from procedure call
  57   123    50 DBMS_OUTPUT.                 Return from procedure call
  59     6    45 <anonymous>.                 Procedure Call
  62   119    45 DBMS_TRACE.                  Procedure Call
  64    57    45 DBMS_TRACE.                  Procedure Call
  66    12    50 DBMS_TRACE.                  Return from procedure call
  69    58    50 DBMS_TRACE.                  Return from procedure call
  73   122    45 DBMS_TRACE.                  Procedure Call
  75    56       .                            Trace of firing procedure
  76    48    50 DBMS_TRACE.                  Return from procedure call
  78   123    50 DBMS_TRACE.                  Return from procedure call
  80     7    45 <anonymous>.                 Procedure Call
  84    71    45 PERSONNEL.FIRE_EMPLOYEE      Procedure Call
  88     8    54 PERSONNEL.IS_MANAGER         SELECT COUNT(MGRSSN) FROM
                                              DEPARTMENT WHERE MGRSSN =                                               :B1
  92    18    50 PERSONNEL.IS_MANAGER         Return from procedure call
  96    71    45 PERSONNEL.FIRE_EMPLOYEE      Procedure Call
 100    25    54 PERSONNEL.IS_SUPERVISOR      SELECT COUNT(SUPERSSN)                                               FROM EMPLOYEE WHERE                                               SUPERSSN = :B1
 104    35    50 PERSONNEL.IS_SUPERVISOR      Return from procedure call
 109    75    54 PERSONNEL.FIRE_EMPLOYEE      DELETE FROM EMPLOYEE WHERE                                               SSN = :B1
 111    76    45 PERSONNEL.FIRE_EMPLOYEE      Procedure Call
 115    40    54 PERSONNEL.CLEAR_DEPENDENTS   DELETE FROM DEPENDENT                                               WHERE ESSN = :B1
 117    43    50 PERSONNEL.CLEAR_DEPENDENTS   Return from procedure call
 119    77    45 PERSONNEL.FIRE_EMPLOYEE      Procedure Call
 123    48    54 PERSONNEL.CLEAR_EMPLOYMENT   DELETE FROM WORKS_ON WHERE
                                              ESSN = :B1
 125    51    54 PERSONNEL.CLEAR_EMPLOYMENT   DELETE FROM EMPLOYEE WHERE                                               SSN = :B1
 127    54    45 PERSONNEL.CLEAR_EMPLOYMENT   Procedure Call
 131    25    54 PERSONNEL.IS_SUPERVISOR      SELECT COUNT(SUPERSSN)                                               FROM EMPLOYEE WHERE                                               SUPERSSN = :B1
 135    35    50 PERSONNEL.IS_SUPERVISOR      Return from procedure call
 139    60    45 PERSONNEL.CLEAR_EMPLOYMENT   Procedure Call
 143     8    54 PERSONNEL.IS_MANAGER         SELECT COUNT(MGRSSN) FROM
                                              DEPARTMENT WHERE MGRSSN =                                               :B1
 147    18    50 PERSONNEL.IS_MANAGER         Return from procedure call
 152    66    50 PERSONNEL.CLEAR_EMPLOYMENT   Return from procedure call
 155    80    50 PERSONNEL.FIRE_EMPLOYEE      Return from procedure call
 157     9    45 <anonymous>.                 Procedure Call
 159    76    45 DBMS_TRACE.                  Procedure Call
 162    63    45 DBMS_TRACE.                  Procedure Call
 164    57    45 DBMS_TRACE.                  Procedure Call
 166    12    50 DBMS_TRACE.                  Return from procedure call
 169    58    50 DBMS_TRACE.                  Return from procedure call
 173    66    45 DBMS_TRACE.                  Procedure Call
 175    39       .                            PL/SQL trace stopped

56 rows selected.

Now you can see that you got some debugging data you didn't need – for example, you don't need to debug the DBMS_TRACE package. If you are interested in only some of the lines, add some more WHERE predicates. This is especially useful to pick out the code from the program unit(s) you want, or the types of statements you want -- SQL statements (EVENT_KIND=54) or call statements (EVENT_KIND=45) for example. Of course, you could also rerun the test with DBMS_TRACE.trace_all_sql and/or DBMS_TRACE.trace_all_calls only. You can also join this data to the ALL_SOURCE Data Dictionary view and match the line numbers to get the actual source code that matches each of these trace lines.

So Many Options, So Little Time

As you can see, there is a lot of information available in the trace tables, such as the list of Event Kinds (EKIND in the listing). For more information about the contents of the tables, or the processes necessary to build and interpolate them, check out ora10g102, Oracle Database 10g: PL/SQL Application Tuning. Or, jump directly into the Oracle documentation. (The link will get you to the Oracle PL/SQL Packages and Types Reference section about DBMS_TRACE. A user account is required.)

If you have any questions about SQL, PL/SQL, Oracle Developer, or even Java, feel free to e-mail me (Mike Marion). I actually love this stuff. Sometimes, your questions are my only contact with the real IT world! (Wait, is that an oxymoron?) I'll try to get your question answered in 24-48 hours. Just remember that sometimes I am out of town teaching and may not be able to get my company e-mail.

Thanks for hanging in there... and Good PL/SQL Debugging to you all!