Monday, September 25, 2006

Action, Module, Program ID and V$SQL...

My last entry pointed you to an article about using DBMS_APPLICATION_INFO.  An observation was made by Alberto Dell'Era that it would be nice if Oracle plopped the PLSQL module name into the session when executing the SQL in that routine.  I don't think that would be good - I would want my information there - and not have it overwritten by the PLSQL runtime. 

Jonathan Lewis pointed out that the module and action columns are in fact populated in V$SQL so that if the developer does use the application info package, it'll appear there - but then questioned what happens when the same SQL statement is associated with multiple values.

I'd like to clear up what happens then - and to add that 10g does in fact also try to inform us of the program (PLSQL module) and line number within that program that first parsed it.  That is, we not only see the first action and module associated with the SQL (that is the answer to the question about "what happens when multiple actions and modules are ultimately associated with the same SQL statement", the first one to parse the SQL statement gets to set the values for all other invocations) but also the object_id of the PLSQL module that first parsed it.

For example:

ops$tkyte%ORA10GR2> create or replace procedure p1
2 as
3 begin
4 dbms_application_info.set_module
5 ( 'p1 module', 'p1 action' );
6 for x in
7 ( select *
8 from dual look_for_me_1 )
9 loop
10 null;
11 end loop;
12 for x in
13 ( select *
14 from dual look_for_me_2 )
15 loop
16 null;
17 end loop;
18 end;
19 /

Procedure created.

ops$tkyte%ORA10GR2> create or replace procedure p2
2 as
3 begin
4 dbms_application_info.set_module
5 ( 'p2 module', 'p2 action' );
6 for x in
7 ( select *
8 from dual look_for_me_1 )
9 loop
10 null;
11 end loop;
12 end;
13 /

Procedure created.

ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> exec p2

PL/SQL procedure successfully completed.

ops$tkyte%ORA10GR2> exec p1

PL/SQL procedure successfully completed.

ops$tkyte%ORA10GR2>
ops$tkyte%ORA10GR2> select object_name, object_id
2 from user_objects
3 where object_name in ( 'P1', 'P2' )
4 /

OBJECT_NAME OBJECT_ID
------------------------------ ----------
P1 126238
P2 126241

ops$tkyte%ORA10GR2> select sql_text, action, module,
2 program_id, program_line#
3 from v$sql
4 where sql_text like
5 '% LOOK\_FOR\_ME\_%' escape '\'
6 /

SQL_TEXT ACTION MODULE PROGRAM_ID PROGRAM_LINE#
--------------- --------- --------- ---------- -------------
SELECT * FROM D p2 action p2 module 126241 5
UAL LOOK_FOR_ME
_1

SELECT * FROM D p1 action p1 module 126238 9
UAL LOOK_FOR_ME
_2

So, P2 "owns" the "LOOK_FOR_ME_1" sql statement - it set the action, module, program_id and program_line# in V$SQL. Similarly - P1 "owns" the second SQL statement. It all depends on who executed it first (and hence can change as the instance is shutdown and started up).
So - start using dbms_application_info and now that you know about the new columns in V$SQL, you can start using them as well - just bear in mind that if multiple SQL modules invoke the same SQL - you will only learn about one of them.

POST A COMMENT

19 Comments:

Blogger Tim... said....

This confused the hell out of me when I first observed it.

In my case I had the same API called from a batch job and an application screen. I couldn't understand how the application screens could be calling the API so many times. Of course, it was merely the first place that issued the API call.

Red faces all round when I realised my mistake :)

Cheers

Tim...

Mon Sep 25, 03:22:00 AM EDT  

Blogger Jeff Moss said....

I believe V$SESSION has this kind of stuff on it in 10gR2 as well...

PLSQL_ENTRY_OBJECT_ID
PLSQL_ENTRY_SUBPROGRAM_ID
PLSQL_OBJECT_ID
PLSQL_SUBPROGRAM_ID

I'll stick a post on my blog at lunchtime with an example using a package...basically the top 2 show the entry point PLSQL unit and the last 2 show the PLSQL unit it's currently running.

Mon Sep 25, 04:06:00 AM EDT  

Blogger Alberto Dell'Era said....

Actually I said "populate MODULE and ACTION ...(snip).. if not populated yet" ;)

But anyway, the 10GR2 program_id/program_line# pair provides the same information I wanted basically, so thanks for pointing it out!

Mon Sep 25, 07:19:00 AM EDT  

Blogger yas said....

