PeopleTools 8.52 Application Engine sets MODULE and ACTION

Update 4.3.2015: See also Undocumented Application Engine Parameter: EnableAEMonitoring

I have written and spoken often about the huge importance of instrumentation in an application. PeopleSoft introduced internal instrumentation to PeopleTools 8.44 for its own Performance Monitor that works on any platform. Since PeopleTools 7.53, when running on an Oracle database, PeopleTools also calls the Oracle supplied package dbms_application_info package to set the module and action for the session. The values set were not particularly useful, so I wrote a PL/SQL package (psftapi) and trigger to set the module and action attributes when a process started.

In PeopleTools 8.50 this instrumentation was enhanced to set module and action to the component and page name in the PIA. These values appear in Oracle Enterprise Manager and Active Session History (ASH). They can be used to profile components.

Now, in PeopleTools 8.52 Application Engine has been enhanced to set the action to the full Application Engine step name.

To illustrate what happens, I have produced an Oracle Extended SQL Trace for the process, but I have shown only the lines in a SQL Trace file with 3 asterisks. So you can see MODULE and ACTION being set (and some other timestamp information). The lines in italic were emitted when module and action were set by my psftapi package, in which I simply set the MODULE to the Application Engine program name.

*** 2012-11-22 21:47:38.282
*** SESSION ID:(7.2237) 2012-11-22 21:47:38.282
*** CLIENT ID:(PS) 2012-11-22 21:47:38.282
*** SERVICE NAME:(HCM91) 2012-11-22 21:47:38.282
*** MODULE NAME:(PSPMCSOSUM) 2012-11-22 21:47:38.282
*** ACTION NAME:(PI=867:Processing) 2012-11-22 21:47:38.282
*** MODULE NAME:(PSAE.PSPMCSOSUM.1448) 2012-11-22 21:47:38.419
*** ACTION NAME:(PSPMCSOSUM) 2012-11-22 21:47:38.419
*** ACTION NAME:(PSPMCSOSUM.MAIN.STATS.S) 2012-11-22 21:47:38.420
*** 2012-11-22 21:47:38.588
*** ACTION NAME:(PSPMCSOSUM.MAIN.CTL.P) 2012-11-22 21:47:38.919
*** ACTION NAME:(PSPMCSOSUM.MAIN.SELECT.C) 2012-11-22 21:47:38.937
*** ACTION NAME:(PSPMCSOSUM.GETCNT.CNT.P) 2012-11-22 21:47:38.963
…
*** ACTION NAME:(PSPMCSOSUM.MAIN.SELECT.C) 2012-11-22 21:48:15.168
*** ACTION NAME:(PSPMCSOSUM.GETCNT.CNT.P) 2012-11-22 21:48:15.168
*** ACTION NAME:(PSPMCSOSUM.MAIN.Close.P) 2012-11-22 21:48:15.197
*** ACTION NAME:(PI=867:Success) 2012-11-22 21:48:15.201

Application Engine also sets the MODULE attribute.  In the above example it was set to PSAE.PSPMCSOSUM.1448.  The string is composed of three parts.

• PSAE indicates that it was running Application Engine. It sets the same value for both stand-alone and Tuxedo server Application Engine processes.
• PSPMCSOSUM was the name of the Application Engine Program
• 1448 was the operating system process ID of the Application Engine process.  This value is recorded in the column SESSIONIDNUM on the table PSPRCSQUE.

The inclusion of the SESSIONIDNUM is useful because it is possible to determine the process instance.  If you have multiple instances of the same Application Engine program running concurrently, you can work out which ASH samples correspond to which process instance by matching the session ID.

SELECT  r.prcsinstance, h.module, h.action, sum(1) ash_secs
FROM v$active_Session_history h
, psprcsque q
, psprcsrqst r
WHERE r.prcsinstance = q.prcsinstance
AND h.module = 'PSAE.'||q.prcsname||'.'||q.sessionidnum
AND h.sample_time BETWEEN r.begindttm AND NVL(r.enddttm,SYSDATE)
and r.prcsinstance = 867
GROUP BY r.prcsinstance, h.module, h.action
ORDER BY ash_secs DESC
/

