DBMS_APPLICATION_INFO is probably one of the most undervalued and without any doubt the most underused of all the packages supplied with the database by Oracle. On the face it, it is a very simple package that does a few very simple things, but it is not possible to overstate its significance.
Oracle 7.3.3
It has also been around for a long time. This package was first documented in Oracle 7.3.3. "Application developers can use the DBMS_APPLICATION_INFO package to record the name of the executing module or transaction in the database for use later when tracking the performance of various modules… System administrators can also use this information to track resource usage by module. When an application registers with the database, its name and actions are recorded in the V$SESSION and V$SQLAREA views. Your applications should set the name of the module and name of the action automatically each time a user enters that module. The module name could be the name of a form in an Oracle Forms application, or the name of the code segment in an Oracle Precompilers application. The action name should usually be the name or description of the current transaction within a module." – Oracle 7 Tuning, Release 7.3.3 ©Oracle 1997, Chapter 23 Registering Applications*How to Register a Session
Make a simple call to DBMS_APPLICATION_INFO, and you will be able to see MODULE and ACTION in your session information,EXECUTE dbms_application_info.set_module(module_name=>'MYMODULE',action_name=>'MYACTION');select sid, serial#, username, module, action
from v$session
where sid IN(select distinct sid from v$mystat)
/
SID SERIAL# USERNAME MODULE ACTION
---------- ---------- -------- -------------------- --------------------------------
367 2515 SCOTT MYMODULE MYACTIONselect sql_id, module, action, sql_text
from v$sqlarea
where module = 'MYMODULE'
/
SQL_ID MODULE ACTION
------------- -------------------- --------------------------------
SQL_TEXT
---------------------------------------------------------------------------------------------
17f888us1tbk2 MYMODULE MYACTION
select sid, serial#, username, module, action from v$session where sid IN(select distinct sid from v$mystat)
9bsqpcnygpgp7 MYMODULE MYACTION
select sql_id, module, action, sql_text from v$sqlarea where module = 'MYMODULE'
Tracing
When we did performance tuning back in the 1990s, all we had was the buffer cache hit ratio (joke) and SQL trace (an even older feature – introduced in Oracle 6, augmented by the wait interface in 7.0.12). When you registered a session with DBMS_APPLICAITON_INFO, it was recorded in the trace. So you knew which part of the trace refers to which value of module and action.This following is taken from a 12c trace. You can see where I called DBMS_APPLICATION_INFO to set the module and action.
Trace file /home/oracle/app/oracle/diag/rdbms/cdb1/cdb1/trace/cdb1_ora_8795.trc
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
…
*** 2016-08-11 11:17:42.803
*** SESSION ID:(367.2515) 2016-08-11 11:17:42.803
*** CLIENT ID:() 2016-08-11 11:17:42.803
*** SERVICE NAME:(orcl) 2016-08-11 11:17:42.803
*** MODULE NAME:() 2016-08-11 11:17:42.803
*** CLIENT DRIVER:(SQL*PLUS) 2016-08-11 11:17:42.803
*** ACTION NAME:() 2016-08-11 11:17:42.803
*** CONTAINER ID:(3) 2016-08-11 11:17:42.803
…
PARSING IN CURSOR #140183328563984 len=95 dep=0 uid=156 oct=47 lid=156 tim=79763572382 hv=611933126 ad='695370e0' sqlid='dbvj2xsk7kqy6'
BEGIN dbms_application_info.set_module(module_name=>'MYMODULE',action_name=>'MYACTION'); END;
*** MODULE NAME:(MYMODULE) 2016-08-11 11:17:42.972
*** ACTION NAME:(MYACTION) 2016-08-11 11:17:42.972
trcsess output=MYACTION.trc module=MYMODULE cdb1_ora_8795.trc
*** [ Unix process pid: 8795 ]
*** 2016-08-11 11:17:42.972
*** 2016-08-11 11:17:42.972
…
Client ID
There is also a function in DBMS_APPLICATION_INFO to set a client identifier. Again it is just a string. The idea is that you can associate an operator with a database session.dbms_application_info.set_client_info(client_info IN VARCHAR2)
dbms_application_info.read_client_info(client_info OUT VARCHAR2)
Confession
When I first looked at this feature back in the late 1990s, I struggled to see the value of MODULE and ACTION, but by then I was working with PeopleSoft, a packaged application that is still with us, and back then it did not register with the database. I used triggers to enable trace for specific processes, and then I would profile the whole trace file.Oracle 10g
Two new things in Oracle 10g made DBMS_APPLICATION_INFO very much more interesting that it had seemed to be.- DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE
- Active Session History
DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE
From Oracle 10g, it became possible to specify values of MODULE and/or ACTION for which the database would automatically enable SQL Trace. It was like setting a watch point in a debugger. Trace would be disabled when the module/action changed to something else.BEGIN
sys.dbms_monitor.serv_mod_act_trace_enable
(service_name=>'P1PPP'
,module_name =>'RECV_PO'
,waits=>TRUE
,binds=>TRUE);
END;
/
Active Session History
ASH was introduced in 10g. It is only available on Enterprise Edition and it requires the Diagnostics Pack licence. Every second, the database records the status of active database sessions in a buffer in memory. Every 10th sample is persisted to a table in the Automatic Workload Repository (AWR). Module and Action are collected as a part of that. Hence, you can analyse the ASH data with SQL Query.WITH x AS (
SELECT h.*
, CASE WHEN h.program LIKE 'PS%' THEN REGEXP_SUBSTR(h.program,'[^.@]+',1,1) ELSE h.program END as program2
FROM dba_hist_active_Sess_history h
), y AS (
SELECT x.program2, x.module, x.action, sum(10) ash_Secs
FROM x
GROUP BY x.module, x.action, x.program2
)
SELECT * FROM y
WHERE ash_secs >= 300
ORDER BY ash_Secs desc
/
ASH
PROGRAM2 MODULE ACTION Secs
------------------------ --------------------------- -------------------------- --------
PSAPPSRV RAE_EVENT_DETAIL RAE_EVENT_DETAIL 5800
PSAPPSRV RC_CASE RC_CASE 2100
PSAPPSRV RC_CASE RC_CASE_TSK 780
PSAPPSRV RA_CM_HOME_GRD RA_CM_HOME_GRD 630
PSAPPSRV XX_PGM_CASE XX_PGM_CASE 600
PSAPPSRV RB_TSK RB_TSK 440
oracle@XXX1 (LGWR) 340
oracle@XXX2 (LGWR) 330
…
- Enterprise Manager: This example shows two actions for a specific module
- AWR reports: The profile of SQL statements reports the module.
Elapsed
Time (s)
|
Execs
|
Elapsed
Time per Exec (s)
|
%Total
|
%CPU
|
%IO
|
SQL Id
|
SQL Module
|
SQL Text
|
305.11
|
1
|
305.11
|
10.62
|
58.94
|
0.97
|
dcxx3tvxsm4az
|
RA_CM_HOME_GRD
|
SELECT
BUSINESS_UNIT, RA_CAMPA...
|
110.51
|
342
|
0.32
|
3.85
|
47.67
|
0.00
|
bvbbkrnyjbyph
|
RAE_EVENT_DETAIL
|
SELECT
PRCSINSTANCE, JOBINSTAN...
|
41.42
|
340
|
0.12
|
1.44
|
48.73
|
0.00
|
cb3p0zbpuw2ha
|
RAE_EVENT_DETAIL
|
SELECT
BUSINESS_UNIT, RA_CAMPA...
|
31.74
|
4
|
7.94
|
1.10
|
57.65
|
0.00
|
7qh8s1qgz0axd
|
RBQ_BOSRCH_QCREATE
|
SELECT * FROM (
SELECT DISTINC...
|
25.49
|
812
|
0.03
|
0.89
|
51.36
|
0.29
|
0fj122xjvgpuc
|
SELECT /*
OPT_DYN_SAMP */ /*+ ...
|
|
24.49
|
1,782
|
0.01
|
0.85
|
49.04
|
0.00
|
9d8rmyu6hzh5v
|
SELECT /*
OPT_DYN_SAMP */ /*+ ...
|
|
22.50
|
4,232
|
0.01
|
0.78
|
48.38
|
0.00
|
16fx1qf2ujdrw
|
SELECT /*
OPT_DYN_SAMP */ /*+ ...
|
|
21.63
|
1,543
|
0.01
|
0.75
|
50.30
|
0.00
|
8nzp1phr63835
|
XX_PGM_CASE
|
SELECT
PROVIDER_GRP_ID, PERSON...
|
19.40
|
1
|
19.40
|
0.68
|
34.48
|
0.00
|
1atzwyuw0mqwn
|
RBQ_BOSRCH_QCREATE
|
SELECT * FROM (
SELECT DISTINC...
|
19.31
|
301,677
|
0.00
|
0.67
|
46.24
|
0.00
|
2t98byasd6zzk
|
RC_CASE
|
SELECT
EOCF_LIB_TERM_ID, EOCF_...
|
Other Features
- Resource Manager: policies can be specified for a module and/or action. Which could be interesting, but I haven't played with it personally.
How to Instrument PL/SQL
I am not a developer, and so it is not my day job to write PL/SQL. However, when I do, I instrument the code by adding calls to DBMS_APPLICATION_INFO as follows:- I store the current values of module and action at the start of each procedure in local variables.
- I set the action to the name of the procedure. I may set other values during the procedure.
- The original values are reinstated at every exit point from the procedure.
- I have a constant with the name of the procedure. I use this to set the value of module.
k_module CONSTANT VARCHAR2(64) := $$PLSQL_UNIT;
…
PROCEDURE my_procedure IS
l_module VARCHAR2(64);
l_action VARCHAR2(64);
BEGIN
dbms_application_info.read_module(module_name=>l_module
,action_name=>l_action);
dbms_application_info.set_module(module_name=>k_module
,action_name=>'MY_PROCEDURE');
…
/*application code goes here*/
…
dbms_application_info.set_module(module_name=>l_module
,action_name=>l_action);
EXCEPTION
WHEN … THEN
dbms_application_info.set_module(module_name=>l_module
,action_name=>l_action);
RAISE / EXIT
…
END my_procedure;
What did Instrumentation ever do for us?
This chart is taken from EDB360 for yet another Java system that does not have any Instrumentation. Module defaults to the program name. A profile of DB time by module is not particularly useful when nearly everything has the same module.
Unfortunately, very few developers or package vendors do this. This includes Oracle, although they have instrumented their E-Business Suite and PeopleSoft ERP packages, many others are not.
Conclusion
Nothing in this story is new.- ASH: Oracle 10g, 2003
- DBMS_APPLICATION_INFO: Oracle 7.3.3, 1997
- Wait Interface: Oracle 7, 1992
- Session SQL Trace: Oracle 6, 1988
I would characterise instrumentation, along with debug code, as a small investment during development that could pay big dividends later, rather than an overhead. Just as effective debug code can help you debug a functional problem, effective instrumentation can help you analyze performance issues.
The overhead of the DBMS_APPLICATION_INFO calls is trivially small, and they make performance improvement activities much easier for both developers and DBAs. So really, it doesn't cost you anything, it will save you effort and resource later.
*My thanks to Mogens Nørgaard and to Peter Gram who is the keeper of the Oracle Museum at Miracle in Denmark
@go-faster.co.uk on BlueSky
Posts
No comments :
Post a Comment