Instrumentation


Introduction

Instrumentation is a general term for the additional information that an application provides over and above the "day to day" workings. The major use is for debug purposes. For example, a debug procedure which the client normally never sees is considered instrumentation.

Oracle's instrumentation policy has many facets, the wait event system, v$ tables, SQL_TRACE=TRUE etc.

Some people argue that instrumentation is just as important as the "normal" application code, since it aids the technical support or developer to track down bugs etc. much quicker than having to do this when the problem is identified. A good instrumentation policy should only add a slight overhead to the general workings of the application, most of the time the instrumentation policy should only actually do the operations (such as debugging) if some form of flag is set, such as SQL_TRACE=TRUE.

If you are undecided about the importance of instrumentation (and believe me, you shouldn't be), then just think what a nightmare it would be if Oracle didn't implement SQL_TRACE, or the Wait Event system, or if SQL*Net didn't allow you to set TRACE_LEVEL_CLIENT, or if ODBC didn't allow you to trace statements made through DSNs (I think you get the picture).

Implementing your own custom routines

Of course, you can always write your own logging mechanism. A lot of applications do this. Typical mechanisms usually involve database tables, and use AQ or Autonomous Transactions to insert the logging information ( and some session information, of course ).

All perfectly valid, but, if I can offer one snippet of advice, always use database features where possible. Instead of writing a custom session information routine, use DBMS_APPLICATION_INFO. Core code (i.e. written in C by Oracle) will always be faster than trying to replicate the functionality simply in PL/SQL.

If you need PL/SQL logging, then before going ahead and spending a fortune on writing your own, have a look at some of the open-source / freeware offerings out there. I highlight a few later in the section, such as Tom Kyte's DEBUG.F, or the Open Source project, LOG4PLSQL. Why re-invent the wheel? (and they're very good products, written by knowledgeable developers).

DBMS_APPLICATION_INFO

Oracle provide a database package (DBMS_APPLICATION_INFO) which allows an efficient mechanism for recording the current state of sessions. The information is visible in v$session / v$session_longops (for set_session_longops).

SET_CLIENT_INFO

The most common use is the SET_CLIENT_INFO procedure, i.e.
SQL> EXEC dbms_application_info.set_client_info('THIS IS A TEST');

PL/SQL procedure successfully completed.

SQL> SELECT sid, serial#, client_info
  2  FROM   v$session;

       SID    SERIAL# CLIENT_INFO
---------- ---------- ----------------------------------------------------------------
         1          1
         2          1
         3          1
         4          1
         5          1
         6          1
         7          1
         8          1
        10       2280 THIS IS A TEST

9 rows selected.
Using this means that a developer can see at a glance the current state of the application.

SET_MODULE

SET_MODULE allows a similar mechanism for recording state, but is typically called once (at the beginning of the application). For example, starting up SQL*Plus sets the module info to 'SQL*Plus', i.e.
SQL> EXEC dbms_application_info.set_module(module_name=>'MY MODULE', action_name=>'MY ACTION');

PL/SQL procedure successfully completed.

SQL> SELECT SID, SERIAL#, MODULE, ACTION
  2  FROM V$SESSION;

       SID    SERIAL# MODULE                                           ACTION
---------- ---------- ------------------------------------------------ --------------------------------
         1          1
         2          1
         3          1
         4          1
         5          1
         6          1
         7          1
         8          1
        10       2280 MY MODULE                                        MY ACTION

9 rows selected.

SET_ACTION

You can set the ACTION directly with SET_ACTION, i.e.
SQL> exec dbms_application_info.set_action('MY ACTION 2');

PL/SQL procedure successfully completed.

SQL> SELECT SID, SERIAL#, MODULE, ACTION
  2  FROM V$SESSION;

       SID    SERIAL# MODULE                                           ACTION
---------- ---------- ------------------------------------------------ --------------------------------
         1          1
         2          1
         3          1
         4          1
         5          1
         6          1
         7          1
         8          1
        10       2280 MY MODULE                                        MY ACTION 2

9 rows selected.

SET_SESSION_LONGOPS

SET_SESSION_LONGOPS is extremely useful for situations where you want to see progress of long-running processes (or maybe processes kicked off via DBMS_JOB), and you want to see time elapsed etc.
Session 1

SQL> DECLARE
  2    l_nohint NUMBER DEFAULT dbms_application_info.set_session_longops_nohint;
  3    l_rindex NUMBER DEFAULT l_nohint;
  4    l_slno   NUMBER;
  5  begin
  6    FOR i IN 1 .. 10
  7    LOOP
  8      dbms_lock.sleep(2);  /* "PROCESS" which takes a while */
  9      dbms_application_info.set_session_longops
 10          ( rindex =>  l_rindex,
 11            slno   =>  l_slno,
 12            op_name => 'my long running operation',
 13            target  =>  1234,
 14            target_desc => '"msg description"',
 15            context     => 0,
 16            sofar       => i,
 17            totalwork   => 10,
 18            units       => 'loops'
 19          );
 20    END LOOP;
 21  END;
 22  /

Session 2

SQL> select opname, target, target_desc, message
  2  from v$session_longops
  3  where serial# = 2280
  4  /

OPNAME                                                           TARGET
---------------------------------------------------------------- ----------------------------------------------------------------
TARGET_DESC
--------------------------------
MESSAGE
--------------------------------------------------------------------------------------------------------------------------------------------
my long running operation                                        1234
"msg description"
my long running operation: "msg description" 1234: 10 out of 10 loops done

Logging to file using DEBUG.F

Tom Kyte (of AskTom) has written a cracking routine for instrumentation which outputs to tables and flat files.

He's called it debug.f (after the debugf command in C), and is available at http://asktom.oracle.com/~tkyte/debugf.

As you can expect from Tom, the coding and mechanisms used are top quality. This is a proven product, he uses this mechanism for the AskTom site (and many others).

LOG4PLSQL

LOG4PLSQL is an open-source project to come up with a standard, feature-rich, mechanism for logging to a wide variety of destinations, including table, SMTP, OS file, NT Event Log, Telnet etc.

It really is a cracking project, using background processes, DBMS_PIPE etc. to improve it's performance and scalability.

You can find it at
http://log4plsql.sourceforge.net/.

Note, Oracle Technology Network has published an article on LOG4PLSQL, written by one of the authors of the project. You can find the article at http://otn.oracle.com/pub/articles/moulard_log4plsql.html.