Performance Metrics and XML Reporting in PeopleSoft

I am working with a PeopleSoft system that makes extensive use of XML Publisher reporting.  Generally these reports are based on SQL queries that are defined in the PeopleSoft PS/Query utility. 

These queries are run by an Application Engine program PSXPQRYRPT that runs the SQL query and produces the report in a single process.  This is a generic application engine program that runs any XML report.  Line 45 (in PeopleTools 8.49) of step MAIN.ExecRPT executes the report with the ProcessReport PeopleCode command.

&oRptDefn.ProcessReport(&TemplateId, &Languaged, &AsOfDate, &oRptDefn.GetOutDestFormatString(&OutDestFormat));

Batch Timings
Analysis of the Application Engine batch timings indicate that nearly all the time in this Application Engine program is spent in PeopleCode, and that this not SQL execution time.  This is misleading.  The ProcessReport command is PeopleCode, but behind the scenes it also issues the SQL in the report data source.  Not all the time is SQL, but the Application Engine Batch Timings does not count any of this as SQL because it is not in the PeopleCode SQL Class. 

Let’s look at an example Batch Timings report (I have edited it down, removing zero and insignificant timings).

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
Record.SelectByKey PSDBFIELD                          8      0.1       8      0.0      0.1
SELECT PSPRCSRQST                                     2      0.1       2      0.0      0.1
SELECT PSXPTMPLDEFN                                   3      0.1       3      0.0      0.1
                                                                                  --------
                                                                                       0.3
AE Program: PSXPQRYRPT
MAIN.ExecRpt.H                       1      0.0       1      0.0       1      0.0      0.0
                                                                                  --------
                                                                                       0.0
------------------------------------------------------------------------------------------
                               Call    Non-SQL  SQL      Total   
PeopleCode                     Count   Time     Time     Time    
------------------------------ ------- -------- -------- --------
AE Program: PSXPQRYRPT
MAIN.ExecRpt                         1    643.2      0.3    643.5
                                       -------- -------- --------
                                          643.2      0.3    643.5
------------------------------------------------------------------------------------------
                                                        E x e c u t e   
PEOPLECODE Builtin/Method                               Count   Time    
------------------------------------------------------- ------- --------
Boolean(Type 5) BuiltIns                                     90      0.1
DateTime(Type 11) BuiltIns                                    1      0.1
SQL(Type 524290) Methods                                     19      0.1
SQL(Type 524290) BuiltIns                                     9      0.1
Record(Type 524291) Methods                                1104      0.1
Session(Type 524303) Methods                                207    633.2
JavaObject(Type 524315) BuiltIns                              6      2.2
PostReport(Type 524324) Methods                               2      0.7
------------------------------------------------------------------------------------------
Total run time                :      644.0
Total time in application SQL :        0.3   Percent time in application SQL :        0.0%
Total time in PeopleCode      :      643.2   Percent time in PeopleCode      :       99.9%
------------------------------------------------------------------------------------------

• The total execution time of is 644 seconds.
• 643.2s are reported as being in PeopleCode, and as coming from the MAIN.ExecRpt step.
• Only 0.3s of that is SQL time, and that comes from PeopleCode functions in the SQL Class  (CreateRecord , CreateSQL etc.)
• The ProcessReport method does not appear in the PeopleCode SQL analysis section of the report, because it is not classed as SQL.

Identifying the Report ID and Report Source
So, the next question is how can I find out which report this process is running.  Different instances of this report may be running different queries.

You can get the list files generated by a process from the Content Management PeopleTools table PS_CDM_FILE_LIST.  Application Engine processes usually produce various log files (with extensions .aet, .trc and .log), the name of the other file is the same as the name of the report followed by an extension that will vary depending on format.

You can look at the report definition on-line under Reporting Tools -> XML Publisher -> Report Definition, and that will show you the Data Source ID

The Data Source is defined in a component accessible from the previous entry in the same menu.

Analysing Execution Times
I have written this query to aggregate execution time for PSXPQRYRPT by output file name. 

• PSPRCSRQST is the process request table, from which I get the run time of the process.
• PS_CDM_FILE_LIST lists the files generated by the process which would be posted to the Report Repository. If I exclude the usual trace files, I am left with the report ID.
• PSXPRPTDEFN is the report definition record, from which I can get the data source ID
• PSXPDATSRC specifies the data source.  A data source type (DS_TYPE) of QRY indicates a PeopleSoft PS/Query.  If it is a private query, the OPRID will have a value.

column report_defn_id heading 'Report ID'      format a12 
column ds_type        heading 'Type'           format a4 
column ds_id          heading 'Data Source ID' format a30 
column oprid          heading 'Owner'          format a10 
column processes      heading 'Prcs'           format 990 
column reprots        heading 'Reps'           format 9,990 
column secs           heading 'Total|Seconds'  format 999,990 
column median         heading 'Median|Seconds' format 999,990 
column variance       heading 'Variance'       format 9990.0
SELECT d.report_defn_id, d.ds_type, d.ds_id, d.oprid 
,      SUM(y.processes) processes
,      SUM(y.reports) reports
,      SUM(y.secs) secs
,      median(y.secs) median
,      variance(y.secs) variance
FROM (
 SELECT x.prcsinstance
 ,      x.filename
 ,      COUNT(DISTINCT x.prcsinstance) processes
 ,      COUNT(*) reports
 ,      SUM(x.secs) secs
 FROM   (
  SELECT r.prcsinstance
  ,      f.filename
  ,      86400*(r.enddttm-r.begindttm)*ratio_to_report(1) over (partition by r.prcsinstance) secs
  FROM   sysadm.psprcsrqst r
  ,      sysadm.ps_cdm_file_list f
  WHERE  r.prcsname = 'PSXPQRYRPT'
  AND    r.prcsinstance = f.prcsinstance
  AND    NOT f.cdm_file_type IN('AET','TRC','LOG')
  AND    r.begindttm >= TRUNC(SYSDATE)
  ) x
 GROUP BY x.prcsinstance, x.filename
 ) y
,      sysadm.psxprptdefn d
WHERE  d.report_defn_id = SUBSTR(y.filename,1,instr(y.filename,'.')-1)
GROUP BY d.report_defn_id, d.ds_type, d.ds_id, d.oprid 
ORDER BY secs DESC
/

I can now see which report process has been executed run how many times, how many copies of the report have been produced, and where the processing time is being spent, and so which one I should look at first.

Total   Median
Report ID    Type Data Source ID                 Owner      Prcs   Reps  Seconds  Seconds Variance
------------ ---- ------------------------------ ---------- ---- ------ -------- -------- --------
XXX_WK_LATE  QRY  XXX_WKLY_LATENESS_RPT                       20     20    2,973      148   3702.9
XXX_HRAM_CON QRY  XXX_HRPD_CNT_AMD_RPT_QRY                    92     92    2,677       27    108.4
XXX_CKOUT_RP QRY  XXX_CHECKOUT_REPORT                         47     47    2,043       41    347.7
XXX_BNK_RPT  QRY  XXX_BNK_DTLS_SCH_QRY                         1     75      141      141      0.0
…

Conclusion

If you have a SQL performance problem with an XML report because the source PS/Query performs poorly, the batch timings will lead you to believe that you have a PeopleCode problem and not a SQL problem. 

Beware, this may not be the case.

Most of the execution time for XML Reports sourced from PS/Queries is almost certain to be SQL execution time.  The above query will tell you which queries are consuming how much time, and so inform your tuning effort.