profile reporting wrongly?

From: Sebastian Sardina <>
Date: Thu 11 Apr 2002 09:54:50 PM GMT
Message-ID: <>

I have seen a similar post about this before.

When I profile a call (under SunOS) it reports me predicates
that, although in the file, they are never called (and I'm sure
that's the case)
In fact, the predicate that takes more time is one that it's never

If I even delete that predicate, then it reports me another predicate
that althought it is used, it is now used MUCH MORE.

So in first place I profile my call and I get this:

Predicate             Module        %Time   Time   %Cum
errorRecoveryProc /0  eclipse       33.1%  45.43s  33.1%
eval              /3  eclipse       13.7%  18.83s  46.8%
subf2             /3  eclipse        9.4%  12.89s  56.2%
=..               /2  sepia_kernel   5.7%   7.87s  61.9%
rel_fluent        /1  eclipse        1.4%   1.88s  89.7%

errorRecoveryProc is on the file but I'm sure it's never called.
So 33% of my times is used in a predicate that is not called! ;-)

In fact, if I delete it completely the profile now says:

Predicate             Module        %Time   Time   %Cum
rel_fluent        /1  eclipse       33.8%  46.16s  33.8%
eval              /3  eclipse       13.5%  18.48s  47.3%
subf2             /3  eclipse        9.1%  12.50s  56.4%
=..               /2  sepia_kernel   6.2%   8.44s  62.6%
ground            /1  eclipse        5.3%   7.18s  67.8%

Now, rel_fluent/1 is suddenly the most expensive! It took
1.4% before and now it takes 33%!

I wonder whether the profile tool is taking into account unification
time or something like that when a goal is called. 
The above two experiments sound strange to me. I guess I am really
missing something here...

Any ideas will be more than appreciated!

Received on Thu Apr 11 22:56:37 2002

This archive was generated by hypermail 2.1.8 : Wed 16 Nov 2005 06:07:13 PM GMT GMT