PRCSINSTANCE MODULE               ACTION                    ASH_SECS
------------ -------------------- ------------------------- --------
         867 PSAE.PSPMCSOSUM.1448 PSPMCSOSUM.GETCNT.CNT.P          7
         867 PSAE.PSPMCSOSUM.1448 PSPMCSOSUM.MAIN.STATS.S          1

Unfortunately, this change to MODULE also means that it is no longer possible to enable trace by setting a watchpoint (as I blogged previously).  It no longer works with Application Engine because it is not possible to predict the value of the SESSIONIDNUM in MODULE.

I am testing with 8.52.12 and have found a significant problem. Application Engine doesn't set the action on DO SELECT statements. The first statement in the trace extract below does come from PSPMCSOSUM.MAIN.CTL PeopleCode, however, the second SQL statement actually comes from PSPMCSOSUM.MAIN.SELECT.D, but the absence of another action line would lead you to believe the statement came from the preceding PeopleCode step.

*** ACTION NAME:(PSPMCSOSUM.MAIN.CTL.P) 2012-11-22 21:47:38.919
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220814597
WAIT #0: nam='SQL*Net message from client' ela= 740 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220815371
CLOSE #348647416:c=0,e=33,dep=0,type=1,tim=257220815447
=====================
PARSING IN CURSOR #348528704 len=98 dep=0 uid=45 oct=3 lid=45 tim=257220815496 hv=1424819941 ad='7ff2559e550' sqlid='98af7ppafu1r5'
END OF STMT
PARSE #348528704:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1148792852,tim=257220815496
EXEC #348528704:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1148792852,tim=257220815572
WAIT #348528704: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220815612
FETCH #348528704:c=0,e=2824,p=0,cr=16,cu=0,mis=0,r=1,dep=0,og=1,plh=1148792852,tim=257220818462
STAT #348528704 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=16 pr=0 pw=0 time=2828 us)'
STAT #348528704 id=2 cnt=3075 pid=1 pos=1 obj=228740 op='INDEX FULL SCAN PS_PSPMCSO_CHART (cr=16 pr=0 pw=0 time=333 us cost=0 size=13 card=1)'
WAIT #348528704: nam='SQL*Net message from client' ela= 123 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220818671
FETCH #348528704:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1148792852,tim=257220818696
WAIT #348528704: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220818714
WAIT #348528704: nam='SQL*Net message from client' ela= 702 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220819434
CLOSE #349389936:c=0,e=16,dep=0,type=1,tim=257220819496
=====================
PARSING IN CURSOR #349702624 len=555 dep=0 uid=45 oct=3 lid=45 tim=257220819548 hv=1888777338 ad='7ff2559ce90' sqlid='5phgqq9s98x3u'
SELECT DISTINCT OPRID , TO_CHAR(CAST((LOGINDTTM) AS TIMESTAMP),'YYYY-MM-DD-HH24.MI.SS.FF') , TO_CHAR(CAST((LOGOUTDTTM) AS TIMESTAMP),'YYYY-MM-DD-HH24.MI.SS.FF') , PM_SIGNON_TYPE , PM_SIGNOFF_TYPE FROM PSPMCSOLOG_VW WHERE '1' <> '2' AND TO_DATE(TO_CHAR(LOGINDTTM,'YYYY-MM-DD'),'YYYY-MM-DD') >= TO_DATE('2005-07-06','YYYY-MM-DD') AND TO_DATE(TO_CHAR(LOGOUTDTTM,'YYYY-MM-DD'),'YYYY-MM-DD') >= TO_DATE('2005-07-06','YYYY-MM-DD') AND OPRID NOT IN ( SELECT OPRID FROM PSPMCSOCHRTXOP) AND LOGIPADDRESS NOT IN ( SELECT LOGIPADDRESS FROM PSPMCSOCHRTXIP) ORDER BY 2
END OF STMT
PARSE #349702624:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4226533831,tim=257220819547
EXEC #349702624:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4226533831,tim=257220819669
WAIT #349702624: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220819723
WAIT #349702624: nam='SQL*Net more data to client' ela= 76 driver id=1413697536 #bytes=8145 p3=0 obj#=-40016373 tim=257220831271
FETCH #349702624:c=15600,e=11621,p=0,cr=214,cu=0,mis=0,r=201,dep=0,og=1,plh=4226533831,tim=257220831375
WAIT #349702624: nam='SQL*Net message from client' ela= 988 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220832412
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220832481
WAIT #0: nam='SQL*Net message from client' ela= 40 driver id=1413697536 #bytes=1 p3=0 obj#=-40016373 tim=257220832541
*** ACTION NAME:(PSPMCSOSUM.MAIN.SELECT.C) 2012-11-22 21:47:38.937

