Time taken to run a loop (Progress 4GL)

Question

I wrote a query which contains multiple for each statements. The query is taking more than 20 minutes to fetch the data. Is there a way to check what time each loop started and ended. (How much time does each loop takes to execute and also the total time taken to complete the program).

score 3 · Answer 1 · answered Nov 25 '19 at 14:51

You could do as you ask (just follow JensD's suggestsions) but you would likely be better served to use the profiler. You can easily add profiling for a code snippet:

assign
  profiler:enabled     = yes
  profiler:description = "description of this test"
  profiler:profiling   = yes
  profiler:file-name   = "filename.prf"
. 

/* this is deliberately awful code that should take a long time to run */

for each orderline no-lock:

  for each order no-lock:

    for each customer no-lock:

      if customer.custNum = order.custNum and orderLine.orderNum = orderLine.orderNum then
        . /* do something */

    end.

  end.

end.

/* end of test snippet */

assign
  profiler:enabled     = no
  profiler:profiling   = no
.

profiler:write-data().

You can then load that prf file into an analysis tool. The specifics depend on your development environment - if you are using an up to date version of PSDOE there is a Profiler analyzer included, if not you might want to download ProTop https://demo.wss.com/download.php and use the simple report included in lib/zprof_topx.p.

Ultimately what you are going to discover is that one or more of your FOR EACH statements is almost certainly using a WHERE clause that is a poor match for your available indexes.

To fix that you will need to determine which indexes are actually being selected and review the index selection rules. Some excellent material on that topic can be found here: http://pugchallenge.org/downloads2019/303_FindingData.pdf

If you don't want to go to the trouble of reading that then you should at least take a look at the actual index selection as shown by:

compile program.p xref program.xref

Do the selected indexes match your expectation? Did WHOLE-INDEX (aka "table scan") show up?

score 1 · Accepted Answer · answered Nov 25 '19 at 13:05

Using ETIME you can initiate a counter of milliseconds. It could be called once or several times to tell how much time has passed since reset.

ETIME(TRUE).

/*
Loop is here but instead I'll insert a small pause.
*/
PAUSE 0.5.

MESSAGE "This took" ETIME "milliseconds" VIEW-AS ALERT-BOX.

Milliseconds might not be useful when dealing with several minutes. Then you can use TIME to keep track of seconds but you need to handle start time yourself then.

DEFINE VARIABLE iStart AS INTEGER NO-UNDO.

iStart = TIME.

/*
Loop is here but instead I'll insert a slightly longer pause.
*/
PAUSE 2.

MESSAGE "This took" TIME - iStart "seconds" VIEW-AS ALERT-BOX.

If you want to keep track of several times then it might be better to output to a log file instead of using a MESSAGE-box that will stop execution until it's clicked.

DEFINE VARIABLE i AS INTEGER NO-UNDO.
DEFINE STREAM str.    
OUTPUT STREAM str TO c:\temp\timing.txt.

ETIME(TRUE).
/*
Fake loop
*/
DO i = 1 TO 20:
    PAUSE 0.1.
    PUT STREAM str UNFORMATTED "Timing no " i " " ETIME "ms" SKIP.
END.
OUTPUT CLOSE.

Time taken to run a loop (Progress 4GL)

2 Answers2