[Chapter 21] 21.2 PLVtrc: Tracing Execution of PL/SQL Programs

21.2 PLVtrc: Tracing Execution of PL/SQL Programs

The PLVtrc (PL/Vision TRaCe) package offers a generic trace facility for PL/SQL applications. It is especially useful if you do not have access to a source debugger for PL/SQL . It is also used by PLVexc to record the currently executing PL/SQL program unit when an exception occurs.

The PLVtrc package offers several capabilities:

Provides a flexible execution trace facility. It inserts trace points anywhere in your code; these fire and display (or write to a log) only if you explicitly turn on the trace. Thus, your trace can remain in place even in production code.
Parses the string returned by a call to the DBMS_UTILITY.FORMAT_CALL_STACK function. You can specify retrieval of the n th module in the stack and use this information in your own auditing and trace activities.
Is similar to the p package. PLVtrc offers a heavily overloaded interface to the PUT_LINE procedure of DBMS_OUTPUT. (In fact, PLVtrc calls the p.l procedure to generate its output.)

The elements provided by PLVtrc can be broken down into three areas: output control, module tracking, and activity trace. They are explored in the following sections.

21.2.1 Directing Output from PLVtrc

As with many other PL/Vision packages, PLVtrc allows you to programmatically control its behavior, in this case its output. PLVtrc offers three different types of output:

Display the trace message to the screen. If not turned on, all calls to PLVtrc programs are ignored.
Log the trace message to the PL/Vision log. If tracing is activated, this feature also writes a line out to the current PLVlog repository.
Display the currently executing module based on the PL/SQL FORMAT_CALL_STACK function. If tracing is activated, this feature adds the current module to the display.

PLVtrc offers a separate toggle for each of these aspects of output. Here are the programs to turn the trace facility itself on and off:

PROCEDURE turn_on;
PROCEDURE turn_off;
FUNCTION tracing RETURN BOOLEAN;

To activate the trace facility, enter:

SQL> execute PLVtrc.turn_on;

To de-activate the trace facility enter:

SQL> execute PLVtrc.turn_off;

To control logging of trace messages using the PLVlog package, PLVtrc offers these programs:

PROCEDURE log;
PROCEDURE nolog;
FUNCTION logging RETURN BOOLEAN;

This command turns on logging of trace message:

SQL> execute PLVtrc.log;

To turn off logging, enter:

SQL> execute PLVtrc.nolog;

You can also request that when trace information is displayed the current module is included in the message. You control the inclusion of that data with this toggle:

PROCEDURE 

dispmod;
PROCEDURE 

nodispmod;
FUNCTION 

displaying_module RETURN BOOLEAN;

So to include the module in trace messages, enter:

SQL> execute PLVtrc.dispmod;

To ignore the module name enter:

SQL> execute PLVtrc.nodispmod;

To turn on all these options, you need to execute all three "on" procedures:

SQL> exec PLVtrc.dispmod;
SQL> exec PLVtrc.log;
SQL> exec PLVtrc.turn_on;

The order in which you call these toggle programs is not important. Just remember that you cannot write information to the log or display the current module unless the overall trace is turned on.

In all examples above I have shown the syntax for executing the programs from within SQL*Plus. You can also call these programs from within a PL/SQL program, in which case you would not use the execute command.

21.2.2 Accessing the PL/SQL Call Stack

The PLVtrc package provides you with the ability to access and parse the call stack maintained by the PL/SQL runtime engine. This call stack is available with a call to the DBMS_UTILITY. FORMAT_CALL_STACK function. Here is an example of the string returned by this function:

----- PL/SQL Call Stack -----
object      line    object
handle      number  name
88ce3f74         8  package STEVEN.DISPCSTK
88e49fc4         2  function STEVEN.COMPANY_TYPE
88e384c8         1  procedure STEVEN.CALC_PROFITS
88e3823c         1  procedure STEVEN.CALC_TOTALS
88e49390         1  procedure STEVEN.CALC_NET_WORTH
88e2bd20         1  anonymous block

The string actually contains many newline characters (you can find these by searching for CHR(10) with the INSTR function). It is designed for easy display, but not easy manipulation within a programmatic setting.

The PLVtrc package offers two programs to access this PL/SQL call stack:

