Greenfield Technologies

Your Progress OpenEdge Database Expert

Investigating Suspicious Progress 4GL Code

From PROGRESSIONS #49 Spring 2002

Overview

This article will discuss several tools that can be used to make better decisions about application performance. The sample code is intended to be used with a simple ChUI application - that keeps it simple and compact. To use this code with a ChUI application you need to have something similar to the following in your applhelp.p file:

            
	if keylabel(lastkey) = "CTRL-F" then
	  run "tools/lrinfo.p".
	 else if keylabel(lastkey) = "CTRL-N" then
	  run "profiler/profctrl.p".

and a corresponding:

	on CTRL-F help.
	on CTRL-N help.

in your startup program. The sample code runs against the "sports" database. For a GUI or Web environment use the controls of your choice to run these programs and modify their UI to your taste.

The lrinfo.p procedure and code referenced by CTRL-N can be downloaded from: profv9.tar

Using Control-F

The CTRL-F function is used to measure, in terms of logical IO operations, the overall impact of a series of interactive tasks. You can use this function in the following manner:

Position yourself on the screen just prior to the start of poor performance.

Type CTRL-F. This "primes the pump" by initializing the measurement of logical IO operations. You'll see the total number of logical IO ops that have been performed so far in this session displayed.

Continue normal execution of the function being investigated. It is best if a repeatable, scripted process is used here. Make note of the number of items presented or processed - this will be important later (this should be the same every time.)

At the end of the function being investigated type CTRL-F again. This displays the logical IO operations executed in the interval being investigated. This is calculated as the difference between the current total value and the value displayed the last time CTRL-F was pressed.

Consider the amount of work represented by the items presented (or processed) by this function. For instance -- if 20 orders were displayed and order summarized data from 5 order-line records it would be reasonable to think that 120 record reads would have been required to obtain that data. More complex cases might require a detailed analysis of the function being investigated - the point is to make an estimate of the number of records that contribute in a meaningful manner to the eventual purpose of the function. You're looking for a significant discrepancy between the logical IO operations executed by the database engine and the number of records that the 4gl client was able to work with.

In a perfect world the ratio of logical IO requests to contributing records should be 2:1. (There is 1 index block and 1 data block read required for every record read) so you should expect that about 240 logical IO operations should have been required to perform this function.

Ratios between 2:1 and 10:1 may not be worth pursuing - that's a judgment call that you'll have to make. One thing to consider is that it can be very difficult to obtain "4gl visible" record counts that are accurate enough to base that decision on. You may need to carefully inspect the code in question or even insert counters into the code to determine the actual number of "4gl visible" records - there is no way to obtain this data via a VST or other similar automated task.

If your ratio is close to 2:1 and the function is still "too slow" the cause may still be the amount of data being manipulated - sometimes you just have to work with millions of records. If that is the case then there are very few choices available to you:

• Get faster hardware - in particular a faster CPU. The query will scale up with the clock speed (there are other factors which may result in even larger improvements.) More CPUs will not help significantly - only faster clock speeds will address this problem.
• Do less work. Find a way to obtain the same result without reading the same number of records - in particular if summary data is involved try de-normalizing and spreading the summarization process out over time as the detail records are updated.
• Find a way to parallelize the work load. This will help the most if there is a significant non-database component involved.

Using Control-N

The CTRL-N function is used to profile the specific performance of each line of code in a series of interactive tasks. (In many, some would say nearly all, cases it is going to point to a database query as the culprit.) You can use this function in the following manner:

Position yourself on the screen just prior to the start of poor performance.

Type CTRL-N & change the "On" value to "On". Enter a comment and temp-file name if desired.

Continue normal execution of the function being investigated. As above, it is best if a repeatable, scripted process is used here.

At the end of the function being investigated type CTRL-N again. Turn off the profiler. This displays the profiling data for the code executed in the interval being investigated. A report file will be created on disk.

Description: profile 7
Date: 11/14/01
Top Average Time lines

