This section shows a simple example of how following the Strobe Performance Profile Interpretation Flowchart can lead to improvements in application performance. An application developer measured program B145000 and produced a Performance Profile. The excerpts are shown in this section.

The Strobe  Performance Profile leads you to the lines of code that are responsible for the increased run time. This case study demonstrates three opportunities for performance improvement. The section following the case study outlines possible opportunities for improvement not covered in the case study. Sample program and Strobe performance profile contains the source code for the case study program and the complete Performance Profile.

Valid performance profile?

The Performance Profile that results from measuring the sample program is called B145000. The first step in evaluating this Performance Profile is to examine the Measurement Session Data report to determine that the reports in the Profile reflect measurement of the intended job step with the intended parameters and that the information is statistically valid. With B145000, verify that these fields contain the correct or expected information.

Measurement Session Data Report (B145000)

In the JOB ENVIRONMENT section verify:

  • PROGRAM MEASURED is B145000
  • JOB NAME is B145000
  • JOB NUMBER is J0271289
  • STEP NAME is XSBTAPGM
  • CONDITION CODE, which is the return code, is C-0000. B145000 ran to completion and returned a return code of 0 to the operating system
  • SYSTEM and CPU MODEL are z/OS 2.4 and 8562-R06, the operating system and the machine model that support production jobs
  • SMF/SYSTEM ID is CW09/CW09, the system on which production jobs commonly run

In the MEASUREMENT PARAMETERS section verify:

  • ESTIMATED SESSION TIME is 1 minute (this is an estimate of the program’s run time)
  • TARGET SAMPLE SIZE is 100,000
  • REQUEST NUMBER (Q) indicates that the number of the request is 62, and the Q indicates that it was a queued request

In the MEASUREMENT STATISTICS section verify:

  • RUN MARGIN OF ERROR PCT, the margin of error for the percentages in the reports that detail run time, is less than or equal to 2.00, indicating that the information in the Performance Profile is statistically valid.
  • The CPU MARGIN OF ERROR PCT is 3.04% which, since it is under the ceiling value of 10, indicates that enough samples were taken to provide valid information in the reports that detail CPU time.

CPU or wait?

Note the following:

  • SESSION TIME, the amount of time the session ran, is 6.27 seconds.
  • EXEC TIME PERCENT is 22.85 and the WAIT TIME PERCENT is 77.15.
  • CPU TIME, the amount of CPU resources  Strobe observed the application using, is 2.21 seconds.
  • WAIT TIME, the amount of time Strobe observed the application waiting to use CPU resources, is 45 minutes and 4.47 seconds.

The actual session time of 6.27 seconds is shorter than the estimated session time of 1 minute. The majority of this time, 4.47 seconds, is waiting time. Because the application experiences a significant amount of wait time, it merits further investigation.

Knowing that you would like to reduce wait time, see the Strobe Performance Profile Interpretation Flowchart determine which report to examine.

What’s causing wait?

The flowchart indicates that to determine the cause of wait, the next report to examine is the Resource Demand Distribution report. 

Identifying demand for resources

On the Resource Demand Distribution report, .FILEMGT has the largest value in the CAUSING CPU WAIT column under PERCENT OF RUN TIME SPENT. This value is 38.16%. Strobe  groups under .FILEMGT all file processing activity that it does not relate to a specific ddname. In this situation, the Performance Profile indicates the code that is responsible for invoking the overhead routines. For a high percentage identified in .FILEMGT, the flowchart directs you to the Wait Time By Module report.

Resource Demand Distribution Report (B145000)

Identifying modules experiencing wait

The Wait Time by Module report lists the modules that Strobe found waiting for CPU resources. It shows that in module SVC 001 and in module SVC 020 the application was waiting a significant amount of time. The application was waiting in module SVC 001 30.83% of the time and in module SVC 020 27.80% of the time. The concentration of wait in these two routines tells you that in these supervisor call (SVC) routines, which are MVS system service routines, the application experiences the majority of wait time. See the Attribution of CPU Wait Time report to find the lines of source code that invoked these overhead routines.

