Profiler timing discrepancies

Posted by danielb on 07-May-2018 21:40

I'm trying to use the Profiler from within PDSOE to profile some code, but have noticed something strange. I have the following call structure:

alpha.p

beta.p

gamma.p

If I select alpha.p, I can see that it has 4237 calls to beta.p, taking a total of 52s. However, if I select beta.p, I can see (in the top panel) that there have been 4237 calls (correct) for a total execution time of 24s. That's 28s that is missing in the timings.

Is this expected? I'm assuming that the timing is a difference between invoking the procedure and waiting for a response v timing the execution of the procedure once it has loaded into memory. We are running with -q, but the profiling is running on uncompiled code.

All Replies

Posted by Rob Fitzpatrick on 07-May-2018 22:23

Recently I was looking at a profiler output file in the profiler viewer in PDSOE (11.7.2) and noticed a discrepancy in the elapsed times shown for a given procedure between the call tree tab and the module details tab.  The former showed 296 ms, the latter showed 5 ms.  I believe the module details number was correct, as I loaded the file into the old profiler viewer tool and it also showed 5 ms for that procedure.  The bug is PSC00365228 and the fix is targeted for 11.7.4.  

I'm not sure whether you are hitting the same bug or a different one.  I suggest you open a case with TS.

Posted by gus bjorklund on 09-May-2018 12:30

There can also be measurement error. If the measurement resolution is to the nearest millisecond (don’t know what it really is), then each individual measurement could be off by +/- 0.5 msec. or more for very samll intervals. Given enough measurements, instead of averaging out, it could produce larger errors, depending on the size of the measured intervals (say 0.6 msec) in a given procedure.

Posted by Arno van der Ende on 17-Oct-2018 07:43

Hi Rob,

Where can I read the details of this bug (PSC00365228)?

I also see some discrepancies in the number of times called:

I profile MethodA.

MethodA calls MethodB.

MethodB does a for each and calls MethodC (1000 times).

Now, in the profile view, tab 'Module details', I see that MethodC is called 1000 times. But when I look in the 'Call tree' view, I see that MethodC is only called once. The timings on both views also don't match.

Is this a bug or just a misunderstanding of my knowledge about these views?

The strange thing is that when I profile in MethodB (instead of MethodA), the number of times in both views are the same.

I'm on 11.7.2 as well.

/ Arno

Posted by Rob Fitzpatrick on 17-Oct-2018 08:56

Hi Arno,

I'm sorry but I can't provide a further resource on this bug.  I just reported it to TS with reproduction steps and they filed a bug.  No KB was created.  I was told the fix should be in 11.7.4; no guarantees.

> Is this a bug or just a misunderstanding of my knowledge about these views?

I believe it is a bug.

Posted by Sanjeva Manchala on 17-Oct-2018 11:30

Hi Rob & Arno,
 
From our bug tracking tools, I can see that the bug is assigned for 11.7.5 as of now.
 
By the way we have made lot of improvements to call tree section in 12.0. I have tried the both the scenarios you have mentioned in 12.0 and I can see that everything is working properly with respect to timings of calls between modules view and call tree section and also the call order itself.
 
The major difference between 11.7.x and 12.0 is, in 11.7.x profiler output doesn’t contain call tree data explicitly, PDS OE has to manually calculate the call tree order and data based in tracing info, which leads to lot errors and performance issues while working with call tree. But in 12.0, profiler output will contain new section to display call tree data and timings and PDS OE just display those values by parsing the output.
 
Please give it a try with OpenEdge 12.0 ESAP and let us know what you feel with new Profiler data.
 
Hope this helps,
Sanjeev

This thread is closed