However, MAIN.SELECT.D duly appears in the AE batch timings report.

                               C o m p i l e    E x e c u t e    F e t c h        Total           
SQL Statement                  Count   Time     Count   Time     Count   Time     Time    
------------------------------ ------- -------- ------- -------- ------- -------- --------
…
AE Program: PSPMCSOSUM

MAIN.CTL.D                           1      0.0       1      0.0       2      0.0      0.0
MAIN.SELECT.D                        1      0.0       1      0.0     556      0.0      0.0
MAIN.STATS.S                         1      0.0       1      0.5       0      0.0      0.5
…

This is a serious problem  If you profile the top SQL statements in an Application Engine (using either ASH as I have done above, or by profiling a trace file and looking for the top SQL statement by searching through the raw trace file) it will lead you to the wrong conclusion!  Time spent in PSPMCSOSUM.MAIN.SELECT.D will be accounted as having been spent in PSPMCSOSUM.GETCNT.CNT.P.  It is not until you look for the specific SQL statement in Application Designer that you realise that the source code doesn't match the instrumentation.

 

Nevertheless, this instrumentation is a very welcome and significant improvement for Application Engine. It will help to localise performance problems. However, until the omissions are fixed, you will need to be aware of their implications and avoid falling into the traps.

My thanks to Wolfgang Breitling for telling me about the feature.

Enabling Oracle Extended SQL Trace by Module and Action

I have written previously about the value of assigning meaningful values to the module and action attributes on a database session (see Using Oracle Enterprise Manager (Grid Control) with PeopleSoft). Oracle added instrumentation to PeopleTools 8.50 (see PeopleTools 8.50 uses DBMS_APPLICATION_INFO to Identify Database Sessions) that sets module and action for on-line and batch sessions.  However, I still use my own trigger to set these attributes for processes initiated by the Process Scheduler.

I originally became interested in module and action because it made it possible to analyse performance problems in specific processes with Active Session History (see Practical Use of ASH). However, since Oracle 10g there is also a very easy way to enable Oracle's extended session trace in the sessions relating to specific processes.

In the Oracle supplied PL/SQL package DBMS_MONITOR, there are two programs to specify combinations of module and action for which SQL trace will be enabled.  It is rather like setting a watchpoint in a debugger. SERV_MOD_ACT_TRACE_ENABLE is used to create a watchpoint, and SERV_MOD_ACT_TRACE_DISABLE removes it. Trace is then enabled in a session when the module and action is set to a value that matches a watchpoint and disabled when the module and/or action is changed to a value for which there is no watchpoint.

This screenshot from OEM shows that a query is being run within a PeopleSoft component RECV_PO, page PO_PICK_ORDERS.

It would be a simple matter to have Oracle trace the session for that component by setting a watchpoint.

BEGIN
 sys.dbms_monitor.serv_mod_act_trace_enable
 (service_name=>'P1PPP'
 ,module_name =>'RECV_PO'
 ,waits=>TRUE
 ,binds=>TRUE);
END;
/

Note that the service name must be specified as part of the watchpoint.  This will usually be the same as the PeopleSoft database name.  Thus, watchpoints copied to another database by cloning won't be effective because the service name will be different.

I could also have specified an action in the example above, but I want to trace all pages in the component and the search dialogue.

As with the other programs in dbms_monitor, information on wait events is included in traces by default.  In the above example, I have also requested information on bind variables to be included in the trace.

When setting a SQL trace for an on-line component it is possible that many different users could trigger tracing.  Trace will be enabled and disabled for each user. The result is that you will get a trace file for each application server process, and each trace file might contain the activity for more than one user if the application server process handled more than one service request.

