ODTUG Kaleidoscope: HOTSOS Instrumentation Library for Oracle

Last week six of us at AMIS attended the ODTUG Kaleidoscope conference in Daytona Beach, FL. I always need some time to digest all the information that was presented so that’s why I am writing this Blog now.

One of the sessions I really enjoyed was given by Eric Evans from Hotsos, titled "Oracle Code Instrumentation, or How I Stopped Worrying and Love Properly Scoped Trace Files". He talked about the Open Source project called HOTSOS Oracle Instrumentation Library. The presentation was all about, well…. Instrumentation.

Using DBMS_APPLICATION_INFO you can instrument your code. When you query for instance V$SESSION, you can see the MODULE, ACTION and CLIENT_INFO that you have set when you call the before mentioned DBMS* package. This call needs to be done at the beginning of a procedure, at the end of the procedure you simply reset the MODULE, ACTION and CLIENT_INFO.

create or replace<br />procedure proc<br />is<br />begin<br />   dbms_application_info.set_module (module_name =&gt; 'PROC'<br />                                    ,action_name =&gt; 'testing'<br />                                    );<br />   dbms_application_info.set_client_info (client_info =&gt; user);<br />   -- Do some interesting PL/SQL Stuff here<br />   dbms_application_info.set_module (module_name =&gt; null<br />                                    ,action_name =&gt; null<br />                                    );<br />   dbms_application_info.set_client_info (client_info =&gt; null);<br />end proc;<br />

While this procedure is executing, the V$SESSION looks like this:

     SID MODULE                              ACTION                              CLIENT_INFO<br />-------- ----------------------------------- ----------------------------------- ------------<br />...<br />     139 PROC                                testing                             ALEX<br />...<br />

However, there is something you need to aware of. When your procedure code calls another procedure (and I sure hope it does ), the information in the MODULE, ACTION and CLIENT_INFO is lost when you come back to the calling program. Calling another procedure with similar calls to the DBMS_APPLICATION_INFO will nullify the MODULE, ACTION and CLIENT_INFO when you return from the other procedure. To resolve this issue you need to store the MODULE, ACTION and CLIENT_INFO prior to calling another procedure and restore the MODULE, ACTION and CLIENT_INFO after the procedure call. Of course you can wrap the calls to DBMS_APPLICATION_INFO to store the MODULE, ACTION and CLIENT_INFO and keep a stack of calls and pop them when needed, or you can use HOTSOS_ILO.

Hotsos_ILO does exactly that and more. I am still playing around with it, so I am still trying to figure out all the details. This is just to give you a general idea of what the HOTSOS_ILO is capable of.

For my first test I created a simple procedure:

SQL> create or replace
  2  procedure hotsos_test
  3  is
  4  begin
  5     hotsos_ilo_task.begin_task (module => 'HotSos Test'
  6                                ,action => 'First call to the ILO'
  7                                ,COMMENT => 'Testing the ILO...'
  8                                );
  9     -- Some very interesting stuff goes here
 10     null;
 11     hotsos_ilo_task.end_task;
 12  exception
 13     when others
 14     then
 15        hotsos_ilo_task.end_task (sqlerrm);
 16  end hotsos_test;
 17  /

Procedure created.

This procedure basically does nothing, it only makes calls to the HOTSOS_ILO_TASK package. When you execute the procedure in the following manner you can see the MODULE and ACTION in the V$SESSION view

SQL> begin
  2     hotsos_ilo_task.set_config (trace => true
  3                                ,write_wall_time => true
  4                                );
  5     hotsos_ilo_task.set_nesting_level (5);
  6     -- Test statements here
  7     hotsos_test;
  8  end;
  9  /

PL/SQL procedure successfully completed.

SQL> select sid, module, action, client_info
  2    from v$session;

     SID MODULE                              ACTION                              CLIENT_INFO
-------- ----------------------------------- ----------------------------------- --------------
     133 HotSos Test                         First call to the ILO
...

A "side effect" is that it also creates a trace file which includes the same information regarding the MODULE, ACTION and CLIENT_INFO. Here is a screenshot of the generated tracefile where I highlighted the HOTSOS tags.

The HOTSOS_ILO_TASK package also keeps track of nested procedure calls. To demonstrate that I created another procedure which calls the procedure I created before.

SQL> create or replace
  2  procedure hotsos_test_2
  3  is
  4  begin
  5     hotsos_ilo_task.begin_task (module => 'HotSos Test 2'
  6                                ,action => 'Nesting the call to Test 1'
  7                                ,COMMENT => 'Trying out Nesting'
  8                                );
  9     hotsos_test;
 10     hotsos_ilo_task.end_task;
 11  exception
 12     when others
 13     then
 14        hotsos_ilo_task.end_task (sqlerrm);
 15  end hotsos_test_2;
 16  /

Procedure created.

SQL> begin
  2     hotsos_ilo_task.set_config (TRACE => true
  3                                ,write_wall_time => true
  4                                );
  5     hotsos_ilo_task.set_nesting_level (5);
  6     -- Test statements here
  7     hotsos_test_2;
  8  end;
  9  /

PL/SQL procedure successfully completed.

Looking at the generated tracefile shows the effect of this nested procedure call. Here is an excerpt of the trace file, but you can take a look at the whole tracefile right here.

...
HOTSOS_ILO_TASK.BEGIN_TASK[][HotSos Test 2][Nesting the call to Test 1][AMIS\alex_n~14-317-737~sqlplusw.exe~SYS$USERS][Trying out Nesting]
...
HOTSOS_ILO_TASK.BEGIN_TASK[][HotSos Test][First call to the ILO][AMIS\alex_n~14-317-737~sqlplusw.exe~SYS$USERS][Testing the ILO...]
...
HOTSOS_ILO_TASK.END_TASK[][HotSos Test][First call to the ILO][AMIS\alex_n~14-317-737~sqlplusw.exe~SYS$USERS][Testing the ILO...]
...
HOTSOS_ILO_TASK.END_TASK[][HotSos Test 2][Nesting the call to Test 1][AMIS\alex_n~14-317-737~sqlplusw.exe~SYS$USERS][Trying out Nesting]
...

The download of the Instrumentation Library also includes a HOTSOS_ILO_TIMER package and a HOTSOS_SYS_UTILS package. The latter one needs to be installed into the SYS schema. This package takes care of writing information to the tracefile.

When I showed this to my colleague Gerwin Hendriksen, who does a lot of performance analysis, he seemed to be thrilled about the possibility of a properly scoped trace file.