Friday 26 August 2011

Tracing when you need it and how you need it

Question:
I just started working at a new position, enhancing an application that's been around for several years. I was alarmed to find that the team was relying on very primitive debugging and tracing approaches, basically inserting calls to DBMS_OUTPUT.PUT_LINE or a "log to table" program all over the code base. Sure, we can turn off server output and not see any of the tracings; we can put the calls to our logging program inside an IF statement that references a global "am I logging?" flag. But this kind of code is a mess. It is hard to read and maintain, adds overhead to our production application, and requires that we deploy our application with the logging database objects. I've shown the team how to use the interactive debugger in our IDE. Do you have any other suggestions for improving the way we debug and trace our code?
Answer:
I have noticed that lots of programmers tend to talk about tracing and debugging as if they were the same thing. In my experience, they serve different, but related purposes. Debugging is the process of identifying the cause of and repairing a particular bug. Tracing involves writing out information about the state of your application to some repository, for later review/analysis.
You can certainly use tracing to assist in the debugging process. However, an interactive source code debugger, commonly available in any robust PL/SQL IDE, is a much better fit for debugging. You step through the code at issue line by line, and analyze the code to uncover the cause of the problem. I am glad to hear that you have introduced this capability to your team; I don't think I have any other advice to offer there. Instead, I will focus on the issue of tracing in PL/SQL applications.
I find that tracing is more useful when I want to let my application run to completion(as opposed to stepping through the code line by line, as is done with a debugger), generate trace information, and then analyze that information. I might need to identify logical problems with the code, analyze performance and isolate lines of code that are a bottleneck, etc.
In the bad, old days, PL/SQL developers relied on calls to DBMS_OUTPUT.PUT_LINE to write information to the screen (or spool it to a file with the SQL*Plus SPOOL command) or relied on inserts into database tables, a more persistent form of tracing, but with more overhead and deployment issues.
Either approach has drawbacks, as you point out in your question. Fortunately, conditional compilation offers a vastly superior solution: when you compile your code for production, turn off tracing and all the tracing code simply disappears; it is not in the code. You do not need to deploy tracing/debugging support objects, such as tables and logging programs. Users experience no overhead from the tracing.
Let's take a look at how you can implement tracing with conditional compilation. In the example below, I have decided to implement three levels of tracing:
1. Completely turned off: no tracing is performed. All tracing logic is removed from the application, once it is compiled.
2. Critical tracing: trace only the most critical parts of the application. I might want to keep critical tracing turned on even when the application goes to production, so that critical failures can be more quickly analyzed and resolved.
3. Full tracing: the most detailed level of tracing, very useful when I am developing and testing my application, but definitely not desirable in the production code.
To demonstrate tracing with conditional compilation, I will add tracing to the list_to_collection function, a handy utility that parses a delimited string and places each item into the next available index in an associative array based on the DBMS_SQL.VARCHAR2A type. Here is the code devoid of tracing:
CREATE OR REPLACE FUNCTION list_to_collection (
string_in IN VARCHAR2
, delimiter_in IN VARCHAR2 DEFAULT ','
)
RETURN DBMS_SQL.varchar2a
IS
l_next_location PLS_INTEGER := 1;
l_start_location PLS_INTEGER := 1;
l_return DBMS_SQL.varchar2a;
BEGIN
IF string_in IS NOT NULL
THEN
WHILE ( l_next_location > 0 )
LOOP
-- Find the next delimiter
l_next_location :=
NVL (INSTR ( string_in, delimiter_in, l_start_location ), 0);

IF l_next_location = 0
THEN
-- No more delimiters, go to end of string
l_return ( l_return.COUNT + 1 ) :=
SUBSTR (string_in, l_start_location);
ELSE
-- Extract the string between the two delimiters
l_return ( l_return.COUNT + 1 ) :=
SUBSTR ( string_in
, l_start_location
, l_next_location - l_start_location
);
END IF;

l_start_location := l_next_location + 1;
END LOOP;
END IF;

