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.
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.
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.
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
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.