Poor performance of PSPMSESSIONS_VW view affects Performance Monitor System Monitor Component

The System Performance Monitor component (PSPMSYSHEALTH; navigation: PeopleTools -> Performance Monitor -> System Performance) gives an overview of each system monitored by the PeopleSoft Performance Monitor. However, the poor performance of the view PSPMSESSIONS_VW can severely affect this component, to the extent that as transaction history builds up the component will not respond within the timeout.

Below is an extract from a PeopleTools trace. What happened is that the query ran until the Tuxedo service timed out. Tuxedo terminated application server process 31944, and spawned a new process (ID 3598). The user session received an error.

PSAPPSRV.31944 (70)   1-783    11.38.38    0.000072
Cur#1.31944.PMONITOR RC=0 Dur=0.000040 COM
Stmt=select count(*) from pspmsessions_vw where pm_agentid = :1
PSAPPSRV.31944 (70)   1-784    11.38.38    0.000008
Cur#1.31944.PMONITOR RC=0 Dur=0.000001 
Bind-1 type=19 length=3 value=689
PSAPPSRV.3598 (112)   1-132    11.42.39  314.495972
Cur#1.3598.PMONITOR RC=0 Dur=0.000095 COM
Stmt=SELECT VERSION FROM PSVERSION WHERE OBJECTTYPENAME = 'SYS'

Even when each query finishes within a reasonable amount of time, the query can be run several times by the component.

This is the definition of PSPMSESSIONS_VW delivered by PeopleSoft.

SELECT T3.PM_CONTEXT_VALUE1
,      T3.PM_AGENTID
,      T3.PM_AGENT_STRT_DTTM
FROM   PSPMTRANSHIST T3
WHERE  T3.PM_TRANS_DEFN_ID = 116
AND    PM_TRANS_STATUS = '1'
AND    PM_TRANS_DURATION <> 0
AND    T3.PM_CONTEXT_VALUE1 IN (
SELECT T.PM_CONTEXT_VALUE1
FROM   PSPMTRANSHIST T
WHERE  T.PM_TRANS_DEFN_SET = 1
AND    T.PM_TRANS_DEFN_ID = 109
AND    T.PM_MON_STRT_DTTM > %TimeAdd(%CurrentDateTimeIn, -720)
AND    T.PM_PARENT_INST_ID <> PM_TOP_INST_ID
AND    T.PM_CONTEXT_VALUE1 NOT IN (
 SELECT T2.PM_CONTEXT_VALUE1
 FROM   PSPMTRANSHIST T2
 WHERE  T2.PM_TRANS_DEFN_SET = 1
 AND    T2.PM_TRANS_DEFN_ID = 108
 AND    T2.PM_CONTEXT_VALUE1 = T.PM_CONTEXT_VALUE1
 AND    T2.PM_MON_STRT_DTTM > %TimeAdd(%CurrentDateTimeIn, -720)))

Firstly, accurate object statistics are required on the transaction history table and its indexes.

An additional index is required on PSPMTRANSHIST:

CREATE INDEX PSPPSPMTRANSHIST ON PSPMTRANSHIST
(PM_TRANS_DEFN_SET
,PM_TRANS_DEFN_ID
,PM_CONTEXT_VALUE1
,PM_MON_STRT_DTTM)
TABLESPACE PSINDEX PCTFREE 0
PARALLEL NOLOGGING COMPRESS 3
/
ALTER INDEX PSPPSPMTRANSHIST NOPARALLEL LOGGING
/

Finally, I have changed the view.

• The IN() operators have been changed to WHERE EXISTS(). The new index supports the efficient execution of these sub-queries.
• The sub-queries are now both correlated back to the main query on T3.
• The ROWNUM criteria have been added to restrict the number of rows the sub-queries can return.

