The "ask Tom" site no longer seems to comprise nerd tools that are legend in effective and one-on-one books:

The requested URL /~tkyte/article2/index.html was not found on this server.

The requested URL /~tkyte/debugf.html was not found on this server.

The requested URL /~tkyte/owarepl/doc/ was not found on this server.

What if they didn't have this kind of information on instrumentation at (just say,)the IRS, and some sorry-assed application accidentally raised your taxes? Boy, that would stink. Where do you think that there currently exists some good ideas on instrumenting Oracle and Java?

The Sun reference ("Effective" p 55) might now be
</code> http://java.sun.com/developer/EJTechTips/2003/tt0513.html <code>
But who really knows?

Please give some example for implementing instrumentation.

Tom:

Does over Instrumentation of application code will leads to slowness of application?

rajesh@10GR2> create or replace procedure without_instrumentation (p_limit in number)
  2  as
  3     a positiven := 1;
  4     b positiven := 1;
  5     c positiven := 1;
  6     d positiven := 1;
  7  begin
  8    for i in 1..p_limit
  9    loop
 10               a := 42;
 11               b := a*2;
 12               c := a * 5;
 13               d := a+b+c;
 14    end loop;
 15  end without_instrumentation;
 16  /

Procedure created.

Elapsed: 00:00:00.03
rajesh@10GR2>
rajesh@10GR2> create or replace procedure with_instrumentation (p_limit in number)
  2  as
  3     a positiven := 1;
  4     b positiven := 1;
  5     c positiven := 1;
  6     d positiven := 1;
  7  begin
  8
  9    for i in 1..p_limit
 10    loop
 11     dbms_application_info.set_module( module_name=>'with_instrumentation',action_name=>'Iteration '||i);
 12     dbms_application_info.set_client_info ('Assigning variable A ');
 13               a := 42;
 14     dbms_application_info.set_client_info (null);
 15     dbms_application_info.set_client_info ('Assigning variable B ');
 16               b := a*2;
 17     dbms_application_info.set_client_info (null);
 18     dbms_application_info.set_client_info ('Assigning variable C ');
 19               c := a * 5;
 20     dbms_application_info.set_client_info (null);
 21     dbms_application_info.set_client_info ('Assigning variable D ');
 22               d := a+b+c;
 23     dbms_application_info.set_client_info (null);
 24     dbms_application_info.set_module(null,null);
 25    end loop;
 26
 27  end with_instrumentation;
 28  /

Procedure created.

Elapsed: 00:00:00.03
rajesh@10GR2>
rajesh@10GR2> declare
  2     x number ;
  3  begin
  4     for i in 1..3
  5     loop
  6             x := dbms_utility.get_time;
  7             without_instrumentation (power(100,i));
  8             dbms_output.put_line (' Time taken WITHOUT Instrumentation for '||power(100,i)||' Iteration = '|| ( dbms_utility.get_time - x ) );
  9             x := dbms_utility.get_time;
 10             with_instrumentation (power(100,i));
 11             dbms_output.put_line (' Time taken WITH Instrumentation for '||power(100,i)||' Iteration = '|| ( dbms_utility.get_time - x ) );
 12     end loop;
 13  end;
 14  /
 Time taken WITHOUT Instrumentation for 100 Iteration = 0
 Time taken WITH Instrumentation for 100 Iteration = 0
 Time taken WITHOUT Instrumentation for 10000 Iteration = 0
 Time taken WITH Instrumentation for 10000 Iteration = 21
 Time taken WITHOUT Instrumentation for 1000000 Iteration = 7
 Time taken WITH Instrumentation for 1000000 Iteration = 2079

PL/SQL procedure successfully completed.

Elapsed: 00:00:21.07
rajesh@10GR2>

I've been down this road, and discovered instrumentation helped development time and quality.
I instrumented a package that had dozens of functions and procedures for a specific business function. In the process, I instrumented EVERYTHING at a granular level.

Turned out I made several false assumptions and the instrumentation is what made it possible to re-set and redevelop appropriate code.

Several years later, that instrumentation is what allowed a very quick diagnostic of an issue involving the same package. Without the instrumentation, it would have been unresolvable, and taken weeks to reprogram a "fix".

For my money, instrumentation is priceless.

There's nothing to say that the level of instrumentation and debugging can't be adaptive anyway. You might easily have instrumentation logic that works along the lines of:

start_timer
perform_operation
stop_timer

if elapsed_time < threshold_for_this_operation
then
perform minimal logging
else
perform detailed logging
end if

Of course one risk of this is that in the event of a general slowdown of the system (say some batch job overruns its window and conflicts with other jobs) then the logic above will trigger every operation to start doing more logging, thus increasing instrumentation overhead and hence system load, so you might want to code in an override.

All this sounds like a lot of work, and sometimes it is a significant proportion of development time, but it's generally based on widely reusable and cut'n'pastable code, and is time that will be made up later in debugging and performance tuning.

I particularly like the concept of negative overhead, by the way.

Hi Tom