Watchpoints can be removed in a similar way.

BEGIN
 sys.dbms_monitor.serv_mod_act_trace_disable
 (service_name=>'P1PPP'
 ,module_name =>'RECV_PO'
 ,action_name =>'PO_PICK_ORDERS');
END;
/

Watchpoints are held the table SYS.WRI$_TRACING_ENABLED.

SELECT * FROM sys.wri$_tracing_enabled
/

TRACE_TYPE PRIMARY_ID QUALIFIER_ID1 QUALIFIER_ID2   INSTANCE_NAME FLAGS
---------- ---------- ------------- --------------- ------------- -----
         5 P1PPP      RECV_PO       PO_PICK_ORDERS                   12

This technique is also effective for processes initiated by the Process Scheduler. The default behaviour from PeopleTools 8.50 is to set Action to the process name, my trigger sets Module to the process name.

 

If I specify only the Module in SERV_MOD_ACT_TRACE_ENABLE, then it trace will be enabled for that module and for any action.

BEGIN
 sys.dbms_monitor.serv_mod_act_trace_disable
 (service_name=>'AAAAAAA'
 ,module_name =>'GPPDPRUN');
END;
/

I choose to set the action to the Process Instance number because I find it useful to relate ASH data to a specific batch process. The above screenshot from OEM shows a streamed Global Payroll calculation running with many concurrent GPPDPRUN processes. The watchpoint would cause each and every process to trace.