SELECT T3.PM_CONTEXT_VALUE1 /*Session ID*/
,      T3.PM_AGENTID
,      T3.PM_AGENT_STRT_DTTM
FROM   PSPMTRANSHIST T3
WHERE  T3.PM_TRANS_DEFN_ID = 116 /*Redirect after login*/
AND    T3.PM_TRANS_DEFN_SET = 1 /*added*/
AND    T3.PM_TRANS_STATUS = '1'
AND    T3.PM_TRANS_DURATION <> 0
AND EXISTS(
SELECT 'x'
FROM   PSPMTRANSHIST T
WHERE  T.PM_TRANS_DEFN_SET = 1
AND    T.PM_TRANS_DEFN_ID = 109 /*User Session Began*/
AND    T.PM_MON_STRT_DTTM > %TimeAdd(%CurrentDateTimeIn, -720)
AND    T.PM_PARENT_INST_ID <> T.PM_TOP_INST_ID
AND    T.PM_CONTEXT_VALUE1 = T3.PM_CONTEXT_VALUE1
AND NOT EXISTS(
 SELECT 'x'
 FROM   PSPMTRANSHIST T2
 WHERE  T2.PM_TRANS_DEFN_SET = 1
 AND    T2.PM_TRANS_DEFN_ID = 108 /*User Session Ended*/
 AND    T2.PM_MON_STRT_DTTM > %TimeAdd(%CurrentDateTimeIn, -720)
 AND    T2.PM_CONTEXT_VALUE1 = T3.PM_CONTEXT_VALUE1
 AND    ROWNUM <= 1)
 AND    ROWNUM <= 1)

The effect of these changes is a significant improvement in the performance of the query. I ran a test query for a single agent on a system with over 3 million rows on PSPMTRANSHIST:

• Original: 24895 consistent gets
  
• New Index: 22547 consistent gets
  
• and View Changes: 85 consistent gets

Your mileage may vary, but for me this made the difference between the component being usable and not.

How to Clear the Application Server Cache Without Shutting it Down

Updated 4.9.2008: It is often necessary to clear the physical cache files on the PeopleSoft application server. You would think that after all the length of time that PeopleTools has been around, that development would have sorted out the problems in object version numbering. Sometimes, recently migrated changes do not take effect until the cache is cleared. Global Support will nearly always ask you to clear the cache if you are experiencing any kind of problem in the PIA. Normally, you would shut down the application server, delete the physical cache directories and restart the application server. From PeopleTools 8.48, each Application server process can only use one dedicated set of physical cache files that is in a directory whose name includes the name and ID number of the server, (previously the server process could use any unlock set cache directories). This allowed PeopleSoft to add an option to the psadmin utility to trigger each PSAPPSRV process to clear out its own physical cache (my thanks to the anonymous question asked after the original version of this posting that reminded me). This option also causes each server process to be recycled. It is the recommended and supported way to clear the physical cache files. This can also be invoked from the command line

psadmin -c purge -d <domain> [-noarch | -arch <archive_directory>] [-log <"log_comments">]
where 'domain' specifies domain name in PS_HOME and
   'archive_directory' specifies location to which to quarantine the purged cache,
   'log_comments' specifies any comments to be added to the purge cache log entry

However, even in previous versions, there has always been a way to invalidate all physical cache files. Any cached object older than the value of LASTREFRESHDTTM on the table PSSTATUS (it was on a different table prior to PeopleTools 8) is purged from the cache when the process that references that cache starts. Therefore, if that value is updated to the current time, the entire cache will be purged.

UPDATE PSSTATUS
SET    LASTREFRESHDTTM = SYSDATE
/
COMMIT
/

Sometimes, developers also have to clear the physical cache on their clients used by the Application Designer. Updating PSSTATUS also clears two-tier client caches. In fact, this behaviour is left over from the days when PeopleTools was a two-tier application, and it was necessary to clear cache files on users' desktop computers.

