Tracing Code with DBMS_MONITOR

Oracle Community

Tracing Code with DBMS_MONITOR

Follow / 6.22.2014 at 10:20pm

In my previous post, I discussed adding instrumentation to your code by registering key tasks with module and action names using DBMS_APPLICATION_INFO. In this post, I want to show you how to use the module/action pairs to start and stop tracing using the DBMS_MONITOR package.

 DBMS_MONITOR can be used to control tracing and execution statistics gathering at various levels such as for individual sessions, for the entire database, or for tasks registered using DBMS_APPLICATION_INFO. I'm going to focus on the particular DBMS_MONITOR calls that utilize module/action names as discussed in my previous post.

Extended SQL Trace

The methods by which you can gather extended SQL trace data have improved over the years. In the "old" days, we used the 10046 event and set it using ALTER SYSTEM or ALTER SESSION commands or perhaps used another package like DBMS_SUPPORT. But in today's supported Oracle versions, turning on extended SQL tracing is much simpler and offers more granular control of what and when you trace.

 What is extended SQL Trace anyway? Simply put, extended SQL Trace data provides a complete record of what your application code does while it is being traced. This includes the SQL (and PL/SQL) being executed and, if requested, any bind variable values used and any wait events incurred during the execution. Basically, it is the output emitted from instrumention Oracle has included in its kernel. I'm not going to get into the details of the trace data in this post, but will refer you to a bunch of great papers over at Method R if you want to really take a deep dive into trace data.

 The key bit to know about the benefit of having trace data is that it can let you know exactly where your code spends its time. Once you know that, you know where to focus your efforts to correct problems/deficiencies and improve performance.

Using DBMS_MONITOR

As I mentioned earlier, the DBMS_MONITOR package allows you to turn tracing on and off. The really nifty part that relates to our use of DBMS_APPLICATION_INFO is the ability that procedures within DBMS_MONITOR have to turn tracing on only for specific module/action names. That way, if you know you're having a performance problem in your code in an area that you have already registered with a module/action name, you can turn tracing on only for that section of code. It allows you to have a very precise scope of activity to trace.

You can turn on tracing for a specific session (SESSION_TRACE_ENABLE) but when you do that, you are tracing everything that session does – not just the task that you care about. The trace file that is created will contain a whole bunch of things you don't care about and that are not related to the specific task you wish to evaluate. The "noise" of all that extra information could cause your real problem to be masked. It's easy to lose the few seconds or minutes of activity consumed specifically by the task you care about if you have a trace file that includes multiple minutes of activity. The more information included in your trace file, the more difficult it becomes to separate what you care about from what you don't.

The SERV_MOD_ACT_TRACE_ENABLE procedure within DBMS_MONITOR allows  you to specify service, module, and action names you have registered and tracing will only occur when those named tasks are active. The service name is associated with how the session connects to the database and is an alias for the instance that is found in the client's TNSNAMES.ORA file. If not specified, the service name will default to SYS$USERS. You can find the service name in V$SESSION along with the module and action names for any session.

With SERV_MOD_ACT_TRACE_ENABLE, you must specify the service_name and then have the option to include other parameter settings as follows:

Parameter            Default value

service_name         * must specify *

module_name          dbms_monitor.ALL_MODULES

action_name          dbms_monitor.ALL_ACTIONS

waits                TRUE

binds                FALSE

instance_name        null (all instances)

plan_stat            null (FIRST_EXECUTION)

Actually, the default values for module_name and action_name are specified as ANY_MODULE and ANY_ACTION in the documentation, but if you attempt to use those, an error will be raised. The documentation also states that if you leave either parameter null, then it will use the "all" default. That is also not true as leaving it blank (i.e. an empty string) or specifically using the null operator will not cause tracing to occur. So remember if you want all modules or all actions to be traced, you must use the default constant.

If you used DBMS_APPLICATION_INFO to set a module name of "Payroll" and an action name of "deductions", then you could enable tracing of that section of code using the following call:

dbms_monitor.serv_mod_act_trace_enable (

service_name=>'SYS$USERS',

module_name=>'Payroll'

action_name=>'deductions')

The trace data file that is emitted would contain the following information:

*** 2014-06-22 15:42:07.521

*** SESSION ID:(21.23447) 2014-06-22 15:42:07.521

*** CLIENT ID:() 2014-06-22 15:42:07.521

*** SERVICE NAME:(SYS$USERS) 2014-06-22 15:42:07.521

*** MODULE NAME:(Payroll) 2014-06-22 15:42:07.521

*** ACTION NAME:(deductions) 2014-06-22 15:42:07.521

=====================

PARSING IN CURSOR #139923700659424 len=97 dep=0 uid=94 oct=47 lid=94 tim=1403469727520966 hv=2572442827 ad='d41dfed0' sqlid='9n0zqvucp8r6b'

BEGIN dbms_application_info.set_module(module_name=>'Payroll', action_name=>'deductions'); END;

END OF STMT

EXEC #139923700659424:c=0,e=136,p=0,cr=0,cu=0,mis=1,r=1,dep=0,og=1,plh=0,tim=1403469727520963

WAIT #139923700659424: nam='SQL*Net message to client' ela= 10 driver id=1650815232 #bytes=1 p3=0 obj#=6204 tim=1403469727521539

 

*** 2014-06-22 15:42:07.592

WAIT #139923700659424: nam='SQL*Net message from client' ela= 70633 driver id=1650815232 #bytes=1 p3=0 obj#=6204 tim=1403469727592201

CLOSE #139923700659424:c=0,e=16,dep=0,type=0,tim=1403469727592285

=====================

PARSING IN CURSOR #139923700659424 len=81 dep=0 uid=94 oct=3 lid=94 tim=1403469727593267 hv=105112848 ad='a6b2fc80' sqlid='7wgj050347t8h'

select 'do a payroll deductions function' from dual           

END OF STMT

PARSE #139923700659424:c=999,e=942,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1403469727593266

EXEC #139923700659424:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1403469727593366

WAIT #139923700659424: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=6204 tim=1403469727593423

FETCH #139923700659424:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1403469727593473

STAT #139923700659424 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)'

WAIT #139923700659424: nam='SQL*Net message from client' ela= 199 driver id=1650815232 #bytes=1 p3=0 obj#=6204 tim=1403469727593760

FETCH #139923700659424:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=1403469727593785

WAIT #139923700659424: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=6204 tim=1403469727593805

*** 2014-06-22 15:42:12.182

 

I executed a simple SELECT from DUAL in this example, but as you can see, the call to DBMS_APPLICATION_INFO that registers the module/action name for "Payroll"/"deductions" is emitted to the trace file as well as the SQL that follows it. 

Note that you must turn off tracing by using the SERV_MOD_ACT_TRACE_DISABLE procedure. If you do not disable the trace, every time the code registered with the specified service/module/action executes, it will be traced.

Summary

Using DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE provides a way to specify just the registered module/action pairs for which you wish tracing to occur. This gives you precise control over the scope of the trace data you collect and helps you focus your performance problem tuning and diagnosis efforts.

748 1 /
Follow / 24 Jun 2014 at 2:06pm

As usual another excellent blog - thanks. For those working with trace files our Toad for Oracle offers a robust and easy trace file browser that makes working with trace files (even huge ones) a breeze. The blog below also references three other blogs which fully highlight Toad's trace file browser. A must have utility for those tackling trace files :)

www.toadworld.com/.../toad-12-1-offers-automatic-trace-file-deadlock-detection.aspx