RETURN l_return;
END list_to_collection;
/
And now I will add tracing (a very basic call to DBMS_OUTPUT.PUT_LINE). The minimal or critical tracing I want to perform is to show the contents of the collection before it is returned. Full tracing will show me the current start location, next location of delimiter and which path was taken (added the last item or added a string between two delimiters) in each iteration.
My program now looks like this:
CREATE OR REPLACE FUNCTION list_to_collection (
string_in IN VARCHAR2
, delimiter_in IN VARCHAR2 DEFAULT ','
)
RETURN DBMS_SQL.varchar2a
IS
l_next_location PLS_INTEGER := 1;
l_start_location PLS_INTEGER := 1;
l_return DBMS_SQL.varchar2a;
$IF $$trace_critical OR $$trace_full $THEN
PROCEDURE show_contents
IS BEGIN
FOR indx IN 1 .. l_return.COUNT
LOOP
DBMS_OUTPUT.PUT_LINE (
'Element at index ' || indx || ' = ' || l_return(indx));
END LOOP;
END show_contents;
$END
BEGIN
IF string_in IS NOT NULL
THEN
WHILE ( l_next_location > 0 )
LOOP
-- Find the next delimiter
l_next_location :=
NVL (INSTR ( string_in, delimiter_in, l_start_location ), 0);
$IF $$trace_full $THEN
DBMS_OUTPUT.PUT_LINE (
'>>> Start location: ' || l_start_location );
DBMS_OUTPUT.PUT_LINE (
'>>> Next location of delimiter: ' || l_next_location );
$END

IF l_next_location = 0
THEN
-- No more delimiters, go to end of string
l_return ( l_return.COUNT + 1 ) :=
SUBSTR ( string_in, l_start_location );
$IF $$trace_full $THEN
DBMS_OUTPUT.PUT_LINE (
'>>> Add rest of string: "' ||
SUBSTR ( string_in, l_start_location ) || '"');
$END
ELSE
-- Extract the string between the two delimiters
$IF $$trace_full $THEN
DBMS_OUTPUT.PUT_LINE (
'>>> Between two delimiters: "' ||
SUBSTR ( string_in
, l_start_location
, l_next_location - l_start_location
) || '"');
$END
l_return ( l_return.COUNT + 1 ) :=
SUBSTR ( string_in
, l_start_location
, l_next_location - l_start_location
);
END IF;
l_start_location := l_next_location + 1;
END LOOP;
END IF;
$IF $$trace_critical OR $$trace_full $THEN
show_contents;
$END
RETURN l_return;
END list_to_collection;
/
With tracing turned off, I see the following output from a call to this function:
SQL> ALTER FUNCTION list_to_collection COMPILE
2 PLSQL_CCFLAGS = 'trace_critical:false, trace_full:false'
3 REUSE SETTINGS
4 /

Function altered.

SQL> DECLARE
2 l_list DBMS_SQL.varchar2a;
3 BEGIN
4 DBMS_OUTPUT.PUT_LINE ('Trace turned off');
5 l_list := list_to_collection ('a,b,c,d');
6 DBMS_OUTPUT.PUT_LINE ('Count in list: ' || l_list.COUNT);
7 END;
8 /
Trace turned off
Count in list: 4
And now with only critical tracing enabled (as my code might go to production):
SQL> ALTER FUNCTION list_to_collection COMPILE
2 PLSQL_CCFLAGS = 'trace_critical:true, trace_full:false'
3 REUSE SETTINGS
4 /

Function altered.

SQL> DECLARE
2 l_list DBMS_SQL.varchar2a;
3 BEGIN
4 DBMS_OUTPUT.PUT_LINE ('Trace CRITICAL Only');
5 l_list := list_to_collection ('a,b,c,d');
6 DBMS_OUTPUT.PUT_LINE ('Count in list: ' || l_list.COUNT);
7 END;
8 /
Trace CRITICAL Only
Element at index 1 = a
Element at index 2 = b
Element at index 3 = c
Element at index 4 = d
Count in list: 4
Finally, I will turn on full tracing (for use in development and testing):
SQL> ALTER FUNCTION list_to_collection COMPILE
2 PLSQL_CCFLAGS = 'trace_critical:false, trace_full:true
3 REUSE SETTINGS
4 /