• If you have multiple Application Servers on a single database, then you can shut each one down in turn without any loss of server. The users will fail over to the surviving servers. However, this can result in the load being unevenly distributed and could overload one server.
• In small environments, and this includes most development and test systems, there is only a single application server. Shutting down an application server requires downtime and can be disruptive.

If an application server has at least two instances of a server process then each process can be recycled one by one, and there is no loss of service because the other processes can handle incoming requests. You could do this manually by entering the stop and boot commands in tmadmin (I discussed this in Chapter 13 of PeopleSoft for the Oracle DBA, but didn't combine it with the idea of clearing the Application Server cache). I have produced a script, tuxcycle.sh (available from GitHub) that uses the Tuxedo command line interface utility, tmadmin, to find out which PSAPPSRV processes are running, and then sequentially recycles each of them. I don't think I would completely automate these two operations into a single process, nor would I run them unattended, but you can now clear cache files without taking a system away from users or developers. Remember, that users will experience a reduction in performance after clearing the cache because it needs to be rebuilt by querying the PeopleTools table. The Process Scheduler, Master Process Scheduler, Distribution Server, and Application Engine processes also have physical caches. These are also cleared when LASTREFRESHDTTM is updated and the processes restarted. However, you should not shut down the Process Scheduler while processes are executing. The server process will shut down and the Application Engine will be killed if using an Application Engine server process (PSAESRV). Any stand-alone processes, including psae, will be killed by the Process Scheduler when it is restarted.

Serious fault with PeopleSoft Performance Monitor fixed in PeopleTools 8.49.14

Regular readers of my ramblings will know that I spend a lot of my time working with the PeopleSoft Performance Monitor (PPM). It is an extremely valuable source of performance metrics that are mostly not available, or if they are just difficult to obtain and process.

In PeopleTools 8.49, PPM has a serious fault. It is very similar to scenario reported for PeopleTools 8.44 in GSC Solution 200769188: PerfMon: Too many httpd processes spawned/sockets opened when using PerfMon.

"When a 404 is returned from the monitor server the calling agent code only checks the HTTP return code but does not flush the input stream. This causes the connection to remain open until the GC finally closes the input steam which closes the open connection. This is easily detected by the increasing list of sockets in CLOSE_WAIT state [, as reported by netstat]. On NT there is no hard limit on file descriptors and therefore a crash is not noticed. On Unix platforms this can cause the process to run out of file descriptors before the JVM GC has a chance to run and free up the sockets."

Hence, when running the application server on Unix, you will reach a point where JSH processes cannot open new ports and PIA users can receive the 'Application Server is Down' message. So, this can cause the system to become unavailable until the application server is rebooted. To prevent this occurring, the PPM must be deconfigured. The Monitor URL should be set to 'NONE'.

According to PeopleSoft Global Support this problem will be resolved in PeopleTools 8.49 patch 14.

Sequence Number Allocation in PeopleSoft

In PeopleSoft for the Oracle DBA Chapter 8 (p168-170) in a section called Sequence Numbers and Concurrency I discuss the implications of how this is done in HR8.4 as a part of the save time processing in PeopleCode FUNCLIB_HR.EMPLID.FieldFormula.

[FUNCLIB_HR.EMPLID.FieldFormula]
SQLExec("Update PS_INSTALLATION Set EMPLID_LAST_EMPL = EMPLID_LAST_EMPL +  1");
SQLExec("Select EMPLID_LAST_EMPL From PS_INSTALLATION", &EMPLID);
…

The problem is that while this update remains uncommitted, nobody else can obtain a new employee ID because the row is locked. This design has scalability issues. PeopleSoft applications generally get away with this because the update is performed as a part of save time processing which is committed when that is complete. Thus the lock is held for only a short time, and never waits for a human response. It executes in the application server which should be close to the database, so there is no network latency.

However, I was looking at this same PeopleCode in HR9.0 and I have noticed that is has changed. The change appears to have been introduced in HR8.8, and uses a new built-in PeopleCode function, GetNextNumberWithGapsCommit(record.field, max_number, increment [, WHERE_Clause, paramlist]), that was introduced in PeopleTools 8.44.

PeopleBooks describes the function thus:
"Use the GetNextNumberWithGapsCommit function to return the sequence number value plus increment for the given field residing in the given record. This function also enables you to specify a SQL Where clause as part of the function for maintaining multiple sequence numbers in a single record.

This function is typically used for obtaining a new sequence number for the application ... The sequence number (record.field ) is incremented right away and it doesn't hold any database internal row lock beyond the execution of this function.

Note. A secondary database connection is used to increment and retrieve record.field. The default behaviour is to keep the secondary database connection persistent in order to improve performance for the next GetNextNumberWithGapsCommit usage. If the database administrator finds the persistent connection too high an overhead for the production environment (which should not be the case since PeopleSoft uses application server to multiplex the database connection), the database administrator can change the default behaviour to use an on-demand connection method. The persistent second connection is disabled using DbFlags bit eight in the application server and process scheduler configuration files. The second connection can be completely disabled using DbFlags bit four in the application server and process scheduler configuration files

The following restrictions apply to the GetNextNumberWithGapsCommit function:

• The function is enabled for Application Engine programs running in stand-alone mode (via PSAE). This function is disabled for Application Engine programs that execute through the PeopleSoft Application Engine server (PSAESRV).
• This function is enabled for PeopleSoft Application Engine programs running under Unix System Services on z/OS.
• PeopleSoft does not recommend Using both the GetNextNumberWithGapsCommit function and the GetNextNumber function in the same application, on the same table, in the same unit of work. This can lead to lock contention or deadlocking.
• For a DB2 z/OS database, isolate the table that contains the sequence number to its own tablespace and set the locksize parameter to row."

Hence, if migrating data into a system via a Component Interface (eg. employees from a legacy system where new EMPLIDs will be allocated), and you need to do this with multiple concurrent process to achieve throughput, it is advantageous to use PSAE rather than PSAESRV processes, otherwise they are likely to serialise.

This is the PeopleTools trace produced when I added an new person to an HR system. You can see the second connection to the database is created at line 51935, and then the row is updated, queried and immediately committed. The lock is only held for only 35ms (on my laptop), instead of holding it until all the save-time processing completes.

PSAPPSRV.4180 1-51932 23.26.14 0.000000 >>> start-ext Nest=01 assign_employee_id FUNCLIB_HR.EMPLID.FieldFormula
PSAPPSRV.4180 1-51933 23.26.14 0.019000 Cur#2.4180.HCM89 RC=0 Dur=0.015000 Connect=Secondry/HCM89/SYSADM/
PSAPPSRV.4180 1-51934 23.26.14 0.000000 SamCreateSecondary ---- Successful obtain Second DB connection
PSAPPSRV.4180 1-51935 23.26.14 0.000000 Cur#2.4180.HCM89 RC=0 Dur=0.000000 COM Stmt=UPDATE PS_INSTALLATION SET EMPLID_LAST_EMPL = EMPLID_LAST_EMPL + 1
PSAPPSRV.4180 1-51936 23.26.14 0.028000 Cur#2.4180.HCM89 RC=0 Dur=0.028000 EXE
PSAPPSRV.4180 1-51937 23.26.14 0.000000 Cur#2.4180.HCM89 RC=0 Dur=0.000000 COM Stmt=SELECT EMPLID_LAST_EMPL FROM PS_INSTALLATION
PSAPPSRV.4180 1-51938 23.26.14 0.005000 Cur#2.4180.HCM89 RC=0 Dur=0.005000 EXE
PSAPPSRV.4180 1-51939 23.26.14 0.000000 Cur#2.4180.HCM89 RC=0 Dur=0.000000 Fetch
PSAPPSRV.4180 1-51940 23.26.14 0.002000 Cur#2.4180.HCM89 RC=0 Dur=0.002000 Commit
PSAPPSRV.4180 1-51941 23.26.14 0.000000 > GetNextNumberWithGapsCommit info ( INSTALLATION, EMPLID_LAST_EMPL, (null) )

This approach is certainly an improvement over the previous behaviour. It is similar to an Oracle Sequence without any caching which increments a value stored on SYS.SEQ$ in an autonomous transaction which it immediately commits without affecting the main transaction (except that Oracle does this in the same session, and here PeopleSoft have created a separate session).

Also, like an Oracle sequence, if the main transaction fails you are left with a gap in your numbers. Some of the dictionary definitions of the word sequence imply a fixed increment or decrement between values (usually 1). In some ways, it would be more helpful to think of this a way of generating a unique identifier rather than a sequence number.

By looking at v$session you can see that a second session is created for the same client process.

Session  Serial Program                          Client    Shadow
ID  Number Name                             Process   Proces
------- ------- -------------------------------- --------- ------
Client Info                                                 LOGON_TIME
----------------------------------------------------------- -------------------
147      35 PSAPPSRV.exe                     4180:7720 5824
PS,,GO-FASTER-4.london.go-faster.co.uk,HCM89,PSAPPSRV.exe,  23:08:40 18/06/2008

139     367 PSAPPSRV.exe                     4180:7720 5824
                                                  23:26:14 18/06/2008

The DbFlags field in the Application Server and Process Scheduler parameter filess controls how PSAPPSRV and PSAE in creates and terminates the secondary session.

;-------------------------------------------------------------------------
; DbFlags Bitfield
;
; Bit       Flag
; ---       ----
; 4         - Disable Second DB Connection
; 8         - Disable Persistent Secondary DB Connection
DbFlags=0

By default, the second session persists until the PSAPPSRV session terminates when either the application server is shut down or the PSAPPSRV process recycles when the number of services reaches the recycle_count specified in the application server configuration file.

Obviously, disabling the second database connection would effectively negate the advantages of this new functionality.

There is additional overhead to the second connection, and if DbFlags is set to 8 the secondary session would be shut down after the incremented sequence number has been returned. However, in a large, highly active system, where sequence numbers are requested frequently, this would lead to frequent creation of secondary sessions. The process of allocating new sequence numbers would also have to wait for the new session to be created.

Note, CLIENT_INFO is not set in the secondary session. However, it is possible to copy the CLIENT_INFO from the primary session using an ON LOGON trigger (which can also be dowloaded from the Go-Faster website).

REM second_client_info.sql
rem (c)Go-Faster Consultancy 2008

spool second_client_info

rem requires following privileges to be granted explicitly
GRANT EXECUTE ON sys.dbms_application_info TO sysadm;
GRANT SELECT  ON sys.v_$session TO sysadm;
GRANT SELECT  ON sys.v_$process TO sysadm;
GRANT SELECT  ON sys.v_$mystat  TO sysadm;

CREATE OR REPLACE TRIGGER sysadm.connect_secondary_session
AFTER LOGON
ON sysadm.schema
DECLARE
l_client_info VARCHAR2(64);
BEGIN
SELECT SUBSTR(p.client_info||'Secondary Session',1,64)
INTO   l_client_info
FROM   v$session p           --primary session
,      v$session s           --secondary session
WHERE  s.program = p.program --same program
AND    s.process = p.process --same process
AND    s.machine = p.machine --same machine
AND    s.user# = p.user#     --same user
AND    s.sid != p.sid        --different session
AND    s.client_info IS NULL --client info not already set
AND    s.sid = (SELECT m.sid
               FROM   v$mystat m
               WHERE  rownum = 1)
AND    p.logon_time < client_info="">l_client_info);
sys.dbms_application_info.set_action(action_name=>'Secondary Session');

