Tony’s Oracle Tips

March 3, 2017

Object oriented logging

Filed under: Uncategorized — tonyhasler @ 11:34 am

It is a very common requirement. You need to be able to log the start and end of procedure and function calls. You also need to log error and exception events and sometimes some informational messages as well. This is typically done by writing a simple logging package that uses autonomous transactions so that any transaction rollback does not rollback the diagnostic logging information as well. Apart from logging text (and usually other things as well) the package typically logs the name of the package and procedure performing the logging. Here is a simplified example that might be implemented at a mythical AJAX company.

create or replace PACKAGE ajax_log_pkg IS
    PROCEDURE log_message (
        p_package_name     VARCHAR2,
        p_procedure_name   VARCHAR2,
        p_message          VARCHAR2
    );
END ajax_log_pkg;
/

create or replace PACKAGE BODY ajax_log_pkg IS
    PROCEDURE log_message (
        p_package_name     VARCHAR2,
        p_procedure_name   VARCHAR2,
        p_message          VARCHAR2 
    ) IS
        PRAGMA autonomous_transaction;
    BEGIN
        INSERT INTO ajax_log_table (
            log_timestamp,
            package_name,
            procedure_name,
            message
        ) VALUES (
            systimestamp,
            p_package_name,
            p_procedure_name,
            p_message
        );

        COMMIT;
    END log_message;

END ajax_log_pkg;
/

The package has a prefix of the company name and a suffix of “_pkg”, a curiously common convention. Here is how such a package might be used (once again simplified).

create or replace PACKAGE ajax_log_demo_pkg AS
    PROCEDURE inner_proc;
    PROCEDURE outer_proc;
END ajax_log_demo_pkg;
/

create or replace PACKAGE BODY ajax_log_demo_pkg AS
    g_package_name     CONSTANT VARCHAR2(30) := 'log_demo_pkg';

    PROCEDURE inner_proc IS
        v_procedure_name   CONSTANT VARCHAR2(50) := 'inner_proc';
    BEGIN
        ajax_log_pkg.log_message(
            g_package_name,
        v_procedure_name,'START');
        -- Do something
        ajax_log_pkg.log_message(
            g_package_name,
        v_procedure_name,'END');
    END inner_proc;

    PROCEDURE outer_proc IS
        v_procedure_name   CONSTANT VARCHAR2(50) := 'outer_proc';
    BEGIN
        ajax_log_pkg.log_message(
            g_package_name,
        v_procedure_name,'START');
        ajax_log_pkg.log_message(
            g_package_name,
        v_procedure_name,'Before call to inner_proc');
        inner_proc ();
        ajax_log_pkg.log_message(
            g_package_name,
        v_procedure_name,'After call to inner_proc');
        ajax_log_pkg.log_message(
            g_package_name,
        v_procedure_name,'END');
    END outer_proc;

END ajax_log_demo_pkg;

We can see that there is a lot of wasted typing here. The calling package name and calling procedure name are specified repeatedly on each call. Still cut-and-paste can limit the productivity cost. What else is there to do? Presumably nothing? Every logging implementation that I have seen has looked very similar to this.

This is roughly what the entries in AJAX_LOG_TABLE might look like after a call to ajax_log_demo_pkg.outer_proc:

03-MAR-17 10.05.27 log_demo_pkg outer_proc START
03-MAR-17 10.05.27 log_demo_pkg outer_proc Before call to inner_proc
03-MAR-17 10.05.27 log_demo_pkg inner_proc START
03-MAR-17 10.05.27 log_demo_pkg inner_proc END
03-MAR-17 10.05.27 log_demo_pkg outer_proc After call to inner_proc
03-MAR-17 10.05.27 log_demo_pkg outer_proc END

The other day a curious thought sped briefly past my mind as I typed CTRL/V. “This would be a lot easier in Java”, I thought. Then I paused and started a short conversation with myself:

“Tony, why do you think ANYTHING in Java would be easier than PL/SQL”?
“Well, Tony, in Java you have classes not packages. You could create an instance of a logging object and avoid specifying the calling package and procedure names on each call”
“Good point, Tony…..”

At that point I sat straight upright in my chair and opened my eyes wide open.

“Tony, Oracle has that capability! It has been there since 8i it is just that we have all forgotten about it!”

It took just moments to implement an object version of AJAX_LOG_PKG.

create or replace TYPE ajax_log_typ AS OBJECT (
    o_package_name     VARCHAR2(30),
    o_procedure_name   VARCHAR2(30),

    MEMBER PROCEDURE log_message (
        p_message   VARCHAR2
    )
) ;
/

create or replace TYPE BODY ajax_log_typ AS
    MEMBER PROCEDURE log_message (
        p_message   VARCHAR2 
    ) IS
        PRAGMA autonomous_transaction;
    BEGIN
        INSERT INTO ajax_log_table (
            log_timestamp,
            package_name,
            procedure_name,
            message
        ) VALUES (
            systimestamp,
            o_package_name,
            o_procedure_name,
            p_message
        );

        COMMIT;
    END log_message;

END;

The object specification replaces the package specification and the object body replaces the package body. I then added two members to the class for the calling package name and the calling procedure name. As a consequence, we can eliminate these two parameters from the member procedure or procedures. Look at how the object-oriented logging implementation is used:

create or replace PACKAGE ajax_log_demo_pkg2 AS
    PROCEDURE inner_proc;
    PROCEDURE outer_proc;
END ajax_log_demo_pkg2;
/

create or replace PACKAGE BODY ajax_log_demo_pkg2 AS
    g_package_name     CONSTANT VARCHAR2(30) := 'log_demo_pkg';

    PROCEDURE inner_proc IS
           o_log              ajax_log_typ := ajax_log_typ(
            g_package_name,
        'inner_proc');
    BEGIN
        o_log.log_message(
            'START'
        );
        -- Do something
        o_log.log_message(
            'END'
        );
    END inner_proc;

    PROCEDURE outer_proc IS
        o_log   ajax_log_typ := ajax_log_typ(
            g_package_name,
        'outer_proc');
    BEGIN
        o_log.log_message(
            'START'
        );
        o_log.log_message(
            'Before call to inner_proc'
        );
        inner_proc ();
        o_log.log_message(
            'After call to inner_proc'
        );
        o_log.log_message(
            'END'
        );
    END outer_proc;

END ajax_log_demo_pkg2;

Each procedure creates a new instance of AJAX_LOG_TYP object and specifies the package and procedure name. Subsequent calls just need to reference the local variable and the message to log; the rest of the context is retrieved from the object instance.
Hardly rocket science and yet I am quite sure that I am very far from alone in missing this neat trick for more years than I care to admit.

Advertisements

2 Comments »

  1. Nice!. I’ll definitely look to use this.

    You can use $$PLSQL_UNIT to replace g_package_name and further reduced the wasted typing, as shown:

    o_log ajax_log_typ := ajax_log_typ( $$PLSQL_UNIT, ‘inner_proc’ );

    Comment by Kevan Gelling — March 8, 2017 @ 10:03 am | Reply

    • Quite true! The code formatter in SQL developer 4.2 messes up $$PLSQL_UNIT so that is why I didn’t use it.

      Comment by tonyhasler — March 9, 2017 @ 6:01 pm | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Blog at WordPress.com.

%d bloggers like this: