Frederick Tang Weblog

I worked on a project to develop a domain index using the Oracle Data Cartridge Interface last year, When I was testing my code, I needed to know what the progress and state of the PL/SQL execution, and found dbms_output.put_line() inadequate as it only outputs when the call is returned to SQL*Plus, i.e. the output is not displayed during run-time. This is better explained by Robert Vollman. That was until Douglas showed me how to use DBMS_APPLICATION_INFO, MODULE, ACTION and CLIENT_INFO.

Whilst reading blogs of my favourite Oracle bloggers, I found Instrumentation Library for Oracle (ILO) developed by Method-R, presented here by Karen Morton. Instrumentation is described by Tom Kyte in this blog post. The idea behind ILO is quite interesting, a comment by Cary Millsap reveals the motivation behind this tool. I downloaded ILO 2.2, installed it on my 10g test database and test ran a very simple test case. I will write a few words about what I found.

I start off with a very simple test code, I granted myself privilege to execute dbms_lock:

DECLARE
BEGIN
   -- Start Task 1
   ILO_TASK.BEGIN_TASK(module=>'ILO Tester', action=>'Task 1', comment=>'Time 0s', begin_time=>sysdate);
   dbms_lock.sleep(10);
   -- Start Task 2
   ILO_TASK.BEGIN_TASK(module=>'ILO Tester', action=>'Task 2', comment=>'Time 10s',begin_time=>sysdate);
   dbms_lock.sleep(10);

   -- End Task 1
   ILO_TASK.END_TASK(end_time=>sysdate);
   -- End Task 2
   ILO_TASK.END_TASK(end_time=>sysdate);
EXCEPTION
   WHEN OTHERS
   THEN
      dbms_output.put_line('Exception thrown');
      ILO_TASK.END_ALL_TASKS(p_error_num=>SQLCODE, p_end_time=>sysdate);
   END;

I am logged on the database using SQL*Plus, before I execute the above PL/SQL block, my session information looks like this:

SQL> select module, action, client_info from v$session where username='FREDT';

MODULE          ACTION          CLIENT_INFO
--------------- --------------- ---------------
SQL*Plus

When the PL/SQL block is executed:

MODULE          ACTION          CLIENT_INFO
--------------- --------------- ---------------
ILO Tester      Task 1

10 seconds later inside the PL/SQL block:

MODULE          ACTION          CLIENT_INFO
--------------- --------------- ---------------
ILO Tester      Task 2

10 seconds more, and PL/SQL block exits:

MODULE          ACTION          CLIENT_INFO
--------------- --------------- ---------------
SQL*Plus

ILO manages tasks in a stack like data structure, therefore, a developer can start multiple tasks using BEGIN_TASK and end the last (started) task using END_TASK, or end all tasks using END_ALL_TASKS. To view session information, one needs either DBA or SELECT ANY DICTIONARY privilege.

This most basic use of ILO requires continuous query on v$session to get anything meaningful. If one wants to take this further, ILO provides the framework to do so. For example, one can enable tracing by inserting this line of code at the beginning of the PL/SQL block (after the line BEGIN):

ILO_TIMER.set_mark_all_tasks_interesting(true, true);

A trace file will be produced in USER_DUMP_DEST, and one can find ILO information inside the trace file. It seems feasible to develop a script which can extract this information out of a trace file into something meaningful or simply more human-readable:

ILO_TASK.BEGIN_TASK[][ILO Tester][Task 1][oracle~pts/2~sqlplus@moddb1 (TNS V1-V3)~SYS$USERS][Time 0s]
*** 2009-01-13 16:50:02.919
*** ACTION NAME: (Task 1) 2009-01-13 16:50:02.919
*** MODULE NAME: (ILO Tester) 2009-01-13 16:50:02.919

ILO_TASK.BEGIN_TASK[][ILO Tester][Task 2][oracle~pts/2~sqlplus@moddb1 (TNS V1-V3)~SYS$USERS][Time 10s]
*** 2009-01-13 16:50:12.921
*** ACTION NAME: (Task 2) 2009-01-13 16:50:12.921
*** MODULE NAME: (ILO Tester) 2009-01-13 16:50:12.921

ILO_TASK.END_TASK[][ILO Tester][Task 2][oracle~pts/2~sqlplus@moddb1 (TNS V1-V3)~SYS$USERS][Time 10s][]
*** ACTION NAME: (Task 1) 2009-01-13 16:50:22.931
*** MODULE NAME: (ILO Tester) 2009-01-13 16:50:22.931

ILO_TASK.END_TASK[][ILO Tester][Task 1][oracle~pts/2~sqlplus@moddb1 (TNS V1-V3)~SYS$USERS][Time 0s][]
*** ACTION NAME: () 2009-01-13 16:50:22.931
*** MODULE NAME: (SQL*Plus) 2009-01-13 16:50:22.931

After reading the ILO source code, and playing around, I could think of a few more ways to take this idea further, but it will require additional development of the library. Most of the “hooks” are inside ILO_TIMER. Indeed, I believe that is why ILO is licensed as LGPL, allowing developers the flexibility to decide how they want to make use of the instrumentation.

Perhaps I will write about these ideas in another post. My parting thoughts were how to have Developers instrument their code the same way, if I am the DBA. Perhaps, if DBA=Developer then it would be a different story. I think about Apache Log4j and if the same adoption can be applied to a tool like ILO, that would be great.