EXCEPTION WHEN NO_DATA_FOUND THEN NULL;
END;
/

show errors

The result is that when the second session is created the trigger fires and copies the client info from the first session and appends the string ',Second'.

LOGON_TIME          Client Info
------------------- ----------------------------------------------------------------
21:44:37 26/06/2008 PS,,GO-FASTER-4.london.go-faster.co.uk,HCM89,PSAPPSRV.exe,
08:01:29 01/07/2008 PS,,GO-FASTER-4.london.go-faster.co.uk,HCM89,PSAPPSRV.exe,Second
…

Discrepancy in Timings between Application Engine and Oracle SQL Trace

I would like to draw attention to the risk of uncritically accepting performance information from either a tool or an instrumented program. It is always necessary to consider whether you can believe what you are being told, or whether something is lying to you.

In this case, I want to highlight in the Application Engine Timings report. Take the following example from Time and Labor. The AE Timings report claims that the process spends 91.5% of the execution time in SQL. This would lead you to believe that this process is affected by the performance of the SQL, and that you need to do some SQL performance tuning.

---------------------------------------------------------------------------------
Total run time                : 1411.6
Total time in application SQL : 1291.7   Percent time in application SQL :  91.5%
Total time in PeopleCode      :  119.4   Percent time in PeopleCode      :   8.5%
Total time in cache           :    0.1   Number of calls to cache        :     3
---------------------------------------------------------------------------------