I guess the two packages (DBMS_UTILITY (format_error_backtrace and format_call_stack) and DBMS_APPLICATION_INFO) would be good enough for instrumenting the code. Your thoughts ... ?

Thanks

Hi Tom

I see some pl/sql code where they use dynamic sql extensively - almost all places - so that they can log the source code itself. For e.g.

  begin
    v_sql_str := 'select ...';
    pk_log.log('Selecting ...', v_sql_str);
    execute immediate v_sql_str using ...;
    -- again
    v_sql_str ...
    pk_log ...
    execute immediate ...
    ...
  end;

When I questioned about dependency chain, they gave

select * from all_source where text like ...

as the answer.
Do you see any disadvantages of instrumenting code like this?
Thanks for your insights.

Hi Tom

This is to make clear.
(o) For the broken dependency chain, we search USER_SOURCE. We are not lost.

The advantage we have is
(o) Log all the SQL or PL/SQL to see where, why, when, how, and which exception is thrown.

Your comments please.
Regards

We have a fair amount of dynamic SQL in some of our packages, and I wrote a package to analyse the USER_SOURCE looking for references in the text so we had better cross-referencing.

To make a long story short, it was a pretty futile effort... typically the table names are included in comments in the code, or even in commented out code. There are problems with subsets of names and word boundaries (TAB1 and TAB1A and TAB1A,TAB1) are hard to distinguish. The code may even be constructed over multiple non-contiguous rows of PL/SQL. There were so many false positives that it became useless.

You might be able to build a package that can handle a lot of this, but then you are spending your time and resources building and maintaining an imperfect version of something you can get for free.

Tom,

My current site recently went through an upgrade from 9.2 to 11.2.0.3 and it a major mutex wait problem with their bespoke trace package.

Admittedly, this package was being called thousands of times as it was quite liberally scattered throughout the entire application but it appeared to be a problem when it was being called from Forms, even when the procedure being called was switched to a simple begin null; end; statement.

Do you have any idea where we should start looking? or even which questions we should be asking as a start point?

Tom,
I have been looking for examples as to how to instrument PL/SQL code and have not been able to locate it on this website. I read blogs and discussions about instrumenting code but could not find one with an example. I have your book "Expert Oracle Database Architecture - Oracle Database 9i, 10g, 11g Programming Techniques and Solutions" and could not find this topic on there. Can you please point to some links or books where I might find this or give an example to do this in PL/SQL code. Thank you.
- Kirthi

Tom,
I checked "Tyler Muth's blog" about the logger project. I am not sure if I could use it at my work place.
I have a procedure that runs for an hour. I currently have insert statments sprinkled in the procedure code to log into a table with the information of what stage of processing it is in. The inserts are not autonomous transactions which I think it should be changed to if I want to keep it the way it is. I am exploring if there are any better ways to do it. Will the "DBMS_APPLICATION_INFO" be an appropriate one to use. The procedure I am trying to instrument is runs over night and I would like to be able to check the log messages in the morning to verify everything ran okay or if there are errors be able to check the log messages to see at what stage it errored.
Thank you,
KS

Hi Tom,

I couldn't find where to download the source code of debug.f

Thanks,
Charlie

Hi Tom,

There 2 good features that logger doesn't have.

1. tail -f debug_trace_file.
2. debug.f("%s %s", l_a, l_b);

Below code with logger to print local variables is awkward, it's not as flexible as debug.f("%s",l_abc). when I want to print different set of variables at each time, I have to add and delete some elements in array l_params.

logger.append_param(l_params, 'p_param1_todo',p_param1_todo);
logger.log('START', l_scope, null, l_params);

There is some workaround for "tail -f".

Thanks,
Charlie

Hi Tom,

While I understand from the previous that you don't recommend the debug.f any more, I'm still curious to see the debug.f first hand.

Most of the links/URLs I could find, with my not-so-good google-skills, are either broken or they don't give out the complete code for it. :((

Please re-post debug.f and share the the link.

I can't thank you enough for giving us this site :)

Team,

I was learning dbms_monitor API, and tried a demo on my local database requesting to trace "All Actions" for a given module.

The requested module has two different actions, but the actions recorded in "v$serv_mod_act_stats" were shown as NULL.

What changes do i need in this script, to make the actions available in v$serv_mod_act_stat.

demo@ORA11G> create table t1 as
  2  select b.*, 0 as final_object_id
  3  from all_objects b;

Table created.

demo@ORA11G>
demo@ORA11G> alter table t1 add constraint t1_pk
  2  primary key(object_id);

Table altered.

demo@ORA11G>
demo@ORA11G> create table t2 as
  2  select distinct object_type ||
  3     trunc( row_number() over(partition by object_type
  4             order by created)/250) as patient_id,
  5     created + rownum as visit_date
  6  from all_objects;

Table created.

demo@ORA11G>
demo@ORA11G> exec dbms_stats.gather_table_stats(user,'T1');

PL/SQL procedure successfully completed.

demo@ORA11G> exec dbms_stats.gather_table_stats(user,'T2');

PL/SQL procedure successfully completed.