Program                                   Line      Avg Time          Time      Calls
---------------------------------------- ----- ------------- ------------- ----------
examples/t4.p                                7      0.008912      0.008912          1
examples/t.p                                47      0.007228      0.028913          4
profiler/profctrl.p                         87      0.004088      0.004088          1
examples/t.p                                45      0.001669      0.005007          3
examples/t2.p                               14      0.001136      0.001136          1
examples/t.p                                43      0.000891      0.003565          4
examples/t3.p                                7      0.000670      0.000670          1
examples/t2.p                               17      0.000273      0.000273          1
profiler/proffunc.p                         93      0.000225      0.000225          1
examples/t.p                                42      0.000203      0.000810          4
profiler/profctrl.p                         94      0.000072      0.000072          1
profiler/proffunc.p                         91      0.000069      0.000069          1
examples/t2.p                               15      0.000068      0.000068          1
profiler/proffunc.p                         95      0.000067      0.000067          1
profiler/proffunc.p                         94      0.000066      0.000066          1
profiler/profctrl.p                         93      0.000066      0.000066          1
profiler/proffunc.p                         76      0.000066      0.000066          1
examples/t2.p                               10      0.000065      0.064974      1,001
profiler/profctrl.p                         95      0.000060      0.000060          1
applhelp.p                                   1      0.000052      0.000052          1
profiler/profctrl.p                         97      0.000049      0.000049          1
profiler/proffunc.p                        100      0.000049      0.000049          1
examples/t.p                                40      0.000041      0.000122          3
profiler/proffunc.p                         92      0.000036      0.000072          2
examples/t2.p                               19      0.000032      0.000032          1
profiler/proffunc.p                        108      0.000029      0.000029          1
examples/t1.p                                7      0.000029      0.000029          1
examples/t2.p                               11      0.000027      0.027302      1,000
examples/t3.p                                9      0.000027      0.000027          1
examples/t4.p                                9      0.000025      0.000025          1
profiler/proffunc.p                        109      0.000023      0.000023          1
applhelp.p                                   3      0.000023      0.000023          1
profiler/proffunc.p                        119      0.000018      0.000018          1
profiler/proffunc.p                         98      0.000016      0.000016          1
profiler/profctrl.p                        100      0.000015      0.000015          1
examples/t.p                                49      0.000014      0.000054          4
profiler/profctrl.p                         98      0.000012      0.000012          1
profiler/proffunc.p                        107      0.000009      0.000009          1
examples/t2.p                               12      0.000008      0.008478      1,000

The profiling data is sorted by the line with the highest total runtime. Average runtime and number of times run for each line of code that is executed is also shown and may be more interesting depending on the situation. The line numbers shown are relative to the DEBUG-LIST line numbers. You will need to compile programs that you'd like to examine like so:

compile
   dir/program.p
   debug-list tmp/program.dbg

in order to obtain the needed listing file.

It is possible to use both CTRL-F and CTRL-N at the same time. It is probably best to use "f" and then "n" in order to minimize the amount of extraneous data reported by the profiler.

Used together these two tools can help narrow down the problem area and provide the raw material for the lrtest.p tool.

Obtaining a Baseline

When a function has been identified as being slow the first task is to obtain a stable baseline to work against. With a stable and repeatable baseline you can isolate the problem and demonstrate that your proposed changes will, in fact, address the issue. To this end it is important to attempt to duplicate the problem in a "Test" or "QA" environment - this environment should be a recent copy of production data and, as such, should closely mirror the performance characteristics of the production database.

Using LRTEST.P

The CTRL-F and CTRL-N tools should point to a specific query that is a candidate for improvement. Use LRTEST.P to separate that query from its surrounding code base and form a test bed. You can the use this test bed to first verify that the ratios are, in fact, out of balance. Use the variable "i" to count the records returned by the query. ("Query" is used loosely here to refer to any block of code that reads lots of records - it could be a stand-alone FIND statement, a simple FOR EACH, a FOR EACH with multiple tables, a GET or a nested combination of these statements.)

/* lrtest.p
 *
 * testbed for counting logical reads
 *
 */

define variable i  as integer no-undo format ">>>,>>>,>>9".
define variable lr as integer no-undo format ">>>,>>>,>>9".

find _myconnection no-lock.

find _userio no-lock where
  _userio._userio-usr = _myconnection._myconn-userid no-error.

lr = _userio._userio-dbaccess.

/****   Test Query   ****/

for each table no-lock where whatever:
  i = i + 1.  /* count the records that the 4gl client "sees" */
end.

/****/

find _userio no-lock where
  _userio._userio-usr = _myconnection._myconn-userid no-error.

lr = lr - _userio._userio-dbaccess.

display lr i.

return.

Once the query has been validated as needing improvement compile LRTEST.P with the XREF option:

compile dir/lrtest.p xref tmp/lrtest.xrf

Check the output file for WHOLE-INDEX searches on the test query and verify that it functions the same as the original query - if necessary embed EXPORT statements to make a baseline record of the selected data for eventual comparison with the improved query's result set.

You can now use this test bed as a base for changing elements of the WHERE clause, adding indexes or whatever other strategies you choose to improve the query. Successful modifications will be reflected in the numbers shown when the test query is run. You can even use it to verify that the data returned is unchanged by logging the result sets of the original and modified queries and comparing them.

This is an iterative process - it will often take many attempts to determine what the best solution is for a given problem. You may find that the first index that you add isn't being used as expected or that a reformulation of the WHERE clause actually makes things worse. It is far better to discover that here, in a safe environment, than it is to submit production users to trial and error.

By using LRTEST.P, COMPILE XREF and the CTRL-F and CTRL-N functions to validate your solution in the QA environment you take the guesswork out of the equation and produce dependable production solutions. Routine use of these tools in the development and testing process is an important step in preventing problems from being introduced into production in the first place.