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 stores 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 by 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 the 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

Fine-Grained Auditing in PeopleSoft

Recently, somebody asked me whether it is possible to audit the fact that someone has queried a piece of data in PeopleSoft. It led to an interesting piece of research.
It is a fairly easy matter to configure Fine-Grained Auditing (FGA) in Oracle, you have to create a policy with the DBMS_FGA package. You can choose which columns to audit and a logical audit condition to determine whether the rows should be audited. This example will log users who query salary data from the JOB record in PeopleSoft.

BEGIN
sys.dbms_fga.add_policy
(object_schema=>'SYSADM'
,object_name=>'PS_JOB'
,policy_name=>'JOB_SALARY'
,audit_condition=>'ANNUAL_RT != 0 OR MONTHLY_RT != 0 OR DAILY_RT != 0 OR
HOURLY_RT != 0 OR SHIFT_RT != 0 OR SHIFT_FACTOR != 0'
,audit_column=>'ANNUAL_RT, MONTHLY_RT, DAILY_RT, HOURLY_RT, SHIFT_RT,
SHIFT_FACTOR'
,enable=>TRUE
,statement_types=>'SELECT'
,handler_schema=>'SYS'
,handler_module=>'dmk_fga_hand( object_schema, object_name, policy_name)'
,audit_trail=>DBMS_FGA.DB + DBMS_FGA.EXTENDED
,audit_column_opts=>DBMS_FGA.ANY_COLUMNS);
END;
/

If the audit condition is matched for any rows in a query, and the query selects one of the audit columns, a single audit row is produced, irrespective of the number of rows that match.
Be aware that if the audit condition raises an error for any inspected row (such as an error caused by coercion), the audited query will also fail. There will be nothing in the message to suggest that it is caused by FGA, and so it can be difficult to diagnose and debug.
I chose to save the audit data to a table in the database, but alternatively, you can output the audit data as an XML data structure in a flat-file written by setting:

, audit_trail=>DBMS_FGA.XML

Oracle writes a file to the directory indicated by the AUDIT_FILE_DEST parameter.
And this is the data the Oracle records in the table.

SESSIONID DBUID    OSUID              OSHST
--------- -------- ------------------ ----------------------
EXTID                  OBJ$SCHEMA OBJ$NAME   POLICYNAME
---------------------- ---------- ---------- ----------
     SCN LSQLTEXT                             STMT_TYPE
--------- ----------------------------------- ----------
NTIMESTAMP#                INSTANCE# PROCESS#      STATEMENT
------------------------- ---------- ------------ ----------
  ENTRYID LSQLBIND
---------- -----------------------------------
    1927 SYSADM   GO-FASTER-4\David  GO-FASTER\GO-FASTER-4
GO-FASTER-4\David      SYSADM     PS_JOB     JOB_SALARY
 6375305 SELECT EMPLID, EMPL_RCD, EFFDT, T            1
23-JUL-07 15.47.21.429000          0 6856:11944        12104
        2  #1(6):K0G004 #2(1):0

It tells us is that a process, running as OS user David on node GO-FASTER-4, connected to the database as SYSADM and queried some audited data on table PS_JOB. But this node is the application server, and it will look the same for all access to PeopleSoft via the Application Server or any other program.
We need to collect some more information from the session.
If you use database triggers to audit updates in PeopleSoft, they obtain the PeopleSoft operator ID from the client information string that is set by a call to the DBMS_APPLICATION_INFO package at the start of every service in the application server. They extract the operator ID with a function called GET_PS_OPRID (delivered in getpsoprid.sql).
You can’t put a trigger on the audit table (SYS.FGA_LOG$) because it is owned by SYS, but we could use the error handler to call a custom PL/SQL procedure. The handler module is fired every time an audit record is written. It is intended to permit a notification to be sent on audit to the DBA when a policy is breached. But we could use it for a different purpose. The handler runs in the same session as the process that performs the audited action. So I can collect information about the session and write it to another audit table that I have created.

CREATE TABLE sys.dmk_fga
(timestamp# DATE
,object_schema VARCHAR2(30)
,object_name VARCHAR2(128)
,policy_name VARCHAR2(30)
,ntimestamp# TIMESTAMP
,instance# INTEGER
,sessionid INTEGER
,entryid INTEGER
,scn INTEGER
,action VARCHAR2(32)
,module VARCHAR2(48)
,client_info VARCHAR2(64)
);

