Introduction
While logging can be done in numerous ways on the client side when using a database, it's often useful to also log information on the database side. For example when executing a stored procedure, running a batch etc, it's good to know what steps are done. This article describes few useful things to know when building a logging mechanism: Autonomous transactions and module/action information.
Setting up the test bench
First we'll need a few tables. One to add data to and another one where log information is going to be stored. The test table is very simple:
CREATE TABLE Test (
SomeColumn VARCHAR2(30)
);
Just a single column to put some text into.
The log table looks like this:
CREATE TABLE LogEntry (
Created DATE DEFAULT SYSDATE CONSTRAINT nn_LogEntry_Created NOT NULL,
CreatedBy VARCHAR2(30) DEFAULT USER CONSTRAINT nn_LogEntry_CreatedBy NOT NULL,
Sid NUMBER CONSTRAINT nn_LogEntry_Sid NOT NULL,
OsUser VARCHAR(20) CONSTRAINT nn_LogEntry_OsUser NOT NULL,
Machine VARCHAR(20) CONSTRAINT nn_LogEntry_Machine NOT NULL,
Process VARCHAR(12) CONSTRAINT nn_LogEntry_Process NOT NULL,
Program VARCHAR(100) CONSTRAINT nn_LogEntry_Program NOT NULL,
Module VARCHAR(100),
Action VARCHAR(100),
Text VARCHAR2(2000) CONSTRAINT nn_LogEntry_Text NOT NULL
);
The idea is to store the following information into the LogEntry table:
Created, when the log entry is created. CreatedBy, the user name that added the log entry. Sid, session identifier for the session that inserted the log entry. OsUser, the actual operating system user. Machine, name of the computer from the statement was executed. Process, process identifier from the statement was executed. Program, program from the statement was executed. Module, descriptive information about the module. Action, descriptive information about the action. Text, the actual log entry text.
Package for logging
To actually insert rows into the LogEntry table I created a package called Logging. The definition of the package looks like following.
CREATE OR REPLACE PACKAGE Logging AUTHID DEFINER
AS
PROCEDURE LogEntry (vText varchar2);
PROCEDURE LogEntryAutonomous (vText varchar2);
END logging;
/
Let's concentrate on the first procedure. The procedure looks like (partial definition of the body):
PROCEDURE LogEntry (vText varchar2) AS
BEGIN
INSERT INTO LogEntry (
Sid,
OsUser,
Machine,
Process,
Program,
Module,
Action,
Text)
SELECT vs.Sid,
vs.OsUser,
vs.Machine,
vs.Process,
vs.Program,
vs.Module,
vs.Action,
vText
FROM v$session vs
WHERE sid = sys_context('USERENV','SID');
END LogEntry;
The procedure inserts the text passed to it to the LogEntry table (what a big surprise :)). But also some information from the v$session view is stored. This information helps to track log entries, what operation came from which user or which workstation, were the operations done from the same session etc.
Normally a user doesn't have the privilege to use v$session inside a procedure. Because of this the user who owns the package must be granted a select privilege to the underlying view. The following statement grants the necessary privileges, and it must be run with SYSDBA privileges:
GRANT SELECT ON sys.v_$session TO <user name goes here>;
/
Also to get the session information from the correct session the sys_context is used to fetch the SID from the USERENV namespace.
Simple tests
Add data with a commit
Now let's do a small test to see that everything is working.
EXECUTE Logging.LogEntry('Entering test 1');
INSERT INTO Test VALUES ('Test row 1');
EXECUTE Logging.LogEntry('Test 1 ended');
COMMIT; The script adds a log entry, inserts a row, adds a second log entry and then commits the transaction. If we look at the data in the Test table, it looks like
SELECT * FROM Test;
SOMECOLUMN
----------
Test row 1
And the data in the LogEntry table is as foreseeable
SELECT TO_CHAR(le.Created, 'dd.mm.yyyy hh24.mi.ss') as Created,
le.Sid,
le.OsUser,
le.Machine,
le.Process,
le.Program,
le.Text
FROM LogEntry le
ORDER BY le.Created DESC;
The results:
CREATED SID OSUSER MACHINE PROCESS PROGRAM TEXT
------------------- --- ------ ------- ------- ------------- ---------------
29.04.2012 23.00.12 94 mika MyBox 2056 SQL Developer Test 1 ended
29.04.2012 23.00.10 94 mika MyBox 2056 SQL Developer Entering test 1
So everything is as expected.
Add data and roll back the operation
Let's do another test:
EXECUTE Logging.LogEntry('Entering test 2');
INSERT INTO Test VALUES ('Test row 2');
EXECUTE Logging.LogEntry('Test 2 ended');
ROLLBACK; Basically this is the same thing as the first test, only this time the transaction isn't committed but rolled back. And if we have a look at the data in the Test table, nothing has been changed (as supposed).
SELECT * FROM Test;
SOMECOLUMN
----------
Test row 1
Now, if we list the contents of the LogEntry table, we'll see that there's no changes in this table either.
SELECT TO_CHAR(le.Created, 'dd.mm.yyyy hh24.mi.ss') as Created,
le.Sid,
le.OsUser,
le.Machine,
le.Process,
le.Program,
le.Text
FROM LogEntry le
ORDER BY le.Created DESC;
The results:
CREATED SID OSUSER MACHINE PROCESS PROGRAM TEXT
------------------- --- ------ ------- ------- ------------- ---------------
29.04.2012 23.00.12 94 mika MyBox 2056 SQL Developer Test 1 ended
29.04.2012 23.00.10 94 mika MyBox 2056 SQL Developer Entering test 1
However, it would have been nice to know that something has been done even though it has been rolled back. For example if the rolling back was done because something went wrong, we could have wrote a log entry about the situation but all interesting information would have been gone because of the rollback.
Using an autonomous transaction
First, what is an autonomous transaction? An autonomous transaction shouldn't be mixed with a nested transaction, it's a completely different beast. While a nested transaction shares the same context as the outer transaction, an autonomous transaction does not. Perhaps the easiest way is to consider an autonomous transaction as a parallel, separate transaction.
When an autonomous transaction is called, the original transaction context is left and a 'new' one begins. When this transaction ends the execution comes back to the original transaction. This means:
- If the autonomous transaction executes a commit, the modified data from the autonomous transaction is visible to all transactions immediately.
- The two transactions share no locks.
- Even if the actual transaction executes a rollback, the data committed in an autonomous transaction remains.
Let's have a look at the other procedure in the package:
PROCEDURE LogEntryAutonomous (vText varchar2) AS
PRAGMA AUTONOMOUS_TRANSACTION;
BEGIN
LogEntry(vText);
COMMIT;
END LogEntryAutonomous;
Basically this procedure just calls the previously defined procedure, but there are two things to note.
PRAGMA AUTONOMOUS_TRANSACTION, this pragma defines that the procedure uses an autonomous transaction. The scope is the whole procedure.
Also note the commit in the end of the procedure. Even though the first procedure didn't do a commit or rollback but the decision was left to the caller of the procedure, now the decision must be done inside the autonomous block before returning to the actual transaction.
If the transaction isn't committed or rolled back in the end of the block, an ORA-06519 will be raised. The explanation for this error is:
06519. 00000 - "active autonomous transaction detected and rolled back"
*Cause: Before returning from an autonomous PL/SQL block, all autonomous
transactions started within the block must be completed (either
committed or rolled back). If not, the active autonomous
transaction is implicitly rolled back and this error is raised.
*Action: Ensure that before returning from an autonomous PL/SQL block,
any active autonomous transactions are explicitly committed
or rolled back.
Now let's run a test.
EXECUTE Logging.LogEntryAutonomous('Entering test 3');
INSERT INTO Test VALUES ('Test row 3');
EXECUTE Logging.LogEntryAutonomous('Test 3 ended');
ROLLBACK; As earlier some modifications are done and the transaction is rolled back. The data in the test table remains unmodified but what about the data in the LogEntry table.
SELECT TO_CHAR(le.Created, 'dd.mm.yyyy hh24.mi.ss') as Created,
le.Sid,
le.OsUser,
le.Machine,
le.Process,
le.Program,
le.Text
FROM LogEntry le
ORDER BY le.Created DESC;
The data looks now like following:
CREATED SID OSUSER MACHINE PROCESS PROGRAM TEXT
------------------- --- ------ ------- ------- ------------- ---------------
29.04.2012 23.46.26 94 mika MyBox 2056 SQL Developer Test 3 ended
29.04.2012 23.46.24 94 mika MyBox 2056 SQL Developer Entering test 3
29.04.2012 23.00.12 94 mika MyBox 2056 SQL Developer Test 1 ended
29.04.2012 23.00.10 94 mika MyBox 2056 SQL Developer Entering test 1
So even if the transaction was rolled back, now the log entries are shown since the autonomous transaction was committed.
Adding extra information
The previous examples gathered some useful information from the client side. However, if the log entries are recorded for example from a stored procedure, it may not be enough to know the calling program or session.
Oracle has a DBMS_APPLICATION_INFO package which can be used to set more information also from the calling client. In the scope of this article the interesting procedures are:
SET_MODULE, sets the current module and action SET_ACTION, sets the current action
By using these procedures the client application can set more information about the context on the client side.
A small test using the DBMS_APPLICATION_INFO:
EXECUTE DBMS_APPLICATION_INFO.SET_MODULE('Test module', 'First action');
EXECUTE Logging.LogEntryAutonomous('Entering test 4');
EXECUTE DBMS_APPLICATION_INFO.SET_ACTION('Some insert sequence');
EXECUTE Logging.LogEntryAutonomous('Insert row 4.1');
INSERT INTO Test VALUES ('Test row 4.1');
EXECUTE Logging.LogEntryAutonomous('Insert row 4.2');
INSERT INTO Test VALUES ('Test row 4.2');
EXECUTE Logging.LogEntryAutonomous('Test 4 ended');
ROLLBACK;First the module and the initial action are set and a log entry is created. After this, a new action is set and few inserts are run inside this action. In the end, a log entry is added and the transaction is rolled back.
After running the script above, the data in LogEntry is fetched using
SELECT TO_CHAR(le.Created, 'dd.mm.yyyy hh24.mi.ss') as Created,
le.Sid,
le.Program,
le.Module,
le.Action,
le.Text
FROM LogEntry le
ORDER BY le.Created DESC;
And the results are as following. The latest 4 rows are from this batch and the previous ones from previous batches.
CREATED SID PROGRAM MODULE ACTION TEXT
------------------- --- ------------- ----------- -------------------- ---------------
30.04.2012 00.01.44 94 SQL Developer Test module Some insert sequence Test 4 ended
30.04.2012 00.01.41 94 SQL Developer Test module Some insert sequence Insert row 4.2
30.04.2012 00.01.37 94 SQL Developer Test module Some insert sequence Insert row 4.1
30.04.2012 00.01.35 94 SQL Developer Test module First action Entering test 4
29.04.2012 23.46.26 94 SQL Developer Test module Some insert Test 3 ended
29.04.2012 23.46.24 94 SQL Developer Test module Some insert Entering test 3
29.04.2012 23.00.12 94 SQL Developer Test module Some insert Test 1 ended
29.04.2012 23.00.10 94 SQL Developer Test module Some insert Entering test 1
Final words
Autonomous transactions are very handy in several situations. Logging is one of them. When using them for the first time, remember that they are not nested transactions and don't behave like one.
Also properly using module and action information, the execution context can be more closely monitored from the database side. This gives lots of useful information especially when solving problems.
History
- April 30, 2012: Article created.
