Tracing a module action

A simple example of setting up oracle End to End application tracing for a module and action.


 I have created and logged in as dummy application user which has the connect and resource privs only called TEST_TRC.

SQL> select s.username,s.service_name,s.module,s.action, s.client_identifier from v$session s where username = 'TEST_TRC'; USERNAME SERVICE_NA MODULE ACTION CLIENT_IDENTIFIER ---------- ---------- ---------- ------------------- ----------------------- TEST_TRC SYS$USERS SQL*Plus

The session has the default service, module, action set for sqlplus. As an all powerful database user I enable tracing act the module/action level.

SQL> exec dbms_monitor.serv_mod_act_trace_enable('SYS$USERS','TRC_MOD','ACT_TRACE',TRUE,FALSE,NULL); PL/SQL procedure successfully completed.

Now that tracing is turned on, as the TEST_TRC user I will run a simple select from dual, then set the ACTION, run another select, then set the ACTION to nothing, and run another simple select.

SQL> select 'before trace' from dual; 'BEFORETRACE ------------ before trace --Set the MODULE/ACTION SQL> exec dbms_application_info.set_module('TRC_MOD','ACT_TRACE'); PL/SQL procedure successfully completed. SQL> select 'started trace' from dual; 'STARTEDTRACE ------------- started trace --Set the ACTION to nothing SQL> exec dbms_application_info.set_module('TRC_MOD',''); PL/SQL procedure successfully completed. SQL> select 'stopped trace' from dual; 'STOPPEDTRACE ------------- stopped trace

Taking a look at the trace file I can see the only statement that is collected is the select from dual when the ACTION was set. The trace also shows that the ACTION was set for the session.

===================== PARSING IN CURSOR #46967219453968 len=69 dep=0 uid=404 oct=47 lid=404 tim=1391634990173882 hv=2290952339 ad='1cbcddf20' sqlid='arq8czk48ua4m' BEGIN dbms_application_info.set_module('TRC_MOD','ACT_TRACE'); END; END OF STMT EXEC #46967219453968:c=0,e=95,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=1391634990157150 WAIT #46967219453968: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1391634990174328 *** 2014-02-05 21:16:42.472 WAIT #46967219453968: nam='SQL*Net message from client' ela= 12297851 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1391635002472204 CLOSE #46967219453968:c=0,e=25,dep=0,type=0,tim=1391635002472324 *** 2014-02-05 21:16:42.526 ===================== PARSING IN CURSOR #46967219453968 len=32 dep=0 uid=404 oct=3 lid=404 tim=1391635002526520 hv=2897629366 ad='1ba24c140' sqlid='dvtn2zfqbcn5q' select 'started trace' from dual END OF STMT PARSE #46967219453968:c=1999,e=54127,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1391635002526518 EXEC #46967219453968:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1391635002526662 WAIT #46967219453968: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1391635002526720 FETCH #46967219453968:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1391635002526760 STAT #46967219453968 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=2 us cost=2 size=0 card=1)' WAIT #46967219453968: nam='SQL*Net message from client' ela= 195 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1391635002527056 FETCH #46967219453968:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=1391635002527092 WAIT #46967219453968: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1391635002527114 *** 2014-02-05 21:16:51.452 WAIT #46967219453968: nam='SQL*Net message from client' ela= 8925308 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1391635011452436 CLOSE #46967219453968:c=0,e=10,dep=0,type=0,tim=1391635011452554 ===================== PARSING IN CURSOR #46967219453968 len=60 dep=0 uid=404 oct=47 lid=404 tim=1391635011452666 hv=244107150 ad='1baf14cf0' sqlid='7a4fksw78tjwf' BEGIN dbms_application_info.set_module('TRC_MOD',''); END; END OF STMT PARSE #46967219453968:c=0,e=57,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=1391635011452665 *** MODULE NAME:(TRC_MOD) 2014-02-05 21:16:51.452 *** ACTION NAME:() 2014-02-05 21:16:51.452

******************************************
keywords: trace ACTION MODULE
******************************************
rdbms version: 11.2
******************************************