CREATE OR REPLACE PROCEDURE dmk_fga_hand ( object_schema VARCHAR2, object_name VARCHAR2, policy_name VARCHAR2 ) AS
l_client_info VARCHAR2(64);
l_action varchar2(32);
l_module varchar2(48);
BEGIN
sys.dbms_application_info.read_client_info(l_client_info);
sys.dbms_application_info.read_module(l_module, l_action);
INSERT INTO dmk_fga
(timestamp#, ntimestamp#
, object_schema, object_name, policy_name
, instance#
, sessionid, entryid
, scn, client_info, action, module)
SELECT sysdate, systimestamp
, object_schema, object_name, policy_name
, i.instance_number
, USERENV('SESSIONID'), USERENV('ENTRYID')
, d.current_scn, l_client_info, l_action, l_module
FROM v$database d, v$instance i
WHERE rownum <= 1;  EXCEPTION WHEN OTHERS THEN NULL; END; /  

And this is the information that is inserted into my new logging table

TIMESTAMP#          OBJECT_SCH OBJECT_NAM POLICY_NAM
------------------- ---------- ---------- ----------
NTIMESTAMP#               INSTANCE# SESSIONID ENTRYID
------------------------- --------- --------- -------
     SCN ACTION               MODULE
--------- -------------------- --------------------
CLIENT_INFO
-----------------------------------------------------
23:00:54 23/07/2007 SYSADM     PS_JOB     JOB_SALARY
23-JUL-07 23.00.54.015000         1      1927       6
 6390779                      PSAPPSRV.exe
PS,,go-faster-4.london.go-faster.co.uk,HCM89,PSAPPSRV.exe,

The SCNs do not match between these two audit records. There is a difference of at least 3, but the tables can be joined on SESSIONID and ENTRYID (so you will probably need an index on these columns).

set long 5000
SELECT --b.client_info,
sysadm.get_ps_oprid(b.client_info) oprid,a.ntimestamp#, a.POLICYNAME
,a.lsqltext, a.lsqlbind
FROM  sys.fga_log$ a, sys.dmk_fga b
WHERE a.sessionid = b.sessionid
AND   a.entryid = b.entryid
;

Now, when I open a component in PeopleSoft that queries somebody’s compensation rate, the FGA policy generates a record.

I can use the above query to combine the audit data. It this example it shows that operator PS queried salary data for employee

OPRID        NTIMESTAMP#               POLICYNAME
------------ ------------------------- ----------
LSQLTEXT
----------------------------------------------------
LSQLBIND
----------------------------------------------------
PS           23-JUL-07 22.00.53.968000 JOB_SALARY
SELECT EMPLID, EMPL_RCD, EFFDT, TO_CHAR(EFFDT,'YYYY-
...
PL_RCD, EFFDT DESC, EFFSEQ DESC
#1(6):K0G005 #2(1):0

Note that the data was queried from the database when the component was opened, and that is when the audit occurred. The operator would have to navigate to the ‘Compensation’ tab to see the data, so the audit does not absolutely prove the data was displayed to the operator, but I suspect that is only a semantic difference.

Overhead

The ability to audit is all very well, but it comes at a price. It is not difficult to generate a large number of audit rows. In the following PL/SQL block, an audit row is generated for each time the query inside the loop is executed (2050 times on my HR demo database).

DECLARE
l_annual_rt NUMBER;
BEGIN
FOR i IN (SELECT DISTINCT emplid, empl_rcd FROM ps_job WHERE effdt <= SYSDATE) loop  
 SELECT j.annual_rt  
 INTO l_annual_rt  
 FROM ps_job j  
 WHERE j.emplid = i.emplid  
 AND j.empl_rcd = i.empl_rcd  
 AND j.effdt = (
  SELECT MAX(j1.effdt) FROM ps_job j1
  WHERE j1.emplid = i.emplid
  AND   j1.empl_rcd = i.empl_rcd
  AND   j1.effdt <= SYSDATE)  
 AND j.effseq = (
  SELECT MAX(j2.effseq) FROM ps_job j2
  WHERE j2.emplid = i.emplid
  AND   j2.empl_rcd = i.empl_rcd
  AND   j2.effdt = j.effdt); 
END LOOP;
END;
/ 

This can have a dramatic effect on performance. I ran the above PL/SQL on my laptop with SQL*Trace.

Operation	Without FGA	With FGA
Driving Query	0.46s	0.43s
Inner Query	0.92s	3.43s
Insert into FGA_LOG$		1.68s
Insert into DMK_FGA		6.48s
Other time in Exception Handler		0.72s
Total	1.38s	12.75s

FGA causes a huge increase in the response time of this test. Most of the additional time is spent inserting the audit rows, although the performance of the single disk in my laptop is probably magnifying the effect.
Conclusion
I have demonstrated that it is possible to use FGA to monitor who is looking at what in PeopleSoft as well as detecting other forms of break-in. However, it can introduce a significant run-time overhead. The ability to incorporate a custom PL/SQL notification procedure suggests that it is designed with the intention of logging exceptional activities rather than routine one that users are permitted to perform.

While FGA could be used to audit access to sensitive data, I think that row-level security should be set up correctly in PeopleSoft in the first place, so that only duly authorised users can access sensitive data. I suggest that FGA should only be used conservatively to monitor exceptional events.