Introduction

As an exceptional Oracle Developer you already know the value of instrumenting your code. You have read enough of Tom Kyte, Cary Millsap & Steve McConnell to understand that with the correct instrumentation diagnosing problems especially time critical problems (are there any others?) becomes much easier.

So the question is not why you should instrument your code but how. In this article I will explain the installation and use of the PL/SQL Logger which was originally developed by Tyler Muth and is now available on Github.

Installation

Once you have downloaded Logger from Githib and unzip the contents to a directory that can be seen by your Oracle client (I use SQL Plus). navigate to the directory “releases” and expand the folder for the Logger release you wish to install. At the time of writing version 2.1.2 was the latest so that will be the version used in this article.

Whilst you can install logger into an existing schema, I am going to use the supplied @create_user.sql to install Logger into it’s own schema. So start SQL Plus and connect to the database as system or a user with the DBA role and run the following script

@create_user.sql

When prompted to do so, enter the username, tablespace, temporary tablespace and password for the new schema. In this example I have accepted the suggested defaults of logger_user, users and temp respectively.

Now connect to the database as the newly created logger_user and run the installation script:

@logger_install.sql

If you run into problems with the installation it is worth starting with the supplied documentation.

In this article I will be accessing the Logger objects from the standard Oracle HR user so the following grant is required:

GRANT EXECUTE ON logger TO hr
/

Once installation is complete, you can view the status of the logger by running the following command

exec logger.status;

which displays the following:

SQL> exec logger.status;
Project Home Page :
https://github.com/tmuth/Logger---A-PL-SQL-Logging-Utility/
Logger Version : 2.1.2
Debug Level : DEBUG
Capture Call Stack : TRUE
Protect Admin Procedures : TRUE
APEX Tracing : Enabled
SCN Capture : Disabled
Min. Purge Level : DEBUG
Purge Older Than : 7 days
Pref by client_id expire : 12 hours
For all client info see : logger_prefs_by_client_id

PL/SQL procedure successfully completed.

How to use

Below is a procedure that updates the salary of a given employee. Now lets pretend it is part of a overnight batch job and is just one of thousands of procedures that need to run. To the outside world this procedure is a blackbox. Without querying the employee after the procedure has run (and committed) you have no idea what has happened when it was called.

CREATE OR REPLACE PROCEDURE raise_salary
(
   p_emp_id     IN employees.employee_id%TYPE,
   p_new_salary IN employees.salary%TYPE
)
IS
BEGIN

   UPDATE employees e
      SET e.salary = p_new_salary
    WHERE e.employee_id = p_emp_id;

END raise_salary;
/

Lets change that by adding some instrumentation.

CREATE OR REPLACE PROCEDURE raise_salary
(
   p_emp_id     IN employees.employee_id%TYPE,
   p_new_salary IN employees.salary%TYPE
)
IS
BEGIN

 logger_user.logger.log('Start of raise_salary');

 UPDATE employees e
   SET e.salary = p_new_salary
 WHERE e.employee_id = p_emp_id;

 logger_user.logger.log('Number of rows updated: {' || TO_CHAR(SQL%ROWCOUNT) || '}'); 

 logger_user.logger.log('End of raise_salary'); 

END raise_salary;
/

The revised version of the procedure captures some basic information as the start of the procedure, how many rows were updated and finally that the procedure completed successfully.

Even in this simple case it is easy for the real code to be submerged by the instrumentation code. There is no one size fits all solution. Careful consideration is required to decide how much instrumentation is required.

When the procedure is run, one of the Logger views can be queried and the output reviewed:

SELECT text
  FROM logger_user.logger_logs_5_min
/

Here is the output from the revised procedure after it has been run:

TEXT
----------------------------
Start of raise_salary
Number of rows updated: {1}
End of raise_salary

Level Up

The output from Logger is controlled by the level constant. The level can be set by calling the logger.set_level procedure. In the previous example I have used the log procedure to instrument my routine. This means that the output will insert an entry into the logger_logs table when the logger_level is set to debug.

There are a number of additional log_x routines that you can use with the various logging levels. For instance, log_warning will insert an entry into the logger_logs table when the logger level has been set to “warning”, likewise if you are only interested in capturing errors, you can set the Logger level to error and use the logger_error procedure.

One of the nicest features of the level facility is the ability to turn logging on for specified clients rather than system wide. In the following example, I have turned on debug logging for user 1 whilst user 2 continues to use the system but without instrumentation messages being inserted.

Logger_user session

The following commands are run:

