Visit Citebite Deep link provided by Citebite
Close this shade
Source:  http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:54174245781686#tom2685781500346683007



Home>Question Details



Nigel -- Thanks for the question regarding "Application Instrumentation", version 9.2.0

Submitted on 1-Jan-2006 21:08 UTC
Last updated 19-Dec-2012 7:56

You Asked

Hello Tom,

Your books, Effective Oracle By Design and Expert Oracle (the original edition and volume 
one of the new edition), press home the importance of incorporating the ability to 
provide runtime trace and profiling information when required.

Much thought has been through my mind regarding a simple, consistent design of such 
functionality, applicable to most programming environments.

Bearing in mind that application instrumentation is good programming practice rather than 
Oracle specific advice, do you have a generic approach to designing an application that 
includes instrumentation and tracing available at the flick of a switch?

A high-level example for eager minds would be gladly received. Maybe using the code 
behind AskTom, if it's not a cheeky request? :)

Many thanks. 

and we said...

Well, it varies by language and environment.

For example, when developing an Oracle application - you would be using

o parameter driven ability to enable/disable sql_trace
o dbms_application_info
o dbms_monitor in 10g

IN ADDITION to doing something in the application.  If the application was written in 
plsql - I might be using our developed "debug.f" routine
http://asktom.oracle.com/~tkyte/article2/index.html#Errors
In C, I used a debugf macro...

In Java/JDBC, I actually just used my debug.f stored procedure (the java client was 
distributed to the desktop - a palm sync conduit - the trace was needed on the server, so 
debug.f was perfect).

So, I think there are many tools necessary depending on circumstances - such as the tool 
being used (HTMLDB has builtin stuff for example that you can use - change the word NO to 
YES in my urls and see what happens..), the products (Oracle has SQL_TRACE - not many 
others can say the same, the application server - 10g AS is fully instruemented as well) 
used and so on. 

Reviews    
2 stars Home for Orphans   December 6, 2006 - 7pm UTC
Reviewer: Harrison from Haymarket "Like Scotland, but we're cheaper" Virginia
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
http://java.sun.com/developer/EJTechTips/2003/tt0513.html
But who really knows?
 


Followup   December 7, 2006 - 9am UTC:

~tkyte is now just tkyte

they turned off directory indexing on my server. 

3 stars   June 13, 2008 - 7am UTC
Reviewer: A reader 
Please give some example for implementing instrumentation.


5 stars Instrumentation Overhead   October 3, 2010 - 5am UTC
Reviewer: Rajeshwaran, Jeyabal 
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>


Followup   October 4, 2010 - 2am UTC:

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

I've often postulated that the overhead of instrumentation is approximately -10.24%

Yes, NEGATIVE 10.24%.

That is, the code runs faster with instrumentation.


Evidence that is true:

a) oracle is heavily instrumented (v$ tables, sql_trace, AWR, ASH, statspack, etc etc etc)

b) without that instrumentation - you would not know where to begin to start to tune

c) therefore, we run faster with it than with out - much much faster...



Now that said, too much instrumentation is just that - TOO MUCH.

Use dbms_application info to set high level details - what function/procedure you are in. use other tracing that is usually DISABLED for what you did above (think about sql_trace - very very very detailed, hardly ever on)

You did sql_trace level tracing there - you don't want to do that every time, you want it usually off.

Common sense must prevail
1 stars Under Intstrumentation Leads to ...   October 4, 2010 - 10am UTC
Reviewer: Dana from Phoenix, AZ USA
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.


5 stars   October 5, 2010 - 2am UTC
Reviewer: David Aldridge 
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.


Followup   October 5, 2010 - 12pm UTC:

what I mean is the logging should be able to be turned ON and OFF easily - just like sql_trace.

the instrumentation should always be there

it should always be infinitely detailed

but most of the time, it shouldn't be executed.


dbms-application-info - call it upon procedure entry maybe (major routine entry) but not every other line of code, every time - that is too much.

but every other line of code should be instrumentation code - that normally DOES NOT RUN (like sql_trace). it only runs when something tells it to. It is too intense to run every time.
4 stars DBMS_UTILITY and DBMS_APPLICATION_INFO   February 14, 2011 - 9am UTC
Reviewer: Parthiban Nagarajan from Coimbatore, India
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