Function altered.

SQL> DECLARE
2 l_list DBMS_SQL.varchar2a;
3 BEGIN
4 DBMS_OUTPUT.PUT_LINE ('Trace FULL');
5 l_list := list_to_collection ('a,b,c,,d,');
6 DBMS_OUTPUT.PUT_LINE ('Count in list: ' || l_list.COUNT);
7 END;
8 /
Trace FULL
>>> Start location: 1
>>> Next location of delimiter: 2
>>> Between two delimiters: "a"
>>> Start location: 3
>>> Next location of delimiter: 4
>>> Between two delimiters: "b"
>>> Start location: 5
>>> Next location of delimiter: 6
>>> Between two delimiters: "c"
>>> Start location: 7
>>> Next location of delimiter: 7
>>> Between two delimiters: ""
>>> Start location: 8
>>> Next location of delimiter: 9
>>> Between two delimiters: "d"
>>> Start location: 10
>>> Next location of delimiter: 0
>>> Add rest of string: ""
Element at index 1 = a
Element at index 2 = b
Element at index 3 = c
Element at index 4 =
Element at index 5 = d
Element at index 6 =
Count in list: 6
Lots more detail!
Finally, I will show you what the post-processed code looks like with tracing turned off entirely, using the DBMS_PREPROCESSOR package:
SQL> BEGIN
2 dbms_preprocessor.print_post_processed_source (
3 'FUNCTION', USER, 'LIST_TO_COLLECTION');
4 END;
5 /
FUNCTION list_to_collection (
string_in IN VARCHAR2
, delimiter_in IN VARCHAR2 DEFAULT ','
)
RETURN DBMS_SQL.varchar2a
IS
l_next_location PLS_INTEGER := 1;
l_start_location PLS_INTEGER := 1;
l_return DBMS_SQL.varchar2a;

BEGIN
IF string_in IS NOT NULL
THEN
WHILE ( l_next_location > 0 )
LOOP
-- Find the next delimiter
l_next_location :=
NVL (INSTR ( string_in, delimiter_in, l_start_location ), 0);

IF l_next_location = 0
THEN
-- No more delimiters, go to end of string
l_return ( l_return.COUNT + 1 ) :=
SUBSTR ( string_in, l_start_location );
ELSE
-- Extract the string between the two delimiters
l_return ( l_return.COUNT + 1 ) :=
SUBSTR ( string_in
, l_start_location
, l_next_location - l_start_location
);
END IF;
l_start_location := l_next_location + 1;
END LOOP;
END IF;

RETURN l_return;
END list_to_collection;
Notice that Oracle inserts blank lines where the tracing code originally appeared; this is done so that line numbers reported in call stacks, error stacks and error backtraces match the contents of USER_SOURCE.
As you can see, conditional compilation offers a high degree of tracing flexibility, but also allows you to easily control the code that is deployed into production, minimizing overhead and dependencies. I have demonstrated in particular that you can conditionally include both individual executable statements and also declarations of elements, including local subprograms, which can then be called in the executable section of your code.
Finally, you might be wondering why I used ccflags (inquiry directives) to control tracing, instead of packaged constants. Oracle recommends the following in this regard:
• Control conditional compilation with an inquiry directive when the normal behavior of the compilation unit can be defined when it has the value null—and when a not null value is never expected to be needed in the production environment. Tracing offers an excellent example of this scenario, since you generally want tracing disabled in production.
Control conditional compilation with a package constant in the opposite situation: when two or more different conditionalizations are expected routinely to be used in the production environment. The nature of the requirement that drives this will typically mean that two or more compilation units are controlled by the same static package constant. A good example of this situation is when you want to use conditional compilation to conditionally install selected components of one's application.

No comments:

Post a Comment