7 Ways to Log Data in the Oracle Database

Updated 14-Dec-2015: Corrected image for 6. Pipelined Function

Overview

1. Insert into Table
2. AUTONOMOUS_TRANSACTION
3. DBMS_APPLICATION_INFO
4. SET_SESSION_LONGOPS
5. DBMS_OUTPUT
6. Pipelined Function
7. DBMS_PIPE

Each section contains:

• Executable code
• An example output of the code
• "The Good"
• "The Bad"

All code has been tested in SQL*Plus on Oracle11gXE. The following setup must be run as "SYS as SYSDBA". This setup must be complete before running code in any section.

create user demo identified by demo
   default tablespace users;

grant connect, resource to demo;
grant select on SYS.V_$SESSION to demo;
grant execute on DBMS_LOCK to demo;
grant execute on DBMS_PIPE to demo;
grant create job to demo;

connect demo/demo

create table demo_tab
   (dtm  timestamp(6)
   ,usr  varchar2(30)
   ,sid  number
   ,txt  varchar2(4000)
   ,loc  varchar2(4000)
   );

create trigger demo_tab_bi before insert
   on demo_tab for each row
begin
   if :new.dtm is null then
      :new.dtm := systimestamp;
   end if;
   if :new.usr is null then
      :new.usr := USER;
   end if;
   if :new.sid is null then
      :new.sid := sys_context('USERENV','SID');
   end if;
   if :new.loc is null then
      :new.loc := DBMS_UTILITY.FORMAT_CALL_STACK;
   end if;
end demo_tab_bi;
/

create procedure log_demo (in_text in varchar2)
is PRAGMA AUTONOMOUS_TRANSACTION;
begin
   insert into demo_tab (txt) values (in_text);
   commit;
end log_demo;
/

create or replace type pipeline_demo_tab
  as table of varchar2(40);
/

create or replace function pipeline_demo
 return pipeline_demo_tab pipelined as
begin
  pipe row('Logging Demo');
  for i in 1 .. 5 loop
    dbms_lock.sleep(1);    -- delay between iterations
    pipe row('  Test: ' || i);
  end loop;
end;
/

create package pipe_demo as
   PIPE_NAME    CONSTANT varchar2(15) := 'Logging Demo';
   status       number;
   procedure log(in_txt in demo_tab.txt%TYPE);
   procedure run_server;
   procedure stop_server;
end pipe_demo;
/

create package body pipe_demo as
procedure log(in_txt in demo_tab.txt%TYPE) is begin
   dbms_pipe.reset_buffer;
   dbms_pipe.pack_message('LOG');
   dbms_pipe.pack_message(to_char(systimestamp,'YYYYMMDDHH24MISS.FF6'));
   dbms_pipe.pack_message(USER);
   dbms_pipe.pack_message(to_number(sys_context('USERENV', 'SID')));
   dbms_pipe.pack_message(DBMS_UTILITY.FORMAT_CALL_STACK);
   dbms_pipe.pack_message(in_txt);
   status := dbms_pipe.send_message(PIPE_NAME);
end log;
procedure run_server is
   cmd_buff     varchar2(30);
   dtm_buff     varchar2(25);
   usr_buff     demo_tab.usr%TYPE;
   sid_buff     demo_tab.sid%TYPE;
   loc_buff     demo_tab.loc%TYPE;
   txt_buff     demo_tab.txt%TYPE;
begin
   insert into demo_tab (txt) values ('Server started');
   commit;
   loop
      loop -- Allow the PIPE Read timeout to prevent "freezing"
         status := dbms_pipe.receive_message (PIPE_NAME, 10);  -- seconds
         exit when status != 1;   -- Status 1 is a timeout error
      end loop;
      if status != 0 then
         insert into demo_tab (txt) values ('Received status ' || status);
         commit; exit;
      end if;
      dbms_pipe.unpack_message(cmd_buff);
      if upper(cmd_buff) = 'LOG' then
         dbms_pipe.unpack_message(dtm_buff);
         dbms_pipe.unpack_message(usr_buff);
         dbms_pipe.unpack_message(sid_buff);
         dbms_pipe.unpack_message(loc_buff);
         dbms_pipe.unpack_message(txt_buff);
         insert into demo_tab (dtm, usr, sid, loc, txt)
            values (to_timestamp(dtm_buff,'YYYYMMDDHH24MISS.FF6'),
               usr_buff, sid_buff, loc_buff, txt_buff);
         commit;
      else
         insert into demo_tab (txt) values ('Received ' || cmd_buff);
         commit; exit;
      end if;
   end loop;
end run_server;
procedure stop_server is begin
   dbms_pipe.reset_buffer;
   dbms_pipe.pack_message('STOP');
   status := dbms_pipe.send_message(PIPE_NAME);
end stop_server;
end pipe_demo;
/

1. Insert into Table

connect demo/demo
alter session set NLS_TIMESTAMP_FORMAT='DD-MON-YYYY HH24:MI:SS.FF6';
column dtm format a27
column usr format a4
column sid format 99999
column txt format a40 wrap

insert into demo_tab (txt) values ('I want to log this text');

select dtm, usr, sid, txt from demo_tab order by dtm desc;

