ODTUG Kaleidoscope: HOTSOS Instrumentation Library for Oracle

3

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&gt; create or replace
  2  procedure hotsos_test
  3  is
  4  begin
  5     hotsos_ilo_task.begin_task (module =&gt; 'HotSos Test'
  6                                ,action =&gt; 'First call to the ILO'
  7                                ,COMMENT =&gt; '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&gt; begin
  2     hotsos_ilo_task.set_config (trace =&gt; true
  3                                ,write_wall_time =&gt; 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&gt; 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.Trace File with 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&gt; create or replace
  2  procedure hotsos_test_2
  3  is
  4  begin
  5     hotsos_ilo_task.begin_task (module =&gt; 'HotSos Test 2'
  6                                ,action =&gt; 'Nesting the call to Test 1'
  7                                ,COMMENT =&gt; '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&gt; begin
  2     hotsos_ilo_task.set_config (TRACE =&gt; true
  3                                ,write_wall_time =&gt; 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.

Share.

About Author

3 Comments

  1. Anton Scheffer on

    My remark was not meant to criticism Hotsos ILO, I just wanted to show the possibilty to use the unknown (and undocumented) procedure sys.dbms_system.ksdwrt for writing messages to the tracefile. But I agree with you, using that procedure is not the same as using a full blown instrumentation package as Hotsos ILO.

    P.S. And I have already written my own (to be true, it’s a logging package which can be used for instrumentation).

  2. Everything that Hotsos ILO does is doable without Hotsos ILO. We’re calling only procedures that are shipped with Oracle.

    However, with Hotsos ILO, look at some of the things that now you don’t have to do:

    - Keep your own stack of dbms_application_info history so that you can instrument task hierarchies, not just tasks at a single level. (A lot of people who bother to learn about and use dbms_application_info don’t tidy up after themselves; when their instrumented task ends, the relic data of the instrumented task persists in v$session until either the session ends, or some other code replaces the module/action info.)

    - Figure out how to separate the act of instrumenting code (done by a developer at compile-time) from the act of activating or deactivating that instrumentation (done by a DBA at run-time).

    - Figure out a consistent, application-wide policy for how to use dbms_application_info, dbms_session, dbms_support or dbms_monitor (there’s an Oracle version dependency there that you don’t want developers having to deal with), or dbms_system.ksdddt and -.ksdwrt. For example, should you nest module/action name changes within timestamps, or vice versa? What kind of format should anything you write to the trace data be in.

    - Have your developers learn about dbms_support/monitor, dbms_application_info, dbms_session, etc. in the first place.

    - Come up with your own security scheme to protect from public abuse of potentially dangerous packages like dbms_system.

    - Worry about performance-tuning your instrumentation.

    We made Hotsos ILO free and open-source, so whether you use it or not, you can see for yourself exactly what’s in there. Our hope is that you’ll find it well-written enough that you won’t bother to write your own.

  3. Anton Scheffer on

    Using sys.dbms_system.ksdwrt( 1, ‘Hallo Alex’ ) you can write whatever you want to the tracefile. You don’t need HOTSOS for that.

    Testing

    Testing

    abc test