Wait Time By Module Report (B145000)

Identifying callers of waiting modules

The Attribution of CPU Wait Time report shows that SVC 001 was invoked from B145000.  It was invoked at line 170 which is an OPEN procedure, at line 243, which is an OPEN procedure and at line 353 which is a CLOSE procedure.  SVC 020 was also invoked by B145000 at line 253 which is a close procedure.  Similarily, SVC 056 was invoked by B145000 at line 253. Because a high proportion of the wait for this application is caused by the execution at line 253 in B145000, this line of source code should be investigated.

Attribution of CPU Wait Time (B145000)

Examining the source code

The next step is to examine the related COBOL source code.  When B145000 needs to write a record procedure FORMAT-OUTPUT:

  • Opens the OUTFILE file
  • Writes the OUTFILE-RECD
  • Closes the OUTPUT file

The increase in wait time is incurred because FORMAT-OUTPUT is opening and closing the OUTFILE file for each invocation. Opening and closing OUTFILE repeatedly incurs an unacceptable amount of wait time.

Improving the source code

The correction to this problem is to invoke FORMAT-OUTPUT so as to minimize the number of COBOL open and close statements. You could change the code to open the file once at the beginning of the program and close it at the end. This method enables you to incur only one open and close and reduce the number of I/Os. Before correcting the code, however, look at the CPU opportunity that this Performance Profile presents.

What’s using CPU time?

Since the Performance Profile is valid, check to see if there is an opportunity to reduce CPU time. You may be able to reduce the 5 minutes and 35.50 seconds of CPU time shown on the Measurement Session Data report. To see what module is using CPU time, see the Program Section Usage Summary, as recommended in the Strobe Performance Profile Interpretation Flowchart.

Identifying CPU time consumption by program section

The Program Section Usage Summary report, identifies the amount of CPU time used by modules and control sections. The module B145000, which you are responsible for coding, used very little of the CPU time.  Strobe assigns most of the use of CPU time to the module .SYSTEM and to a section named .LELIB.  Strobe groups all system services under .SYSTEM. The section .LELIB within .SYSTEM used 54.57% of CPU time. Note that this section is distinguished by a large spike on the histogram. To further investigate CPU consumption, see the Program Usage by Procedure report.

Program Section Usage Summary Report (B145000)

Identifying CPU Time Consumption by Procedures

The Program Usage by Procedure report shows that CEEPLPKA used 54.47% of the CPU time.

Program Usage by Procedure Report (B145000)

With this information, see the Attribution of CPU Execution Time report to see what lines of application code are responsible for invoking Language Environment Services.

Attribution of CPU Execution Time Report (B145000)

Attributing CPU Execution Time

The Attribution of CPU Execution Time report shows that Language Environment Services (CEEPLPKA) was invoked by B145000 which is an ACCEPT statement.

Note that the Attribution of CPU Execution Time report is indexed; for the modules identified, it displays the source code line number and the procedure name in addition to the hexadecimal starting location and interval length. All indexed reports that show source code provide this information. For more information about indexed source Performance Profiles, see Indexed source performance profiles.

Identifying the Source Code

Strobe points to a new area than those you found when you followed the opportunity to reduce wait time. Strobe enables you to pinpoint those critical path lines of code that caused the application suddenly to become inefficient. It points to the ACCEPT statement where the program B145000 obtains the current date.

Changing the Source Code

The next step is to modify the source code. The statement ACCEPT WS-CURRENT-DATE FROM DATE is contained in FIND-ACCT-COST procedure.  The solution is to move the ACCEPT statement during initialization, rather than invoking it repeatedly.

Identifying CPU Consumption Related to Source Code

In this case study, the Program Section Usage Summary shows that module B145000 and section name B145000 used only a total of .96% of the CPU time. Strobe identifies the lines of code responsible for this CPU consumption. The source indexed Program Usage by Procedure report, identifies the line numbers, procedure names, and hexadecimal offsets for the responsible lines of code.

