Logging in PL/SQL

What is the best debugging tool ever invented in the history of the programming langauge? We have a choice of many powerful and cutting-edge tools these days, but still, the most powerful and handy debugging tool is logging which is written by developers themselves.

But unfortunately, PL/SQL has a weaking functionality on the logging and this is why somebody is trying to implement the fully functioning logging ability with PL/SQL.

Anyway, the most widely used way of logging is absolutely the DBMS_OUTPUT package. But it has a critical limitation that you can’t see the logs until the PL/SQL execution completes.

set serveroutput on

begin
	for idx in 1 .. 10 loop
		dbms_output.put_line(sysdate || ', ' || idx || 'th insertion');
		dbms_lock.sleep(1);
	end loop;
end;
/

2009/11/10 13:33:18, 1th insertion
2009/11/10 13:33:19, 2th insertion
2009/11/10 13:33:20, 3th insertion
2009/11/10 13:33:21, 4th insertion
2009/11/10 13:33:22, 5th insertion
2009/11/10 13:33:23, 6th insertion
2009/11/10 13:33:24, 7th insertion
2009/11/10 13:33:25, 8th insertion
2009/11/10 13:33:26, 9th insertion
2009/11/10 13:33:27, 10th insertion

PL/SQL procedure successfully completed.

Elapsed: 00:00:10.00

Another trick is to use DBMS_SYSTEM package with KSDWRT procedure. This procedure enables us to write a text to trace file(1), alert log(2) or both(3). With UTL_FILE package, you can leave a log to any text file. But you need to have a network access(telnet and/or ftp) to the database server to read those files, which is also a big limitation.

begin
	for idx in 1 .. 10 loop
		sys.dbms_system.ksdwrt(1, sysdate || ', ' || idx || 'th insertion');
		dbms_lock.sleep(1);
	end loop;
end;
/

-- C:\ORACLE\ADMIN\UKJA1021\UDUMP\ukja1021_ora_1448.trc
*** 2009-11-10 13:37:15.015
*** ACTION NAME:() 2009-11-10 13:37:15.000
*** MODULE NAME:(SQL*Plus) 2009-11-10 13:37:15.000
*** SERVICE NAME:(UKJA1021) 2009-11-10 13:37:15.000
*** SESSION ID:(140.1169) 2009-11-10 13:37:15.000
2009/11/10 13:37:15, 1th insertion
2009/11/10 13:37:16, 2th insertion
2009/11/10 13:37:17, 3th insertion
2009/11/10 13:37:18, 4th insertion
2009/11/10 13:37:19, 5th insertion
2009/11/10 13:37:20, 6th insertion
2009/11/10 13:37:21, 7th insertion
2009/11/10 13:37:22, 8th insertion
2009/11/10 13:37:23, 9th insertion
2009/11/10 13:37:24, 10th insertion

A little programming skill would be a big help on the situation like this. For instance, following example relies on the pipelined tablen function and DBMS_PIPE package to overcome the limitations mentioned above. While session A logs, another session B can read it simultaneously.

create or replace package pkg_log
as
  type log_array is table of varchar2(4000);
	procedure log(message in varchar2);
	procedure flush;
	function get_log return log_array pipelined;
end;
/

show err

create or replace package body pkg_log
as
	procedure log(message in varchar2) is
		v_status number;
	begin
		dbms_pipe.pack_message(sysdate || ', ' || message);
    v_status := dbms_pipe.send_message('log');
	end log;

	procedure flush is
		v_status number;
	begin
		dbms_pipe.pack_message('$$END$$');
		v_status := dbms_pipe.send_message('log');
	end;

	function get_log return log_array pipelined is
		v_status  number;
		v_message varchar2(4000);
	begin
		while true loop
			v_status := dbms_pipe.receive_message('log');
    	if v_status = 0 then
      	dbms_pipe.unpack_message(v_message);
      	if v_message = '$$END$$' then
      		return;
      	end if;
      	pipe row(v_message);
      	pipe row('');
    	end if;
		end loop;
		return;
	end get_log;
end;
/

show err

It works like this.

-- session #1
begin
	for idx in 1 .. 10 loop
		pkg_log.log(idx || 'th insertion');
		dbms_lock.sleep(1);
	end loop;
	pkg_log.flush;
end;
/

-- session #2
set array 2
set pages 100
select * from table(pkg_log.get_log);

COLUMN_VALUE
---------------------------------------

2009/11/10 13:30:12, 1th insertion

2009/11/10 13:30:13, 2th insertion

2009/11/10 13:30:14, 3th insertion

2009/11/10 13:30:15, 4th insertion

2009/11/10 13:30:16, 5th insertion

2009/11/10 13:30:17, 6th insertion

2009/11/10 13:30:18, 7th insertion

2009/11/10 13:30:19, 8th insertion

2009/11/10 13:30:20, 9th insertion

2009/11/10 13:30:21, 10th insertion

This is a situation where a little knowledge can play an important role to solve the problem.