rollback;

select dtm, usr, sid, txt from demo_tab order by dtm desc;

The Good:

• Simple.
• Reasonably fast.

The Bad:

• Not necessarily persistent - a ROLLBACK can remove uncommitted records from the DEMO_TAB table.
• Unavailable to "other" sessions until COMMIT.

2. Autonomous_Transaction

connect demo/demo
alter session set NLS_TIMESTAMP_FORMAT='DD-MON-YYYY HH24:MI:SS.FF6';
column dtm format a27
column usr format a4
column sid format 99999
column txt format a40 wrap

BEGIN
   log_demo('No rollback on this record');
   rollback;
END;
/

select dtm, usr, sid, txt from demo_tab order by dtm desc;

The Good:

• Persistent - a ROLLBACK will not remove records from the DEMO_TAB table.
• Immediately available to "other" sessions.

The Bad:

• Requires a procedure or a package.
• Performance penalty - Redolog Buffer Flush during COMMIT.

3. DBMS_APPLICATION_INFO

connect demo/demo
column sid format 99999
column client_info format a20
column module format a20
column action format a30

BEGIN
   DBMS_APPLICATION_INFO.set_client_info
      (client_info => 'Logging Demo');
   DBMS_APPLICATION_INFO.set_module
      (module_name => 'Demo3' 
      ,action_name => 'Temporary Entry'); 
END;
/

select sid, client_info, module, action from V$SESSION
 where client_info = 'Logging Demo';

The Good:

• Simple.
• Very fast.
• Immediately available to "other" sessions.

The Bad:

• Security - Need access to V$SESSION
• Not persistent - V$SESSION data is automatically removed from memory.
• Not really a log - Only 1 V$SESSION entry per session.

4. SET_SESSION_LONGOPS

connect demo/demo
column sid format 99999
column opname format a30
column sofar format 9999
column units format a5

DECLARE
   ri  binary_integer := dbms_application_info.set_session_longops_nohint;
   sn  binary_integer;   -- slno
BEGIN
   DBMS_APPLICATION_INFO.set_session_longops
      (rindex => ri, slno => sn, units => 'un',sofar => 0,
       op_name => 'Logging Demo', totalwork => 1);
   DBMS_APPLICATION_INFO.set_session_longops
      (rindex => ri, slno => sn , sofar => 1,
      totalwork => 1);
END;
/

select sid, opname, sofar, totalwork, units from v$session_longops
 where opname = 'Logging Demo' order by start_time desc;

The Good:

• Very Fast.
• Automatically calculates TIME_REMAINING.
• Immediately available to "other" sessions.

The Bad:

• Security - Need access to V$SESSION_LONGOPS.
• Can require some thought to properly setup.
• Not persistent - V$SESSION_LONGOPS data is automatically removed from memory.

5. DBMS_OUTPUT

connect demo/demo
set serveroutput on

BEGIN
   DBMS_OUTPUT.put_line('Logging Demo');
   for i in 1 .. 5 loop
      dbms_lock.sleep(1);    -- delay between iterations
      DBMS_OUTPUT.put_line('  Test: ' || i);
   end loop;
END;
/

The Good:

• Simple.
• Very Fast.
• Can read DBMS_OUTPUT buffer within session PL/SQL.

The Bad:

• Not persistent - Stored in DBMS_OUTPUT buffers.
• Client must wait for call to complete before reading buffer.
• Never available to "other" sessions.

6. Pipelined Function

connect demo/demo
set arraysize 1

select * from table(pipeline_demo);

The Good:

• Fast.
• Results returned while PL/SQL is executing.

The Bad:

• Not persistent - Results returned via SQL SELECT.
• Must hide DML behind autonomous_transaction
• Strange way to run PL/SQL, using an SQL SELECT.
• Never available to "other" sessions.

7. DBMS_PIPE

connect demo/demo
alter session set NLS_TIMESTAMP_FORMAT='DD-MON-YYYY HH24:MI:SS.FF6';
column dtm format a27
column usr format a4
column sid format 99999
column txt format a40 wrap

BEGIN
   DBMS_SCHEDULER.create_job
      (job_name   => 'pipe_demo_server'
      ,job_type   => 'PLSQL_BLOCK'
      ,job_action => 'BEGIN pipe_demo.run_server; END;'
      ,enabled    => TRUE);END;
/

--  PAUSE HERE to allow the job to start
select job_name, session_id from user_scheduler_running_jobs;

BEGIN
   log_demo('Sending message on pipe.');
   pipe_demo.log('This is the pipe message');
   log_demo('Sent message on pipe.');
   pipe_demo.stop_server;
END;
/

--  PAUSE HERE to allow the job to complete
select job_name, session_id from user_scheduler_running_jobs;

select dtm, usr, sid, txt from demo_tab order by dtm desc;

The Good:

• Very Fast.
• If configured, can be available to multiple "other" sessions.

The Bad:

• Complicated to Setup.
• Not persistent while in the pipe.
• Reading a pipe can hang, causing the database to "freeze'.

Cleanup

Cleanup code must be run as "SYS" or "SYSTEM".

BEGIN
   demo.pipe_demo.stop_server;
END;
/

drop user demo cascade;