Example

Line 233 is an ACCEPT statement that used .38% of the CPU time.

Because this example does not show significant amounts of CPU resource use, you probably would not pursue the performance analysis here.

Program Usage By Procedure Report for Module (B145000)

Measure again with Strobe

The appropriate changes are made to B145000. However, we reference the results to B145000A, and evaluate the resulting Performance Profile. This Performance Profile shows the effects of your changes and may reveal opportunities to improve performance that were not apparent the first time you measured the program. You may find opportunities to reduce wait time even further.

The change to the application code dramatically reduced the wait time. On the Measurement Session Data report, the wait time for B145000A is .17 seconds which is a reduction of 4.3 seconds. Note also that the CPU time is less than .01 seconds which is a reduction of 1.32 seconds.

The WAIT TIME PERCENT value can increase even when the actual wait time experienced has decreased. For example, the WAIT TIME has decreased. The WAIT TIME PERCENT, has increased from 77.15 in B145000 to 98.39 in B145000A. This increase occurs because in B145000A, the percentage is a larger portion of a much smaller number.

The Measurement Session Data report for B15000A shows that there may be additional performance improvement opportunities.  The WAIT TIME PERCENT field shows 98.39% of the time the application is in a wait state.  Because the percentage of wait time is high, it merits investigation.

Measurement Session Data Report (B145000A)

Reviewing the Resource Demand Distribution Report

To investigate wait time further, see the Resource Demand Distribution report. In the Resource Demand Distribution report, the PERCENT OF RUN TIME SPENT in the CAUSING CPU WAIT column shows that ddname INFILE is experiencing a high degree of wait time. INFILE is causing CPU to wait 42.74% of the time. As the Performance Profile Interpretation Flowchart indicates, see the Data Set Characteristics report to see how the files are defined.

Resource Demand Distribution Report (B145000A)

Reviewing the Data Set Characteristics Report

The Data Set Characteristics report, shows the characteristics of the file in which you are interested. Note that INFILE is a VSAM key sequenced data set with a data component (identified by KSDS in the ACCESS METHOD column) and an index component (identified by INDX in the ACCESS METHOD column).

Review the information on the Data Set Characteristics report. Notice the following:

  • The block size or CI size (BLK/CI SIZE)
  • The number of blocks transferred (EXCP COUNTS)
  • The number of buffers (BUF NO) for the data and index portions for VSAM
  • The POOL NO field is blank, indicating that the VSAM file uses non-shared resources.

Data Set Characteristics Report (B145000A)

QSAM Blocking and Buffering

For the QSAM file ACCTFILE, note the record size and block size on the Data Set Characteristics report. The record size is 100 and the block size is 100.

You may be able to improve performance by increasing the block size of the file to the largest possible for the DASD or tape you are using. With a larger block size, the program will perform fewer reads and writes.

Reviewing the data set characteristics supplement report

To further investigate VSAM buffering, see the Data Set Characteristics Supplement report. This report shows the OPEN INTENT\PROCESSING MODE, which indicates whether the application opens files for input, output, or both. For VSAM files, it also shows whether the records are processed sequentially or directly (randomly) and provides the number of CIs (control intervals) in a CA (control area).

VSAM Blocking and Buffering

Review the JCL to be more efficient with buffer usage. Review the Data Set Characteristics report for the number of buffers used.

Data Set Characteristics Supplement Report (B145000A)

Changing the Application

Following is an example of JCL changes to improve file performance. To change the block size in the QSAM file and to change the number of index buffers in the VSAM cluster, the application’s original job control language (JCL) statements needed to be changed. The original and modified JCL statements for program PAYROLL1 are shown with the changed lines indicated with change bars.

Original and Modified JCL Statements

Measure to Verify the Effects of the Changes

After making the changes to the QSAM and VSAM files, measure again with  Strobe  to validate expected performance improvements.