PL/SQLでのLoggingの使用

Programming Langaugeと言うのが開発された以降発明された最高のデバッグツールはなんでしょうか。精巧で強力なデバッグツールがたくさんありますがなお一番強力で一番よく使われるデバッグツールは開発者が自分で記録するログ(Log)であります。

しかしPL/SQLは相対的にログを残す機能がとても弱いです。この問題を話し合ってみみます。

一番よく使用されるのがDBMS_OUTPUTパッケージでしょう。でも、PL/SQLブロックの実行が終わった後で記録されるので実行時間が長いPL/SQLブロックをデバッグする場合は相当不便です。

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

他のトリックは次のようにDBMS_SYSTEMパッケージを用いてトレースファイル(1)やAlert Logファイル(2)、または両方(3)に記録することです。TAILとかテキストエディターでファイルを開けてみればいいでしょう。UTL_FILEパッケージを利用して別途のファイルに記録して確認することもできます。この方法の一つデメリットはログファイルがサーバーにあると言うことです。ネットワーク接続や保安の問題によって使用しにくい場合が多いです。

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

プログラミングに興味があったらもっと良い方法が作れます。次の例を見てください。Pipelined Table FunctionとDBMS_PIPEパッケージを利用しています。特定セッションでログを記録すれば他のセッションではSELECT文を利用してログの内容を確認できます。上で見た二つの方法をみんな乗り越えています。

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

使用例は次のようです。

-- 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

考え方に沿って無数な方法でログを管理することができます。重要なものは自分が必要なツールはたまに自分で作ることができれば良いと言うことです。