exec logger_user.logger.set_level(p_level => 'OFF')
/

This system wide command turns Logger off. This means currently no instrumentation is being recorded.

exec logger_user.logger.set_level(p_level => 'DEBUG', p_client_id => 'user_one')
/

This command turns on debug logging for the client identifier user_one. (see user one session below for how this is set). This means any instrumentation that uses the logger.log procedure will be inserted into the log table.

The following query will show you the current clients that logging is enable for:

SELECT *
  FROM logger_prefs_by_client_id
/

User_one session

The following command sets the client identifier (this is used by the call to enable logging for this client by the Logger_user session above)

exec dbms_session.set_identifier('user_one');

I then execute the raise_salary procedure and commit.

User_two session

Almost a carbon copy of the user_one session with the exception of the identifier.

exec dbms_session.set_identifier('user_two');

I then execute the raise_salary procedure and commit.

Now when I query the logger table I see the following output which shows that only user_one’s actions have been captured.

SQL> SELECT client_identifier, text
2      FROM logger_user.logger_logs_5_min
3 /

CLIENT_IDENTIFIER TEXT
------------------------------------
user_one Start of raise_salary

user_one Number of rows updated: {1}

user_one End of raise_salary

But wait there is more…

All of the main Logger procedures allow you to give context to the information you are recording. The context would normally be where the message has originated from, i.e. Application, Package etc. The facility is provided by the p_scope parameter. Here is the raise_salary procedure used earlier refactored to include the p_scope parameter.

CREATE OR REPLACE PROCEDURE raise_salary_scope
(
   p_emp_id     IN employees.employee_id%TYPE,
   p_new_salary IN employees.salary%TYPE
)
IS

   l_scope logger_user.logger_logs.scope%type := 'raise_salary_scope';

BEGIN

   logger_user.logger.log('Start', l_scope);

   UPDATE employees e
      SET e.salary = p_new_salary
    WHERE e.employee_id = p_emp_id;

   logger_user.logger.log('Number of rows updated: {' || TO_CHAR(SQL%ROWCOUNT) || '}', l_scope);

   logger_user.logger.log('End', l_scope);

END raise_salary_scope;
/

Each of the calls to the log procedure now has the name of procedure contained within the l_scope parameter passed to it.

The following query shows results of using the scope parameter

SQL> SELECT scope, text
2      FROM logger_user.logger_logs_5_min
3    /

SCOPE                TEXT
------------------------------------------------
raise_salary_scope   Start

raise_salary_scope   Number of rows updated: {1}

raise_salary_scope   End

The logging of parameter values is handled within Logger by using the p_params object. This is easier to show with an example rather than even more text!

Here is the final revision of the raise_salary procedure.

CREATE OR REPLACE PROCEDURE raise_salary_params
(
   p_emp_id     IN employees.employee_id%TYPE,
   p_new_salary IN employees.salary%TYPE
)
IS

   l_scope    logger_user.logger_logs.SCOPE%TYPE := 'raise_salary_scope';
   l_params   logger_user.logger.tab_param;

BEGIN

   logger_user.logger.append_param(l_params, 'p_emp_id', p_emp_id);
   logger_user.logger.append_param(l_params, 'p_new_salary', p_new_salary);

   logger_user.logger.log('Start', l_scope, null, l_params);

   UPDATE employees e
      SET e.salary = p_new_salary
    WHERE e.employee_id = p_emp_id;

   logger_user.logger.log('Number of rows updated: {' || TO_CHAR(SQL%ROWCOUNT) || '}', l_scope);

   logger_user.logger.log('End', l_scope);

END raise_salary_params;
/

The parameters are added to a pre-defined Logger associative array and that array is included in the first call to the log procedure.

The parameters are stored in the extra column and the following query shows how to display them.

SQL> SELECT text, extra
2      FROM logger_user.logger_logs_5_min
3    /

TEXT                         EXTRA
---------------------------------------------------------------------------------
Start                        *** Parameters *** p_emp_id: 100 p_new_salary: 4500

Number of rows updated: {1}

End

Summary

There is no getting away from the fact that the instrumentation is an overhead to your application. Trying to find the balance between too much and too little information that is to be captured, the extra code you need to develop and then the extra resources required to execute the larger code base all need to be carefully considered.

My opinion is that this is a price I am willing to pay. When bad things happen and you are under pressure to track down the cause you will find the problem far quicker with code that is telling you what exactly is happening. Compare this with the alternative. Peering into an enormous black box armed only with guesses.

Acknowledgements

Tyler Muth

Martin Giffy D’Souza