ps_callstack: Returns the same string returned by the FORMAT_CALL_STACK function. It is provided for consistency and to save you some typing.
ps_module: Returns the n th module in the PL/SQL call stack, with the default being the "most recent module," (i.e., the program that was active before the PLVtrc.module function was called.) This, by the way, is the second module in the stack.

NOTE: One big problem with FORMAT_CALL_STACK is that it will not provide the name of the current program within a package. If you are executing a standalone function or procedure, FORMAT_CALL_STACK shows you its name. If you are running a function within a package, however, it only shows you the package name. If your code design is package-driven, this fact renders the FORMAT_CALL_STACK function largely irrelevant. This shortcoming is the main reason that PLVtrc also maintains its own program call stack in a PL/Vision stack.

21.2.3 Tracing Code Execution

PLVtrc offers two programs to trace the execution of your code: action and show . The action program's header is:

PROCEDURE 

action
   (string_in IN VARCHAR2 := NULL, 
    counter_in IN INTEGER := NULL,
    prefix_in IN VARCHAR2 := NULL);

You pass a string, a numeric counter or indicator, and another string that is used as a prefix on the trace message. The action procedure is used by startup , terminate , and the other activity trace module, show . It is, in other words, the lowest-level trace procedure.

The show procedure is heavily overloaded. Like the p.l procedure, the show program comes in many flavors of argument combinations, as shown in the list below. This is done to make it easy for you to pass different combinations of data for display without having to perform TO_CHAR conversions and concatenations.

The following datatype combinations are supported by PLVtrc.show :

Single-value	Double-value	Triple-value
string	string, date	string, number, number
date	string, number	string, number, date
number	string, boolean	string, number, boolean
boolean

Here are the headers for the single-value show procedures:

PROCEDURE show (stg1 IN VARCHAR2);
PROCEDURE show (date1 IN DATE, mask_in IN VARCHAR2 := PLV.datemask);
PROCEDURE show (bool1 IN BOOLEAN);
PROCEDURE show (num1 IN NUMBER);

Here are the headers for the double-value show procedures:

PROCEDURE show (stg1 IN VARCHAR2, num1 IN NUMBER);
PROCEDURE show
   (stg1 IN VARCHAR2,
    date1 IN DATE, mask_in IN VARCHAR2 := PLV.datemask);
PROCEDURE show (stg1 IN VARCHAR2, bool1 IN BOOLEAN);

Here are the headers for the triple-value show procedures:

PROCEDURE show 
   (stg1 IN VARCHAR2, num1 IN NUMBER, num2 IN NUMBER);
PROCEDURE show 
   (stg1 IN VARCHAR2, num1 IN NUMBER,
    date1 IN DATE, mask_in IN VARCHAR2 := PLV.datemask);
PROCEDURE show 
   (stg1 IN VARCHAR2, num1 IN NUMBER, bool1 IN BOOLEAN);

You can place calls to both action and show in your programs. No output is generated from these message lines until you turn on the trace. And since there is very little overhead involved in calling these programs, you can leave the trace in your code even when it goes into production status. When you have to debug the code, you simply call PLVtrc.turn_on , run the application, and you have a wealth of information available to you.

21.2.4 The PLVtrc Program Stack

PLVtrc offers two programs to build its own program execution stack: startup and terminate . You can also get information about the current and previous modules of the stack.

The PLVtrc call stack operations provide two key advantages over the builtin:

The call stack contains the names of the specific programs being executed (or whatever strings you pass to represent the names of programs).
You can call startup at any point, so you can give names in your call stack to anonymous blocks as well as named modules. Just don't forget to terminate if you run startup .

21.2.4.1 startup

You should call PLVtrc.startup as the first line in the body of your program. Its header is:

PROCEDURE startup 
   (module_in IN VARCHAR2, string_in IN VARCHAR2 := NULL);

You provide the module name or abbreviation or whatever string you want to record as representing the program. You can also pass in a second string argument. This value is displayed or logged by PLVtrc, according to the toggle settings. This second argument allows you to pass variable data into the trace.

21.2.4.2 terminate

The terminate program performs a task opposite that of startup : it pops off the stack the most recently pushed module and sets the previous module variable. The header for terminate is:

PROCEDURE terminate (string_in IN VARCHAR2 := NULL);