I believe V$SESSION has this kind of stuff on it in 10gR2 as well...

PLSQL_ENTRY_OBJECT_ID
PLSQL_ENTRY_SUBPROGRAM_ID
PLSQL_OBJECT_ID
PLSQL_SUBPROGRAM_ID


These columns do not exist in v$session in 10G R2.

Mon Sep 25, 07:49:00 AM EDT  

Blogger David Aldridge said....

>> if multiple SQL modules invoke the same SQL - you will only learn about one of them

Would that, IYHO, constitute a bad design/programming practice?

Mon Sep 25, 10:30:00 AM EDT  

Blogger Alberto Dell'Era said....

yas,

in my 10gr2 instance I can see all the PLSQL* entries.

Mon Sep 25, 11:24:00 AM EDT  

Blogger Alberto Dell'Era said....

I've noticed that Jeff Moss has written a nice complement to this discussion, talking about the PLSQL* columns we find in 10gR2 v$session:

http://oramossoracle.blogspot.com/#5861940984882131840

Maybe He was too shy to link it here ? Since my understanding is that this is OK for Tom, here I am ;)

Mon Sep 25, 02:17:00 PM EDT  

Blogger Jeff Moss said....

Thanks Alberto.

I think the link is perhaps not the right one - this one might work.

Mon Sep 25, 03:56:00 PM EDT  

Anonymous Jonathan Lewis said....

One detail to note in 10gR2 is the latch activity.

Try variations on this code:


begin
for i in 1..1000 loop
dbms_application_info.set_module(
to_char('module ' || i),
to_char('Action ' || i)
);

dbms_application_info.set_action(
to_char('Action ' || i)
);

dbms_application_info.set_client_info(
to_char('client ' || i)
);

end loop;
end;
/


I get 5,000 hits on the client/application info latch from just the set_module() calls. And with a single CPU, I have just one (child) latch of that name.

If you go overboard on setting the values, you could introduce an odd bottleneck.

I was just bashing out a quick script to check this, and discovered that I had already answered my earlier question myself - in Dec 2003, then again in Jan 2005 - and forgotten that I'd done it. O tempora, O mores.

P.S. Is there a tag that allows 'code' to appear. The normal "pre" tag is not accepted.

Mon Sep 25, 04:03:00 PM EDT  

Blogger Jeff Moss said....

I asked the question about displaying code recently and Doug (with others assistance I think) put out something here about using PRE tags and displaying code...might be of use to you Jonathan...

Mon Sep 25, 04:25:00 PM EDT  

Blogger Gary Myers said....

Like Yas, I don't see the PLSQL* columns in V$SESSION in 10GR2 (XE Windows version). The columns aren't documented in the 10GR2 reference guide. Maybe they are a patch addition or Enterprise edition/option feature (or maybe even an OS issue, though if the information was only available on some OSs, I'd expect the columns visible but null).

Mon Sep 25, 07:47:00 PM EDT  

Blogger yas said....

Gary you are right, I have checked this with 10.2.0.2 and these PLSQL* columns exist there. So it seems they are introduced with the 10.2.0.2 patchset.

Mon Sep 25, 10:59:00 PM EDT  

Blogger Tyler said....

In case you haven't noticed it yet, APEX (formerly HTML DB), sets module = "APEX: APPLICATION 101", Action = "PAGE 1", Client Info = "TMUTH" and Client Identifier = "TMUTH:12345" (for app 101, page 1, user TMUTH, session 12345).

On a related note, you can use module or module and action with the database resource manager, so you could actually give certain applications more CPU time, etc.

There are a number of Top SQL reports in APEX 2.0+ under "Utilities" > "Monitor". So, you can get the Top SQL for App 101 order by Buffer Gets / Rows Processed. I need to get these into SQL Developer.

There is also an API call in the latest release of ODP.Net to set module, but I don't think they've implemented action or client_identifier yet, but you can still set them via a PL/SQL call.

Also note that all of these values get propegated to the Audit tables. This allows you to make fine-grained auditing decisions using these values, and also to view them in the audit tables should an audit event occur.

Tue Sep 26, 11:06:00 AM EDT  

Blogger Tyler said....

In case you haven't noticed it yet, APEX (formerly HTML DB), sets module = "APEX: APPLICATION 101", Action = "PAGE 1", Client Info = "TMUTH" and Client Identifier = "TMUTH:12345" (for app 101, page 1, user TMUTH, session 12345).

On a related note, you can use module or module and action with the database resource manager, so you could actually give certain applications more CPU time, etc.

There are a number of Top SQL reports in APEX 2.0+ under "Utilities" > "Monitor". So, you can get the Top SQL for App 101 order by Buffer Gets / Rows Processed. I need to get these into SQL Developer.

There is also an API call in the latest release of ODP.Net to set module, but I don't think they've implemented action or client_identifier yet, but you can still set them via a PL/SQL call.

Also note that all of these values get propegated to the Audit tables. This allows you to make fine-grained auditing decisions using these values, and also to view them in the audit tables should an audit event occur.

Tue Sep 26, 11:10:00 AM EDT  

Anonymous Anonymous said....

Nice blog Jeff. Another resource added to the bookmarks ;-)