However, all is not quite as it appears. Faced with a potential SQL problem, I usually turn to Oracle SQL Trace. The following is taken from a TKPROF analysis of the trace file for the same process.

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   153883      1.80       2.41          0          4          0           0
Execute 192806    429.94     464.96       8398     276000     588543      123140
Fetch    52740      2.75       3.55        590     202419          0       15265
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   399429    434.49     470.93       8988     478423     588543      138405

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
SQL*Net message to client                  196521        0.00          0.13
SQL*Net message from client                196521        0.32        849.98
...
SQL*Net more data to client                114884        0.00          1.91
SQL*Net more data from client              250825        0.05          1.88
...

The database reports 849.98s for the idle event SQL*Net message from client, and only 470.93s on non-idle activity. So only 36% of the total elapsed time is spent in the database, the other 64% is time that the Application Engine process is busy executing code.

Why the discrepancy?

This is certainly a very chatty process. There are nearly 200,000 round-trip SQL*net messages between AE and Oracle. It could be a network latency problem. However, very little time is spent on the SQL*Net more data events so it is unlikely that there is a significant network component.

Let's look at the statements that have the longest times in AE timing report .

                         PeopleSoft Application Engine Timings
                              (All timings in seconds)

                               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
------------------------------ ------- -------- ------- -------- ------- -------- --------
PeopleCode

