2

Understanding PeopleSoft Trace File for Performance Tuning

Making sense of a PeopleSoft trace file is absolutely essential for resolution of performance issue(s). You may face an issue where users are complaining of slow performance and OEM is not capturing the SQL – you have two options: Find the SQL using PeopleSoft trace or enable a database trace.

You should first try to do PeopleSoft trace. Also, you need to understand what all is in the trace without getting confused. A utility you can use to examine the trace file is TraceMagic. Click Here for details of TraceMagic.

Below is how you would read a trace file to identify performance bottleneck SQLs and then take them for further evaluation.

This trace is for PeopleTools 8.5x

PSAPPSRV.8972 (706)      1-19753  10.45.11    0.000000 Cur#1.8972.ELM91DEV RC=0 Dur=0.000000 COM Stmt=SELECT FILL.LM_GRADE_VAL_ID,FILL.LM_GRADE_LABEL FROM PS_LM_GRD_SCH_VW FILL

Understanding the PeopleSoft Trace:

Here’s how to understand the trace. Lets look at this trace line. The part of the trace file we’re concerned with is:

1-19753  10.45.11    0.000000 Cur#1.8972.ELM91DEV RC=0 Dur=0.000313 COM Stmt=SELECT FILL.LM_GRADE_VAL_ID,FILL.LM_GRADE_LABEL FROM PS_LM_GRD_SCH_VW FILL

First column =1-19753. This is the sequential line counter for that process (exe). Next line will have the incremental number.

Second column = 10.45.11. It is the timestamp at which the trace line is written. This timestamp comes from the machine in which PeopleTools is running and is not the database timestamp.

Third column = 0.000000. It is the time that has elapsed since the previous trace line was written. This means that line 1-19753 was written 0.000000 seconds after line 1-19752. This time will be explained in more detail.

Fourth column = Cur#1. This is the cursor number for the statement. If you open a second cursor it will have a cursor number > 1.

Fifth column = ELM91DEV. The PeopleSoft database in which this API call is executing.

Sixth column = RC=0. This is the return code for the associated API call.

Seventh column = Dur=0.000313. This is the time to execute the assoicated API call. Depending on what the call is this might be the time to execute the statement. This will be explained in more detail.

Eight column = COM Stmt=SELECT FILL.LM_GRADE_VAL_ID,FILL.LM_GRADE_LABEL FROM PS_LM_GRD_SCH_VW FILL …. This is the database API call.

Understanding the trace timers is absolutely essential to resolving the performance issues. There are two main timers to understand.

Dur=0.000313. This represents the time for the API associated with the SQL statement to run. In other words, this could be the time to Prepare or Execute etc. This is the time parameter you would be looking for while trying to resolve a performance issue. Many a times, the value of this parameter would be the same as CPU.

Third column = 0.000000. To reiterate from above, this is the time since the previous trace line was written. So this time could represent any of the following:

• User Think Time – If the value here is very large than most likely this time is User Think Time. If the line prior to this line is a Disconnect, Commit or a Rollback then there is a very good chance that this time is User Think Time. If this is the case then, a large value here should be of no worry.
• PeopleTools processing – This would be for an activity that did not result in a Trace line being written. This might be PeopleCode (providing the PeopleCode trace was NOT turned on), this could be Panel Processor, this could be PeopleTools waiting for a Remote Call (a COBOL process which runs as a whole separate process) to complete, etc. A large value due to one of these reasons is something that should definitely looked into.
• SQL – Time This includes (is a superset) the SQL time Manager Information trace