As with startup , you can provide a string to be displayed or logged, depending on the status of the PLVtrc toggles. You should call PLVtrc.terminate as the last executable statement in your procedure, and immediately before your RETURN statement in a function.

You should also call PLVtrc.terminate in each of your exception handlers in a PL/SQL block where startup was called. Otherwise the enclosing module will not be popped off the stack when the block fails.

If you use one of the high-level handlers of PLVexc to handle your exception, however, you do not have to -- and should not -- call terminate . Those handlers do that for you.

21.2.4.3 Current module

Each time PLVtrc.startup is executed, it pushes the current module onto the PLVtrc execution stack and sets the current module to the first argument in the call to startup .

You can obtain the name of the current module in the PLVtrc environment by calling the currmod function, whose header is:

FUNCTION currmod RETURN VARCHAR2;

21.2.4.4 Previous module

To see the name of the previous module, you can call the prevmod function, whose header is:

FUNCTION prevmod RETURN VARCHAR2;

The PLVexc package makes use of this function so that it can record the program in which an exception was raised. You might not have too much use for prevmod .

See Section 21.2.5, "Using PLVtrc" to see how you put these pieces together.

21.2.4.5 Emptying the stack

The clearecs procedure empties the execution stack by recreating it. The header for this procedure is:

PROCEDURE clearecs;

You will want to use this program when you have finished running a test and you want to make sure that there aren't any extraneous module names left on the stack.

21.2.4.6 Displaying the stack

You can display the contents of the stack with a call to showecs ; the header is:

PROCEDURE 

showecs;

This program, in turn, calls PLVlst.display to display the contents of the list, which comprise the underlying data structure for the stack (implemented, actually, with the PLVstk package -- an interesting exercise in code layering).

21.2.4.7 Retrieving stack contents

If you do not want to directly display the PLVtrc stack, you can extract it as a string in much the same format as that provided by the builtin FORMAT_CALL_STACK function with the ecs_string function. Its header is:

FUNCTION ecs_string RETURN VARCHAR2;

Each module name in the call stack is separated by a newline character.

You can also retrieve a single module from the stack with the module procedure. This program's header is:

FUNCTION module (pos_in IN INTEGER := c_top_pos)
   RETURN VARCHAR2;

where pos_in is the position in the stack in which you are interested. The current program is stored in the top-most position of 0 (actually not yet on the call stack) and is encapsulated in the package constant, c_top_pos . To obtain the name of the module that called the current program, you would pass in a position of 1.

21.2.5 Using PLVtrc

The following examples show you how to use the different elements of the PLVtrc package.

Use the startup and terminate procedures in my procedure to integrate it into the PLVtrc call stack. In addition, handle exceptions using the PLVexc component (which also performs a terminate ).

CREATE OR REPLACE PROCEDURE proc (val in number) IS
BEGIN
   PLVtrc.startup ('proc');
   IF 1/val > 1 THEN NULL; END IF;
   PLVtrc.terminate;
EXCEPTION
   WHEN OTHERS THEN PLVexc.rec_continue;
END;
/

Show the employee name and date before giving them a name.
```
FOR emp_rec IN emp_cur
LOOP
   PLVtrc.show (emp_rec.ename, emp_rec.hiredate);
   give_raise (emp_rec.empno);
END LOOP;
```
Remember: this call to show will not actually generate any output unless you turn on at least one of the trace features.

Use the startup and terminate procedures to track execution of a nested, anonymous block. Notice that in the exception section, I explicitly call terminate for the NO_DATA_FOUND exception. For all other errors, I let the PLVexc package handle the PLVtrc.terminate and the error as well.

PROCEDURE annual_calcs (val in number) 
IS
BEGIN
   PLVtrc.startup ('proc');

   calc_gross_revenue;
   BEGIN
      PLVtrc.startup ('analyze');
      calc_rev_distribution;
      PLVtrc.terminate;
   EXCEPTION
      WHEN OTHERS THEN PLVexc.halt;
   END;
   call_profits;
   PLVtrc.terminate;

EXCEPTION
   WHEN NO_DATA_FOUND 
   THEN 
      PLVtrc.terminate;
      p.l ('Invalid value: ' || TO_CHAR (val);

   WHEN OTHERS 
   THEN 
      /* This program calls PLVtrc.terminate */
      PLVexc.rec_continue;
END;
/