Friday, September 16, 2016

One of my Favourite Database Things: DBMS_APPLICATION_INFO

Notes for my slot in session UGF2630: EOUC Database ACES Share Their Favorite Database Things: Part I – OpenWorld , Sunday 18th September 2016
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');
MODULE and ACTION are just character strings. You can put anything you like in there, but I recommend that the values are meaningful to your application, consistent and predicable.
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             MYACTION
And you can also identify SQL for that module in v$sqlarea.
select 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'
This hasn't changed since 1997 (except the strings have got longer). Today, there are a few more dynamic performance views where module and action are recorded.

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
You can use the trcsess utility to extract part of a trace by module and action
trcsess output=MYACTION.trc module=MYMODULE cdb1_ora_8795.trc
and this is the start of the resulting file
*** [ Unix process pid: 8795 ]
*** 2016-08-11 11:17:42.972
*** 2016-08-11 11:17:42.972
…
And again, this hasn't changed since it was introduced

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)
For example, PeopleSoft makes practical use of this to get a user ID set by the application into database triggers that perform application auditing. It uses another procedure to read the client identifier.
dbms_application_info.read_client_info(client_info OUT VARCHAR2)
Although, I find it is often more interesting to know where in an application a SQL came from, than which operator activated the code.

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;
/
So, if your application set module and action to meaningful, predictable values, you now had an easy way of enabling SQL trace (See also Enabling Oracle Extended SQL Trace by Module and Action). This is why I generally avoid putting the values of variables into module or action because it makes it difficult to enable trace by this method, unless perhaps the variable has relatively few known values.

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
/
This query profiles the amount of database time by program, module and action. We can see which modules and actions taken the most database time. Then we could look for specific SQL statements associated with a particular module.
                                                                                     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
…
Module and Action are also visible in:
  • 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;
I would characterise this as an investment rather than an overhead during development, in the same way, debug code is an investment that will pay dividends later if you are debugging a functional problem. The overhead of the DBMS_APPLICATION_INFO calls is trivially small, and they present the opportunity to make performance improvement activities much more effective for both developers and DBAs.

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.
For contrast, this example is taken from a PeopleSoft system. PeopleSoft is now instrumented out-of-the-box. With instrumentation, you can see that the time is broken down between the various components of the system. Now you can see which components consume the most time and justify the most attention. Many of the module names are meaningful to the developers.

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 write and talk about it instrumentation because I think it is impossible to overstate the value of instrumentation to an application using DBMS_APPLICATION_INFO and yet it is very rare to find instrumented systems.
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