LOGGER - a quick start to debug, track errors or calculate code timings in PL/SQL

What is LOGGER?

It’s a PL/SQL logging and debugging framework. It’s super simple to install and use.

Yes, you can also use it in PL/SQL within Oracle APEX or in any other application that uses Oracle Database.

What are the benefits of using it for YOU, a developer?

• Debugging - tracking down the exact source (line) of the error

• Error Logging - an easy way to track errors

• Timing - simple benchmarking of sections of code

You can read more on the official GitHub project page.

Installation

If you’re the one who wants to install Logger, just read this blog post by Danny Bryant - it’s quite old, but still relevant. Blog post, of course, I dunno how old Danny is.

It shouldn’t take more than 30 minutes.

My advice for the installation process:

• Always install on a separate schema and call it, e.g., LOGGER.

• When installing to production, set the logger level to ERROR to prevent debug calls from being left there

• During installation, you may get some errors like “PLS-00049: bad bind variable ‘NEW.PREF_TYPE’ - you can ignore them.

How to use LOGGER?

With Logger already installed, you will notice that your application schema (let’s say it’s HR - Human Resources) will have access to objects named “%LOGGER%”.

These objects are synonyms for real objects in the schema LOGGER.

In 95% of use cases, you will probably use only the first four objects:

• package LOGGER

• tables/views:

  • LOGGER_LOGS,

  • LOGGER_LOGS_5_MIN (logs from the last 5 minutes)

  • LOGGER_LOGS_60_MIN (“ 60 mins)

Debugging

Below is a sample procedure for giving an employee a salary raise.

Here’s a brief explanation of some additional code used:

• l_scope - used to identify a procedure during debugging

• l_params - required to save procedure parameters

• logger.append_params - procedure used to add parameters

• logger.log - used to save debug values into the LOGGER_LOGS table

• logger.log_error - used to save errors into the same table

create or replace procedure update_employee_salary (
   p_emp_id in employees.employee_id%type,
   p_raise  in number
) is
    -- define scope
   l_scope  logger_logs.scope%type := 'update_employee_salary';
    --prepare variable to save parameters
   l_params logger.tab_param;
begin
    --add parameters to log
   logger.append_param (
      p_params => l_params,
      p_name   => 'p_emp_id',
      p_val  => p_emp_id
   );
   logger.append_param(
      p_params => l_params,
      p_name   => 'p_raise',
      p_val  => p_raise
   );

    -- log a monent when procedure starts and save parameters
   logger.log(
      p_text   => 'START',
      p_scope  => l_scope,
      p_extra  => null,
      p_params => l_params
   );

    --main procedure logic
   update employees
      set
      salary = salary + p_raise
    where employee_id = p_emp_id;

    -- log amount of modified records
   logger.log(
      p_text  => 'Employees updated: ' || sql%rowcount,
      p_scope => l_scope
   );

   -- log end of procedure
   logger.log(
      p_text  => 'END',
      p_scope => l_scope
   );
exception
   when others then
        --log error
      logger.log_error(
         p_text   => 'Unexpected error: ' || sqlerrm,
         p_scope  => l_scope,
         p_extra  => null,
         p_params => l_params
      );
      raise;
end;

I will compile this procedure in my HR schema.

And give a raise to one of the employees.

begin
   update_employee_salary(
      p_emp_id => 100, -- 100 is Steven King with current salary 24000
      p_raise  => 5000
   );
end;

Let’s check what’s in my table:

select 
    id,
    logger_level,
    text,
    time_stamp,
    scope,
    user_name,
    line_no,
    call_stack,
    extra,
    client_info
 from logger_logs
order by id desc;

As you can see, LOGGER has recorded some useful data:

• Name of the procedure and the time it was executed - SCOPE, TIME_STAMP.

• Line number, call stack

• Who did it - USER_NAME.

• TEXT - the one I coded into my procedure. It can be whatever you want.

• Exact parameters used to run my procedure - “EXTRA” column.

• LOGGER_LEVEL - the level of my log, which is 16 in that case.

If you’re interested in more details in other columns, just execute select * from logger_logs and delve into the LOGGER documentation mentioned above.

Error logging

Now, let’s assume there was an error in giving a raise, and we want to obtain more information.

If I encountered this error in APEX, I’d probably only see ORA-01476.

That’s why I have logs in my LOGGER_LOGS table, and I can exactly track the source of my error:

And I can find out that the error occurred in line 32 of my code, becausethe value in the call_stack column says:

"ORA-01476: divisor is equal to zero ORA-06512: at "HR.UPDATE_EMPLOYEE_SALARY", line 32"

Which is 100% true:

That’s just a simple example, but imagine how easy it can be to debug/track errors if you use LOGGER across all your PL/SQL? Especially if your logic is much more complicated with nested procedures and functions.

Timing

LOGGER is also useful for calculating the time taken for your procedure to execute.

It can be achieved using logger.time_start and logger.time_stop procedures.

DECLARE
   l_scope  logger_logs.scope%type := 'update_employee_salary';
BEGIN
    logger.time_start(p_unit => l_scope);

    update_employee_salary(
        p_emp_id => 100,
        p_raise  => 500
    );
    logger.time_stop(p_unit => l_scope);
END;

The time required was 28.173 ms, which can be clearly seen after selecting logger_logs table.

Using Logger in production environments

By default, the logger is installed in debug mode. It logs at any level to the logger_logs table.

To avoid unnecessary traffic and table growth, you should set the logger level to ERROR.

--execute from LOGGER schema
BEGIN 
    logger.set_level(logger.g_error); 
END;

This way, the logger_logs table in production will be updated only with errors via logger_log.error procedure.

begin
(..)
   when others then
        --log error
      logger.log_error(
         p_text   => 'Unexpected error: ' || sqlerrm,
         p_scope  => l_scope,
         p_extra  => null,
         p_params => l_params
      );
      raise;
end;

To reset the logger level to DEBUG, run the code below.

--execute from LOGGER schema
BEGIN 
    logger.set_level(logger.g_debug); 
END;

I guess sometimes you will want to set DEBUG mode in production for a while, but you shouldn’t forget to switch it back to ERROR.

Summary

If you've never used LOGGER, I believe you'll know where to start after reading this blog post.

With this knowledge and your ideas, you should be able to make your work easier by simplifying debugging and error tracking.

However, please note that I described only the basic functionality of LOGGER.

If you want to learn more, please consult the official documentation here.

Cheers.

Rafal

PS Curious about the cover image? That’s just a family of ducks in Poland, close to Kielce.