demo@ORA11G>
demo@ORA11G> create or replace package mypkg
  2  as
  3     procedure process_data;
  4  end;
  5  /

Package created.

demo@ORA11G> create or replace package body mypkg
  2  as
  3     procedure process_data
  4     as
  5             l_value int;
  6             l_avg_visit int;
  7     begin
  8             dbms_application_info.set_module(
  9                     module_name=>'MYPKG#PROCESS_DATA',
 10                     action_name=>'FINAL_OBJECT_ID_FINDING');
 11             for x in (select * from t1 order by owner,object_id)
 12             loop
 13                     if x.object_type ='PACKAGE' then
 14                             l_value := x.object_id ;
 15                     else
 16                             update t1 set
 17                                     final_object_id = l_value
 18                             where object_id = x.object_id;
 19                     end if;
 20             end loop;
 21
 22             dbms_application_info.set_action(
 23                     action_name=>'AVG_VISIT_DATE_FINDING');
 24             select avg( last_visit_date - visit_date )
 25             into l_avg_visit
 26             from (
 27             select a.visit_date , max(b.visit_date) as last_visit_date
 28             from t2 a, t2 b
 29             where a.patient_id = b.patient_id
 30             and b.visit_date < a.visit_date
 31             group by a.patient_id,a.visit_date
 32                      );
 33             dbms_output.put_line(' Average_visit_date ='||l_avg_visit);
 34             dbms_application_info.set_module(null,null);
 35     end;
 36  end;
 37  /

Package body created.

demo@ORA11G>
demo@ORA11G>
demo@ORA11G> select * from dba_enabled_aggregations;

no rows selected

demo@ORA11G> begin
  2     dbms_monitor.serv_mod_act_stat_enable(
  3             service_name=>sys_context('userenv','service_name'),
  4             module_name=>'MYPKG#PROCESS_DATA',
  5             action_name=>dbms_monitor.all_actions);
  6  end;
  7  /

PL/SQL procedure successfully completed.

demo@ORA11G> column PRIMARY_ID format a10
demo@ORA11G> column QUALIFIER_ID1 format a20
demo@ORA11G> column QUALIFIER_ID2 format a20
demo@ORA11G> select * from dba_enabled_aggregations;

AGGREGATION_TYPE      PRIMARY_ID QUALIFIER_ID1        QUALIFIER_ID2
--------------------- ---------- -------------------- --------------------
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA

1 row selected.

demo@ORA11G>
demo@ORA11G> set timing on
demo@ORA11G> exec mypkg.process_data
 Average_visit_date =-14

PL/SQL procedure successfully completed.

Elapsed: 00:00:08.28
demo@ORA11G> set timing off
demo@ORA11G>
demo@ORA11G> column service_name format a10
demo@ORA11G> column module format a20
demo@ORA11G> column action format a10
demo@ORA11G> column stat_name format a32
demo@ORA11G>
demo@ORA11G> select *
  2  from v$serv_mod_act_stats
  3  where service_name = sys_context('userenv','service_name')
  4  and module ='MYPKG#PROCESS_DATA'
  5  order by service_name, module, stat_id,stat_name, value;

AGGREGATION_TYPE      SERVICE_NA MODULE               ACTION        STAT_ID STAT_NAME                     VALUE
--------------------- ---------- -------------------- ---------- ---------- -------------------------------- ----------
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA                63887964 parse count (total)               0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA                85052502 opened cursors cumulative                 0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA               326482564 gc current blocks received                0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA               582481098 user commits                      0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA               798730793 workarea executions - onepass             0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA               916801489 db block changes                  0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              1099569955 application wait time             0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              1190468109 physical writes                   0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              1236385760 redo size                         0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              1388758753 gc current block receive time             0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              1431595225 parse time elapsed                0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              1759426133 gc cr block receive time          0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              2263124246 physical reads                    0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              2432034337 cluster wait time                 0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              2453370665 execute count                     0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              2748282437 DB CPU                            0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              2821698184 sql execute elapsed time          0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              2877738702 gc cr blocks received             0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              2882015696 user calls                        0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              3143187968 session logical reads             0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              3211650785 workarea executions - optimal             0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              3332107451 user I/O wait time                0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              3649082374 DB time                           0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              3671147913 user rollbacks                    0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              3678609077 session cursor cache hits                 0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              3804491469 workarea executions - multipass           0
SERVICE_MODULE        ORA11G     MYPKG#PROCESS_DATA              3868577743 concurrency wait time             0

27 rows selected.

demo@ORA11G>
demo@ORA11G> begin
  2     dbms_monitor.serv_mod_act_stat_disable(
  3             service_name=>sys_context('userenv','service_name'),
  4             module_name=>'MYPKG#PROCESS_DATA',
  5             action_name=>dbms_monitor.all_actions);
  6  end;
  7  /

PL/SQL procedure successfully completed.

demo@ORA11G>

Thanks Chris.

What changes do i need in this script, to make the actions available in v$serv_mod_act_stat.

So do i need to request each action explicitly? or any shortcuts available to have all actions available in v$serv_mod_act_stats.