Progress version: 10.2B03
Overhead: This is the average overhead as reported by the Progress Profiler. I assume this is the overhead to call the method/external procedure/etc.
Per Profiler documentation, it is:
"Where LineNo is 0, that refers to the time used to initialize and then later to tear down
the procedure or trigger. This is the overhead of running the
procedure/function/trigger."
The pattern for relative run times between different kinds of calls are true over 30 or 40 runs that I have done. This is a concern before we go further into OOABL.
Case 1: When method called is part of object constructed using NEW ()
/* overhead is at least 10X higher when compared to calling a method that is say part of the parent class or a method which is static*/
Therefore:
oViewerClass = new ViewerClass().
for each someTable:
/* overhead in latest measurement is: .000311 seconds per one call */
oViewerClass:writeBuffer (bufferhandle to SomeTable).
/* overhead to call this static helper method: .000079 seconds */
vchardigits = utils.getDigitsOnly(vchardigits).
/* overhead to call a method in the parent class: .000016 seconds */
this-object:addsubTotal().
/* overhead to call external procedure: .000047 */
run COUNTRYISO2.P(input vcntry,
output vCntryISO2,
output vCntry).
end.
/* actual method called*/
270 method public override logical writeBuffer(input pHBuffer as handle):
271
272 if (pHBuffer:available) then
273 do:
274 for each ttOutStream no-lock :
275 vCharBuffer = "".
276 ttOutStream.hbuf:buffer-copy(pHBuffer).
277
278 do i = 1 to ttOutStream.hbuf:num-fields:
279
280 pFBuffer = ttOutStream.hbuf:buffer-field(i).
281
282 vReportValue =
283 if (pFBuffer:label > "") then
284 DYNAMIC-INVOKE(pFBuffer:label,
285 "format",
286 input pFBuffer:buffer-value,
287 input pFBuffer:format)
288 else
289 if (pFBuffer:buffer-value <> ?) then
290 pFBuffer:string-value()
291 else
292 if pFBuffer:data-type = "date" then "00000000"
293 else
294 fill(" ",integer(pFBuffer:width-chars)).
295
296 vCharBuffer = vCharbuffer + vReportValue +
297 ttOutStream.columnDelimiter.
298 end. /* do i = */
299
300 if (ttOutStream.columnDelimiter <> "") then
301 vCharBuffer = substring(vCharbuffer,1,
302 length(vCharBuffer) - 1).
303 if ttOutStream.upperCase then
304 /* the higher CASE configurations take over if set */
305 vCharBuffer = CAPS(vCharBuffer).
306
307 put stream-handle ttOutStream.hStream unformatted
308 vCharBuffer skip.
309 end. /* for each*/
310
311 end. /* if available */
312 end method.
you need to compare apples with apples.
When New()ing a class, you are loading it into memory, and then
calling methods of that object whilst in memory.
You cannot compare this with just running an external procedure.
To make a like-for-like comparison, run the external program
persistently, and then run an internal procedure within the persistent
procedure
Julian
The point is that method calls contained in a created object are at least 10X slower then calls to external procedures and even static methods or methods in the parent class.
The point is that this method call overhead seems to be unreasonably high when compared to other types of method calls or are they?
We will be incuring a 10X degradation in overhead performance if we switch to method calls in created objects verus external procedures let alone internal procedures.
It adds many minutes to our batch jobs executing over large datasets.
Ok. given this set of code
testing.model1.cls
class testing.model1:
method public void foo():
end method.
end class.
testing/external.p
/** does nothing */
and this test program:
def var lv_o as int no-undo.
def var lv_p as int no-undo.
def var lv_i as int no-undo.
def var m as testing.model1 no-undo.
etime(yes).
do lv_i = 1 to 100000:
run testing/external.p.
end.
assign lv_p = etime.
m = new testing.model1().
etime(yes).
do lv_i = 1 to 100000:
m:foo().
end.
assign lv_o = etime.
message lv_p lv_o view-as alert-box.
what results do you get ? Mine are the complete opposite of what you say:
lv_p (external time) = 4305 (4.3 seconds)
lv_o (method call) = 223 (.22 of a second) 20x faster
if you add -q as a session startup parameter the times are as follows
lv_p (external time) = 431 (.43 seconds)
lv_o (method call) = 223 (.22 of a second) 2x faster
which is exactly as I would have suspected (the -q loads the procedure into memory, so subsequent calls don't have to load it from disk etc).
I did finally try your code and added measurements for internal procedure calls:
For 200,000 calls, the difference in real seconds between internal procedure and delegated object method call is about .4 seconds; this is quite acceptable over large volumes of calls.
Thanks to Julian .. he is making me re-think the results I was seeing in production code.
It probably is due to comparing apples and oranges.
I will be out of the office until Monday 27th February with little email access. If you need to contact someone within the office then please phone reception on 01904 727150, otherwise I will reply to your email as soon as I am able.
Thanks, Andrew.
Excellent news.
Thanks for posting back your findings.