Understanding Trace Results

This section discusses:

Trace file sections.
Step traces.
SQL traces.
Statement timings traces.
Database optimizer traces.

At the top of each trace, useful information helps you to identify the PeopleTools version, the database name, and the database platform type.

SQL Counts and Timings Section

The first section of a trace file is the SQL section. It records the performance of application-specific SQL. The trace values appear within a series of columns and sections. The following table describes each column within the first section of the trace file:

Column	Description
SQL Statement	Application Engine SQL actions and stored SQL objects always have a statement ID. The SQL Statement column shows the statement ID so that you can attribute trace values to individual SQL statements. In the case of SQLExec SQL, a portion of the SQL statement appears in the first column to help you identify it. For SQL objects, use the TraceName property in the Create SQL so that you can uniquely identify it in the traces.
Compile Column	This column shows how many times the system compiled a SQL statement and how long the compilation took. The term compiled refers to the SQL statement being sent to the database to be parsed and optimized, and it also includes the time required for the first resolution of any PeopleSoft meta-SQL.
Execute Column	This column shows how many times the system executed the SQL statement and the time consumed doing so. The term executed refers to the system sending the compiled SQL to the database server to be run against the database.
Fetch Column	This column applies to Select statements. It shows how many rows your program fetched from the database and how much time this consumed. The system must first execute a Select statement against the database to find the relevant rows and generate an active set. After the set exists, the program must still fetch the rows. Some database APIs have buffered fetches, which means that the fetch may include more than one row. Therefore, subsequent fetches are free until the buffer becomes empty.
Total Column	This column shows the sum of the compile, execute, and fetch times of the SQL statement. Some database application programming interfaces (APIs may defer a compile to the execute phase or defer an execute to the first fetch operation.
PeopleCode SQL	This subsection is for SQL run from PeopleCode actions. Compile counts and times for such SQL is included in execute count and times because you do not explicitly control the ReUse feature. To determine whether ReUse is occurring, you must do a program run after enabling the generic PeopleTools trace for SQL statements, API calls, and so on. As a starting point, use a trace value of 31.
Application Engine SQL	This subsection reveals the time attributed to Application Engine overhead that is not directly related to the SQL within your program. For example, the values in this section represent the SQL generated for checkpoints, commits, and so on. If there are Commit statements without checkpoints, it indicates that restart has been disabled, or a restartable program has called a non-restartable program. If the time consumed performing a checkpoint or committing seems more than expected, you should try to reduce it if possible by setting the commit frequency of the steps containing Do loops.
AE Program: `program_name`	This subsection shows SQL actions for a particular program. The action properties that affect performance are flagged. For example, BulkInsert. ReUse is not flagged because it is self-evident when the Execute count is higher than the compile count.

Note: When you run a SQL trace at the Application Engine level and the PeopleTools level simultaneously, you may see misleading results. Extra overhead is added to the overall SQL timings by the PeopleTools trace. Tracing SQL at the Application Engine level (-TRACE) adds to the non-SQL times because PeopleTools writes the trace data after timing the SQL.

PeopleCode Actions Section

The second section of the trace file, or PeopleCode section, records the performance associated with all the PeopleCode actions in your program. The following table describes each column in this section:

Column	Description
PeopleCode	The names of the PeopleCode actions in your program.
Call	How many times each PeopleCode action is called during a program run.
Non-SQL	The time spent running non-SQL actions.
SQL	Time spent running SQL. The total SQL time should be similar to that of the PeopleCode SQL subsection in the first section of the trace file.
Total	The cumulative amount of time spent on an action.

Note: The system rounds to the first decimal place (tenths), but only after it calculates the sum of each action time.

PeopleCode Built-ins and Methods Section

The third section of the trace file contains either a list or summary of the PeopleCode built-ins and methods used. To see a list of built-ins and methods, you must enable the PeopleCode detail timings in addition to the statement timings trace.

If a method or built-in function takes a large amount of time, you may want to consider alternatives. For example, if array processing dominates your runtime, consider inserting the data into temporary tables and performing the processing on tables in the database.

Summary Data

The fourth section of the trace file contains summary data. The values in this section provide an overview of the program run without providing too many details.

The following table describes the values that appear in this section:

Column	Description
Total run time	The overall amount of time a program required to complete from start to finish.
Time in application SQL	The time that your program spent executing SQL. This value includes SQL run by both PeopleCode and SQL actions.
Percent time in application SQL	The percentage of time spent running SQL compared to the entire program run.
Time in PeopleCode	The time the program spent running PeopleCode. Time in PeopleCode excludes SQL run from within PeopleCode.
Percent time in PeopleCode	The percentage of time spent running PeopleCode compared to the entire program run.
Total time in Cache	The amount of time the program spent retrieving objects from the cache or refreshing the cache. Total time in cache includes all memory cache access, file cache access, and SQL run to load managed objects such as Application Engine program components, metadata, and so on. Time varies according to where Application Engine finds an object. For instance, retrieving an object that the system cached during a previous run is faster than retrieving it from the database.
Number of calls to Cache	The actual number of calls the program made to the cache. The number of calls to the cache remains constant for the same Application Engine program processing the same data.

Environment Information Section

The fifth section of the trace file contains environment information specific to Application Engine. If programs appear to be performing poorly, check the trace value that you set.

Each trace produces an unavoidable degree of overhead. As a result, the more traces you have enabled, the more likely you are to see degraded performance. Run only the traces you need. This section of the trace file shows information about:

SQL traces.
PeopleCode traces.
Application Engine traces.
Application Engine DbFlags (%UpdateStats).

A step trace reports each step name that your program runs and the order it runs in. Associated with each step is a timestamp, a Do action level, and an action type.

The trace shows the steps that run within a called section by indented formatting. For example, a step that runs within a called section is preceded by two dots (..), while other steps are preceded by only one dot (.).

The SQL trace report shows formatted SQL processes, including commits, rollbacks, and restarts. You can also view the buffers associated with each SQL statement. Use a SQL trace to spot errors in your SQL and to view your commit strategy.

The Application Engine statement timing trace report is similar to a COBOL timings trace in which you monitor COBOL programs to evaluate performance. This trace enables you to gather performance information to determine where program performance slows down. After you identify these spots, you might be able to modify your program to run more efficiently, or you might want to change the database schema and configuration to optimize program performance.

The statement timings trace is invaluable for tuning an Application Engine program. It may also be useful as a default trace level for all production runs to provide a metric for long-term performance trends.

By examining all of the figures in this trace, you can identify areas of your program that are not running as efficiently as possible. For instance, if compile counts are high, you can reduce the numbers by using the Application Engine reuse feature. If inserts appear to be running slow and you have many of them, you can increase performance by using the Application Engine bulk insert feature. Each value in the trace, including cumulative totals, is rounded to the nearest tenth of a second, but totals are calculated using nonrounded timings.

You can write this trace to a file or you can write the results to tables. Either way, timings trace overhead is minimal. Internal testing reveals that the Application Engine trace has an overhead between 2 percent and 5 percent of total runtime.

By storing timings information in a table, you can store historical data in the database, which enables you to produce reports that help with trend analysis, allow ad hoc SQL queries for longest running statements, and so on. By storing timings data in the database, you can manipulate and customize reports to show only the metrics in which you are most interested.

You can use third-party tools to query and present the data as detailed graphical representations of program performance. You can also implement alarms if the performance of a program reaches a specified maximum value in a particular area, such as SQL compile time.

Note: Application Engine does not write the timings trace to a table for programs invoked by the CallAppEngine PeopleCode function. To write to a table, a process instance is required, and programs invoked by CallAppEngine are not assigned a process instance.

The Statements Timings (table) option, or 1024 -TRACE option, populates the following tables.

PS_BAT_TIMINGS_LOG (Parent)

This table stores general information about a program run.
PS_BAT_TIMINGS_DTL (Child)

This table stores detailed information about a program run, such as the execute count, fetch time, and so on.

The SQL Timings (table) option, or the 16834 -TRACE option, populates the following tables.

PS_AE_TIMINGS_LG (Parent)
This table stores general information about a program run.
PS_AE_TIMINGS_DT (Child)

This table stores detailed information about a program run, such as the execute count, fetch time, and so on.

PS_BAT_TIMINGS_FN

This table stores PeopleCode detailed timing information.

PeopleSoft software provides BATTIMES.SQR as an example of the type of reports you can generate to reflect the information stored in the BAT_TIMINGS tables. You can produce a summary report for all the programs for a specific run control ID, or you can get detailed data for a specific process instance.

To invoke the BATTIMES.SQR report through PeopleSoft Process Scheduler:

Select PeopleTools, Process Scheduler, Batch Timings.
The Batch Timings page appears.
From the Report Type drop-down list, selectDetail orSummary.
In the Batch Timings For group box, enter the run control ID for summary reports and enter the process instance for detail reports.
When you have made the appropriate selections, click the Run button.

To view batch timings using Process Monitor:

Select PeopleTools, Process Scheduler, Process Monitor.
Locate the program run associated with the current trace.
Click the Job Details button.
In the Process Detail dialog box, click the Batch Timings link.
PeopleCode detail timings do not appear; they appear only in the file format.

The database optimizer trace provides the execution or query plan for the SQL that your Application Engine program generates. Each SQL statement is traced only once. You can write the trace to a file or a table.

How you view the results of this trace depends on the relational database management system (RDBMS) that you are currently using. For instance, on some platforms only the trace-to-file option is available, whereas on others only the trace-to-table option is available. The following table shows the options available for each of the supported platforms:

RDBMS	Output
Oracle	File and table
DB2 for OS/390	Table
DB2 for UDB (AIX, Sun Solaris, Microsoft Windows NT)	Table
Microsoft SQL Server	File and table

Note: PeopleTools applications do not collect optimizer data for SQL originating from PeopleCode actions unless you run Oracle and use file output. In this case, the system traces all SQL that runs after the first SQL action runs.

Oracle

When sending the trace to a file, Application Engine writes the trace file to the default Oracle trace directory specified on the database server. To read the trace file, use the TKPROF utility.

To send the trace to a table on Oracle, a PLAN_TABLE table must exist and the statement_id must be of type VarChar2(254) instead of VarChar2(30).

When sending to a table, the PeopleSoft application updates the trace rows as follows:

For the EXPLAIN PLAN SET STATEMENT_ID, PeopleSoft software updates the STATEMENT ID column:
```
EXPLAIN PLAN SET STATEMENT_ID = ApplId.Section.Step.Type FOR sqlstmt
```
or the PLAN_TABLE REMARKS column, PeopleSoft software updates the REMARKS column:
```
PLAN_TABLE‘s REMARKS column = ‘ProcessInstance-RunControlId(QueryNo)’ 
```
Where queryno is a count of how many SQL statements have been traced up to a particular point.

Note: When tracing to a table with Oracle, PeopleSoft software does not perform optimizer traces on %UpdateStats and %TruncateTable unless the latter resolves into a Delete statement. Alternatively, sending the Oracle TKPROF utility to a file handles both the Analyze and Truncate commands.

Microsoft SQL Server

When you send trace output to a file, Application Engine writes the optimizer trace to the following location: %TEMP%\psms<queueid><spid>.trc. To read the trace, use the SQL Server Profiler utility.

Note: The system writes the trace file to the server directory when you specify the trace on the client. If the client has %Temp% set to a drive or directory that does not exist on the server, then Application Engine does not generate a trace file.

When you send trace output to a table, Application Engine writes the trace data to the dbo.PS_OPTIMIZER_TRC table. PeopleTools creates the table automatically when you run the trace for the first time. The trace data written to the table is identical to the data that appears in the optimizer trace file.

You use the SQL Server Profiler utility to view the optimizer results. To view the populated trace table, specify the current server and database in the Source Table dialog box. The Owner value must bedbo, and theTable value must bePS_OPTIMIZER_TRC.

In the trace, you find information about text, duration, and start time for:

Execution plans.
Remote procedure calls.
Insert statements (Update, Delete, and Select statements).
PeopleSoft-generated user events that associate trace data with a PeopleSoft SQL identifier.

If the Application Engine program terminates while you are using the trace option, verify that Application Engine was not tracing a SQL statement at the moment the program terminated. If it was tracing a SQL statement at that time, you must manually stop the trace. Otherwise, the trace thread on the server continues to run and will lock the trace file, and each time that server process ID (SPID) is reused by the server, new information will be appended to the locked trace file.

To stop the trace manually, submit the following command from Query Analyzer:

xp_trace_destroyqueue queueid

The queueid variable in the file name %TEMP%\psms_queueid_spid.trc is the ID that corresponds to the queue used for the first SQL statement that the system profiled. Because this trace is only designed to trace Application Engine SQL (not PeopleTools SQL), the queue is closed after every statement profiled. Therefore, the queue that must be destroyed may not be the queue ID used in the trace file.

Note: If the %TEMP% variable is set to a location that does not exist, Application Engine does not generate a trace file.

DB2 for OS/390

For DB2 for OS/390, you can only send the optimizer trace to a table. To facilitate this trace:

The PeopleSoft application selects the maximum query number from the PLAN_TABLE table, increments it by 1000 to avoid clashing with other processes, and then increments it by 1 for every SQL statement traced.
The PeopleSoft application sets the SET REMARKS parameter to this value: ApplId.Section.Step.Type-RunControlId(ProcessInstance)

Note: Before using the Database Optimizer Trace, you must first create a DB2 PLAN_TABLE. Refer to your DB2 UDB for OS/390 and z/OS Administration Guide for the correct format and instructions for creating the PLAN_TABLE.

DB2 for UNIX

For DB2 for UNIX, you can only send the optimizer trace to a table. To facilitate this trace, we implemented:

EXPLAIN ALL SET QUERYNO =ProcessInstance SET QUERYTAG = 'Section.Step' FOR sql stmt

Note: Before using the Database Optimizer Trace, you must first create the DB2 explain tables.

Database Optimizer Trace and Performance

While the database optimizer trace is enabled, performance may be affected. Typically, you turn on this trace only when you are collecting detailed performance metrics. When you are not tuning system performance, turn off the optimizer trace.

To prevent an administrator or perhaps a user from unwittingly turning the optimizer trace on or leaving it on after doing performance tuning, you can disable the database optimizer trace for an entire database.

For example, if you have a production database and a development database, you might want to enable the optimizer trace for the development database but disable it for the production database.

On the PeopleTools Options page, clear the Allow DB Optimizer Trace option to disable the optimizer trace for a database.

Understanding Trace Results

Trace File Sections