nVision Performance Tuning: 5. Additional Instrumentation of nVision

This blog post is part of a series that discusses how to get optimal performance from PeopleSoft nVision reporting as used in General Ledger.

One of the challenges of tuning and monitoring nVision is to be able to identify each report being run. Calls to Oracle instrumentation package dbms_application_info  were added to the component processor in PeopleTools 8.50, and to Application Engine in PeopleTools 8.52.  However, COBOL, nVision, and SQR were never instrumented.
Therefore, there is still a place for the psftapi package and trigger.  When a PeopleSoft batch process starts, it sets the status on its request record on the Process Scheduler request record, psprcsrqst to 7, thus indicating that it is processing.  A trigger on that table fires on that update and calls the psftapi package.  The package sets module and action to the process name and process instance, and also stored the process instance number in a package global variable that can be read with another procedure in the package.  Every scheduled process will have module and action set to something meaningful.  Any PeopleSoft instrumentation will simply overwrite these values.  A sessions module and action are picked up Oracle monitoring tools, in particular, they are also stored in the Active Session History (ASH).
However, nVision reports always run as the same process name, either NVSRUN for a single report, RPTBOOK for a report book of many reports, or DRILLDWN for a nVision drill-down query.  Knowing the process instance is useful because then we can look up the operator and run control ID
However, we also need to know the report ID being run.  When each individual nVision report starts it queries the runtime parameters from the PS_NVS_REPORT PeopleTools table.  There is no update, so it is not possible to capture this with a DML trigger.  Instead, you can create a fine-grained audit policy on the query with a PL/SQL handler.  The handler package is then invoked by the audit policy.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 85%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">BEGIN
DBMS_FGA.ADD_POLICY(
object_schema => 'SYSADM',
object_name => 'PS_NVS_REPORT',
policy_name => 'PS_NVS_REPORT_SEL',
handler_module => 'AEG_FGA_NVISION_HANDLER',
enable => TRUE,
statement_types => 'SELECT',
audit_trail => DBMS_FGA.DB + DBMS_FGA.EXTENDED);
END;
/

The handler package runs in the session that triggered the audit.  It can access the audit record and extract the string of colon-separated bind variables thus obtaining the report ID and business unit.  It updates the session action attribute in the same way as psftapi.sql.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 85%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">CREATE OR REPLACE PROCEDURE sysadm.aeg_fga_nvision_handler
(object_schema VARCHAR2
,object_name VARCHAR2
,policy_name VARCHAR2)
AS
l_sqlbind VARCHAR2(4000);
l_parm1 VARCHAR2(30);
l_parm2 VARCHAR2(30);
l_parm3 VARCHAR2(30);
l_parm4 VARCHAR2(30);
BEGIN
BEGIN
SELECT x.lsqlbind
, SUBSTR(x.lsqlbind,x.start1,LEAST(30,NVL(x.end1,x.lensqlbind+1)-x.start1)) parm1
, SUBSTR(x.lsqlbind,x.start2,LEAST(30,NVL(x.end2,x.lensqlbind+1)-x.start2)) parm2
, SUBSTR(x.lsqlbind,x.start3,LEAST(30,NVL(x.end3,x.lensqlbind+1)-x.start3)) parm3
, SUBSTR(x.lsqlbind,x.start4,LEAST(30,NVL(x.end4,x.lensqlbind+1)-x.start4)) parm4
INTO l_sqlbind, l_parm1, l_parm2, l_parm3, l_parm4
FROM (
SELECT l.*
, NULLIF(REGEXP_INSTR(lsqlbind,' #[0-9]+\([0-9]+\)\:',1,1,1,'i'),0) start1
, NULLIF(REGEXP_INSTR(lsqlbind,' #[0-9]+\([0-9]+\)\:',1,2,0,'i'),0) end1
, NULLIF(REGEXP_INSTR(lsqlbind,' #[0-9]+\([0-9]+\)\:',1,2,1,'i'),0) start2
, NULLIF(REGEXP_INSTR(lsqlbind,' #[0-9]+\([0-9]+\)\:',1,3,0,'i'),0) end2
, NULLIF(REGEXP_INSTR(lsqlbind,' #[0-9]+\([0-9]+\)\:',1,3,1,'i'),0) start3
, NULLIF(REGEXP_INSTR(lsqlbind,' #[0-9]+\([0-9]+\)\:',1,4,0,'i'),0) end3
, NULLIF(REGEXP_INSTR(lsqlbind,' #[0-9]+\([0-9]+\)\:',1,4,1,'i'),0) start4
, NULLIF(REGEXP_INSTR(lsqlbind,' #[0-9]+\([0-9]+\)\:',1,5,1,'i'),0) end4
, LENGTH(lsqlbind) lensqlbind
FROM sys.fga_log$ l
) x
WHERE x.sessionid = USERENV('SESSIONID')
AND x.entryid = USERENV('ENTRYID')
AND x.obj$name = 'PS_NVS_REPORT';
EXCEPTION
WHEN no_data_found THEN
RAISE_APPLICATION_ERROR(-20000,'AEG_FGA_NVISION_HANDER: No Audit Row');
END;