DELETE PS_SCH_ADHOC_DTL                           36540     60.6       0      0.0     60.6
INSERT PS_SCH_ADHOC_DTL                           71887    885.6       0      0.0    885.6
Record.SelectByKey SCH_ADHOC_DTL                  36596    118.0   36596      0.0    118.0
                                                                                  --------
                                                                                    1291.7

In less than 24 minutes, some statement have been executed very frequently. So, there were lots of SQL*Net messages, because there were lots of SQL statements. These SQL statements are submitted from PeopleCode. It is very likely we are in some sort of procedural loop, and therein lies the problem.

PeopleSoft programs can only measure the time taken to execute SQL from the perspective of the client program. In this case the timings are calculated by instrumentation inside Application Engine and PeopleCode. Meanwhile, the timings in the Oracle trace are obtained from instrumentation within the Oracle kernel.

There is still a fair amount of code in PeopleSoft that executes during the time counted as execution of SQL Statements. This is not just the SQL*Net libraries. I think that the timings include most of the time it takes for sqlexec() and Row set functions to execute. The discrepancy with the Oracle time mounts with every SQL operation.

In this case, there is very little to be gained by tuning the SQL. We can't do much about the PeopleCode because it is delivered vanilla functionality. All we can do is to bring more CPU to bear upon the problem by running multiple concurrent instances of the process.