http://oramossoracle.blogspot.com

Tue Sep 26, 03:04:00 PM EDT  

Anonymous Gabe said....

Using dbms_application_info is a way to extend the instrumentation any developer should have in his/her Oracle code but, by itself, it is hardly “it”.

"Databases were born/optimized to … " … read and write tables seems to come first … write and access internal memory structures, well, maybe later, much later.

Using dbms_application_info is simple … getting juice out of it is complex and most of the time a privilege. Wading through funky trace files just to see how my program is doing? Hmmm.

Though some are pointing out that possibilities seem endless once registering with dbms_application_info, personally I see diminishing returns on complexity setting in quite early on. Latch activity, specifics on versions, increase possibility of failure due to complexity, scattered information, etc.

It is refreshing though to see some of the caveats surfacing out of the discussion.

And seeing my text submitted through dbms_application_info quietly being chopped to 48, 32 or 64 chars is akin to … "my point was … hmm … what was actually my point?"

Right. dbms_application_info = not enough application instrumentation.

Tue Sep 26, 03:15:00 PM EDT  

Blogger Thomas Kyte said....

Gabe -

but on the other hand, I would be a very very very happy man if ever Java application, upon grabbing a connection from a connection pool only did one thing for me - that would be:

call dbms_application_info to let me know who the heck you were. that is all, if I could get just that LITTLE TINY THING, I would be happy

and then if I could get you to call dbms_session.set_identifier - I'd just about wet myself.

I'd be so happy :) I could figure out who the heck you are, and trace what the heck you are doing... Life would be so so very good again.

Tue Sep 26, 03:21:00 PM EDT  

Anonymous Gabe said....

The readme for the ILO from HOTSOS (which is heavily based on dbms_application_info) does list instrumenting multi-tier applications as a limitation.

log4plsql does not offer anything really to mitigate this problem either.

I don’t have anything against those little things you mention. Making calls to write into internal memory structures in an application loop makes me cringe though … even if a juicy trace file (worse, few of them) were to be the reward. If communicating that my application is in iteration n of some loop is important then write it in a table.

What I’m saying is that using dbms_application_info and application instrumentation are not synonymous. The recent flurry of articles does seem to use the two terms almost within the same breath.

dbms_application_info allows the Oracle tracing system (which is shared resource-centric) to be augmented with application information. Great for the Oracle tracing system … not necessarily so [or just not enough] for the particular Oracle application … and it comes at a cost and it is hardly enough.

My view is … tailored instrumention for the Oracle application itself (asynchronous inserts into journaling table) … record those items required for hooking up into the Oracle tracing system including moderate calls to dbms_application_info.

One journaling table per system with the autonomous_transaction procedure to write ought to be enough mechanism to let others know who I am and what I’m doing; and I’ll record the SID and SERIAL# too; and I’ll make the couple of calls you mention.

Writing application information out, every other line of code – as you say, is paramount and non-negotiable. Making calls to dbms_application_info is based on how I feel about the DBA giving me ORA-00942 for v$session and v$sql … just joking.

I don’t think I’m disagreeing with what you and others are saying … more with what’s not being said. A recurring question/follow-up on asktom is "what exactly is instrumentation?" … essentially people keep asking "how exactly do I instrument my application code?" … dbms_application_info might be necessary (in moderation) but is hardly sufficient.

Wed Sep 27, 09:57:00 AM EDT  

Blogger Steven said....

A quick plug for the fabulously useful reserved word $$plsql_line - equivalent to __LINE__ in C.

Insert debugging info into debug table using autonomous transactions and $$plsql_line - you will know the exact line in your code.

Fri Oct 12, 02:26:00 PM EDT  

POST A COMMENT

<< Home