IF l_parm4 IS NULL THEN
l_parm4 := l_parm3;
l_parm3 := l_parm2;
l_parm2 := l_parm1;
END IF;

IF l_parm4 IS NULL THEN
l_parm4 := l_parm3;
l_parm3 := l_parm2;
END IF;

IF l_parm4 IS NULL THEN
l_parm4 := l_parm3;
END IF;

dbms_output.put_line(l_sqlbind);
dbms_output.put_line(l_parm1);
dbms_output.put_line(l_parm2);
dbms_output.put_line(l_parm3);
dbms_output.put_line(l_parm4);

dbms_application_info.set_action(SUBSTR('PI='||psftapi.get_prcsinstance()||':'||l_parm4||':'||l_parm3,1,64));
--EXECUTE IMMEDIATE 'ALTER SESSION SET TRACEFILE_IDENTIFIER=''PI='||psftapi.get_prcsinstance()||':'||l_parm4||':'||l_parm3||'''';
END;
/

The action attribute is then picked up by the ASH data.  It is easy to extract the report ID and business unit from the action string with regular expressions, as in this example query.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 85%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">set lines 160 trimspool on
column module format a12
column action format a32
column client_id format a12
column prcsinstance format a9 heading 'Process|Instance'
column business_unit format a8 heading 'Business|Unit'
column report_id format a10
select DISTINCT module, action, client_id
, REGEXP_SUBSTR(h.action,'[[:digit:]]+') prcsinstance
, substr(regexp_substr(h.action,':([[:alnum:]])+',1,2),2) business_unit
, substr(regexp_substr(h.action,':([A-Za-z0-9_-])+',1,1),2) report_id
from v$active_session_History h
where program like 'PSNVS%'
/

Here you can see how process instance, report ID and business unit are held in action and how they can be extracted.  Now, it is possible to profile ASH data for nVision processes, find the long-running SQL and determine which layout it came from.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 85%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">                                                           Process   Business
MODULE ACTION CLIENT_ID Instance Unit REPORT_ID
------------ -------------------------------- ------------ --------- -------- ----------
RPTBOOK PI=1780508:GBGL224S:UK001 GBNVISION 1780508 UK001 GBGL113S
RPTBOOK PI=1780509:GBGL010E:UK002 GBNVISION 1780509 UK002 GBGL010E
RPTBOOK PI=1780502:GBGL91PF:UK001 GBNVISION 1780502 UK001 GBGL91PF
RPTBOOK PI=1780502:GBGL91FR:UK001 GBNVISION 1780502 UK001 GBGL91FR
RPTBOOK PI=1780502:GBGL91GB:UK001 GBNVISION 1780502 UK001 GBGL91GB
RPTBOOK PI=1780502:GBGL91DM:UK002 GBNVISION 1780502 UK002 GBGL91DM
RPTBOOK PI=1780506:GBEXP2AM:UK001 GBNVISION 1780506 UK001 GBEXP2AM
RPTBOOK PI=1780509:Processing GBNVISION 1780509 Processing
RPTBOOK PI=1780500:GBGL113S:UK003 GBNVISION 1780500 UK003 GBGL113S
RPTBOOK PI=1780509:GBGL010E:UK000 GBNVISION 1780508 UK000 GBGL010E 

This code in this blog is available on github.

Other recommendations

  • Create an index on SYS.FGA_LOG$ to support the query in the FGA handler package.
#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 85%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">CREATE INDEX sys.fga_log$_obj$name
ON sys.fga_log$ (obj$name, sessionid, entryid)
TABLESPACE sysaux PCTFREE 1 COMPRESS 1
/
  • Put a regular purge of the FGA_LOG$ table in place, to purge rows after, say, 31 days.  Otherwise, it will grow indefinitely, one row will be added for every nVision report run.
#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 85%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">DELETE FROM fga_log$ 
WHERE obj$name = 'PS_NVS_REPORT'
AND ntimestamp#
  • Move SYS.AUD$ and SYS.FGA_LOG$ from the SYSTEM tablespace to another ASSM tablespace using the instructions in Oracle support note 1328239.1.