Followup   February 14, 2011 - 9am UTC:

they would be insufficient.

dbms_utility is useful for "dumping" information - but not really "instrumenting". That would be like saying "sqlerrm" is useful for instrumenting. You might CALL sqlerrm from your instrumentation - but sqlerrm doesn't facilitate in itself.

dbms_application_info is a good start. It will show in real time where in your code you are right now.

But it won't show you where you've been, what you've done.

In my opinion you need a further level of instrumentation - the debug stuff. Remeber, I originally wrote:

<quote>
For example, when developing an Oracle application - you would be using

o parameter driven ability to enable/disable sql_trace
o dbms_application_info
o dbms_monitor in 10g

IN ADDITION to doing something in the application.
</quote>

that in addition (addressed above) is the big part, application info is just the tip
4 stars Dynamic SQL for Instrumentation   April 14, 2011 - 6am UTC
Reviewer: Parthiban Nagarajan from Coimbatore, India
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.


Followup   April 14, 2011 - 10am UTC:

I don't see any advantages to it.

I see disadvantages of:

o the dependency chain is broken, I cannot select * from user_dependencies and get meaningful data anymore.

o the compile time checking is lost, my code is infinitely more fragile

o I have to do bulk processing myself - I lose the implicit bulk processing provided by plsql with implicit static cursors. (it runs slower, does more work in the database)

o I lose the ability to have %rowtype and all kinds of plsql short cuts



I see this as being a "not smart idea". I don't see any advantage to "select * from all_source where text like...." using dynamic sql over static sql at all - BOTH would have the sql in there to search on.

I can search my code with static sql, further I have user_dependencies to search it even better.


I would discourage this approach entirely.
4 stars RE: Dynamic SQL for Instrumentation   April 14, 2011 - 10am UTC
Reviewer: Parthiban Nagarajan from Coimbatore, India
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

Followup   April 14, 2011 - 10am UTC:

(a) yes you are.

(b) and all you need is the LINE number, the sql is already in the database. Log the line number and you can pull up the CODE!!!!!!!


My comments stand, this is a horrible idea for the reasons above and more.
5 stars Not a good idea   April 14, 2011 - 2pm UTC
Reviewer: Dan from FL
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. 


Followup   April 14, 2011 - 5pm UTC:

Yeah, I'd like to see the guys above find all of the code that references table A, AA and AAA.

Easy with user_dependencies, impossible (pretty much) with SQL against all_source.


and all you need is the *LINE NUMBER*, everything else can be found from that.
5 stars instrumentation   April 14, 2011 - 11pm UTC
Reviewer: A reader 


5 stars issues calling trace package   July 26, 2012 - 7am UTC
Reviewer: Dominic from London UK
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?


3 stars How to instrument PL/SQL code?   December 17, 2012 - 3pm UTC
Reviewer: A reader 
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


Followup   December 18, 2012 - 12pm UTC:

you do this simply by logging lots of stuff - everything you can think of - and having a configurable way to turn it on and off - so you can see critical messages, informational, warning, all messages from a certain module, by a certain user, under a certain set of circumstances, etc etc etc.

https://www.google.com/search?q=how+to+instrument+code



see
http://tylermuth.wordpress.com/2011/11/09/logger-project-moved-temporarilly/


for a nice package to do the logging that is configurable.
3 stars   December 18, 2012 - 1pm UTC
Reviewer: A reader 
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


Followup   December 19, 2012 - 7am UTC:

I am not sure if I
could use it at my work place.


?? why not - it is delivered in source code format, you can read it, you could have written it - it is just PLSQL. You can review it - check it in - use it...


Will the
"DBMS_APPLICATION_INFO" be an appropriate one to use.


absolutely! session longops is what you want to look at (in addition to setting action, module and client_info).


dbms_application_info will give you "real time" feedback on something that is running - the logger package will give you tracing information for performance tuning, maintaining code and so on.



All information and materials provided here are provided "as-is"; Oracle disclaims all express and implied warranties, including, the implied warranties of merchantability or fitness for a particular use. Oracle shall not be liable for any damages, including, direct, indirect, incidental, special or consequential damages for loss of profits, revenue, data or data use, incurred by you or any third party in connection with the use of this information or these materials.

About Oracle | Legal Notices and Terms of Use | Privacy Statement