However, it has been suggested that if the Action was set to the process run control ID then the watchpoint could be set to the specific run control value used by a user or scheduled job. It would be a simple matter of changing the trigger (I'll leave that as an exercise).  Then, a user could be told to use a specific value for run control ID that would then invoke trace.

BEGIN
 sys.dbms_monitor.serv_mod_act_trace_disable
 (service_name=>'AAAAAAA'
 ,action_name =>'TRACEME');
END;
/

Update 24.11.2012 This technique will not work for Application Engine from PeopleTools 8.52 because it now sets MODULE to a value that includes a session number and so cannot be predicted.

Enabling Oracle Database Trace on PeopleSoft processes with a Trigger (improved)

In Chapter 11 of PeopleSoft for the Oracle DBA, I suggested using a database trigger to enable Oracle's SQL Trace facility. Then, in chapter 14, I introduced a further trigger to disable trace for Application Engine processes, in case they are run with the PSAESRV process.

This was not a good idea because the cursors opened by the Application Engine program are still open when the AE program completed, and the process updates its status from 7 (processing) to 9 (success) or 3 (error). This causes the unset_trace trigger to fire and disable SQL Trace. Consequently, the STAT lines for these cursors are never emitted to the trace file. The STAT lines contain the execution plans and a wealth of other information.

Updated 26.4.2021: Instead, I have a new version of the trace trigger (trace_trigger.sql can be downloaded from my Github repository of PeopleSoft scripts).

spool trace_trigger
rem (c)Go-Faster Consultancy Ltd. 2008

rem 1.5.2008 - moved logic to disable trace from unset_trace trigger into main trigger 
rem because cursors in AE not shut until after status is changed away from processing

ROLLBACK;
----------------------------------------------------------------
REM explicit grants by sys required on following privileges
----------------------------------------------------------------
GRANT ALTER SESSION TO sysadm;
GRANT EXECUTE ON sys.dbms_monitor TO sysadm;
GRANT EXECUTE ON sys.dbms_application_info TO SYSADM;
----------------------------------------------------------------

CREATE OR REPLACE TRIGGER sysadm.set_trace
BEFORE UPDATE OF runstatus ON sysadm.psprcsrqst
FOR EACH ROW
WHEN (new.runstatus = 7 AND old.runstatus != 7 AND new.prcstype != 'PSJob')(1)
DECLARE
  l_waits BOOLEAN := TRUE;(2)
  l_binds BOOLEAN := FALSE;
BEGIN
  --set module and action whether we are tracing or not
  sys.dbms_application_info.set_module((3)
 module_name => :new.prcsname,
 action_name => 'PI='||:new.prcsinstance
  );
   
  IF ( :new.runcntlid LIKE 'TRACEME%'(5)
  ----------------------------------------------------------------
  --code conditions for enabling trace here instead of when clause
  ----------------------------------------------------------------
  --  OR (    SUBSTR(:new.prcsname,1,3) = 'TL_'
  --      AND :new.rqstdttm <= TO_DATE('20080509','YYYYMMDD'))
  ----------------------------------------------------------------
     ) THEN

    --if we are going to trace, then set tracefile identifier
    EXECUTE IMMEDIATE 'ALTER SESSION SET TRACEFILE_IDENTIFIER(4) = '''||
      TRANSLATE(:new.prcstype     ,' -','__')||'_'||
      TRANSLATE(:new.prcsname     ,' -','__')||'_'||
      :new.prcsinstance||'_'||
       TRANSLATE(:new.servernamerun,' -','__')||
       '''';

    EXECUTE IMMEDIATE 'ALTER SESSION SET TIMED_STATISTICS = TRUE';
    EXECUTE IMMEDIATE 'ALTER SESSION SET MAX_DUMP_FILE_SIZE = 2097152'; --1Gb
    EXECUTE IMMEDIATE 'ALTER SESSION SET STATISTICS_LEVEL=ALL';

    ----------------------------------------------------------------
    --logic to determine whether you want to trace binds also
    ----------------------------------------------------------------
    IF :new.runcntlid LIKE 'TRACE%BIND%' THEN(6)
      l_binds := TRUE;
    END IF;
    ----------------------------------------------------------------

    sys.dbms_monitor.session_trace_enable(waits=>TRUE,binds=>l_binds);(7)
--  EXECUTE IMMEDIATE 'ALTER SESSION SET EVENTS ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 12''';

  ELSIF :new.prcstype = 'Application Engine' THEN(8)
    --explicitly disable trace if application server process
    sys.dbms_monitor.session_trace_disable;

    --reset max dump file size AFTER disabling trace
    EXECUTE IMMEDIATE 'ALTER SESSION SET MAX_DUMP_FILE_SIZE = 5M';

    --if not tracing, then reset tracefile identifier
    EXECUTE IMMEDIATE 'ALTER SESSION SET TRACEFILE_IDENTIFIER(4) = ''''';
  END IF;
EXCEPTION WHEN OTHERS THEN NULL;
END;
/

show errors

DROP TRIGGER sysadm.unset_trace;

rem test that the trigger fires by updating something
UPDATE  sysadm.psprcsrqst new
SET     runstatus = 7
WHERE   runstatus != 7
AND     new.prcstype != 'PSJob'
AND    rownum < 1
--AND 1=2
;

ROLLBACK;
spool off

1. The trigger fires when any process begins. Previously I used logic in the WHEN clause to restrict when it fired.
2. Wait events are collected in the trace by default.
3. Irrespective of whether trace is enabled, the trigger also calls the dbms_application_info package to set the module name to the PeopleSoft Process Name, and action to the PeopleSoft Process Instance number.
4. Also irrespective of whether trace is enabled, the trace file identifier is set so that the trace file name includes the Process Type, Process Name, Process Instance Number, and the name of the Process Scheduler.
(Updated 6.2.2009) Previous versions of this trigger set tracefile identifier irrespective of whether trace was enabled. Unfortunately, this causes a small trace file to be generated for every process.5. Logic in the trigger determines whether a SQL Trace will be enabled. The supplied version of the trigger traces processes whose run controls begin with 'TRACE'
6. Additional logic has been added to also enable bind variables to be captured if the run control begins with 'TRACEBIND'.
7. The dbms_monitor package is new in Oracle 10g and is the only officially supported way to enable extended trace. If using the trigger on earlier versions of the database, it should be replaced with the commented code to set event 10046.
8. If it is not required to SQL Trace a process, and the process is an Application Engine program, then trace is explicitly disabled. Thus, if a PSAESRV process has traced an AE program, trace is disabled when it next handles a request. This has the advantage that the stat lines for the cursors are written to the trace file. However, the disadvantage is that the process continues to trace between requests, and the time between requests is reported as 'SQL*Net message from client'.