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.

BEGIN
  DBMS_FGA.ADD_POLICY(
   object_schema      => 'SYSADM',
   object_name        => 'PS_NVS_REPORT',
   policy_name        => 'PS_NVS_REPORT_SEL',
   handler_module     => 'GFC_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.

CREATE OR REPLACE PROCEDURE sysadm.gfc_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,'GFC_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.

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.

                                                           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.

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.

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.

1. My thanks to Tyler McPheeters for the original idea of using FGA