Hello,
I am reposting with easier data to read as my previous posts were confusing.
What is profiled is an user interaction with a DrGeo sketch: the user drags a point, a segment then the whole sketch is recomputed in real time. The sketch in question is the one shown in picture http://squeak.ofset.org/tmp/profile1a.PNG
When interacting with the sketch, artifacts appear in the smaller morphs like the small red rectangles representing points. There is a tiny delay when they are redrawn, however once the interaction ends, the whole sktech is clean without any artifacts.
I still can't have a text form for the profile on iPad, but I have pasted the two images in one, easier to read in one shot. Sorry. So the profile is in the file http://squeak.ofset.org/tmp/profile1iPad.PNG
I also included a profile of the same interaction on a PC, file profile1PC.txt
Looking at the profile, I see in the iPad a lot of time spent in the method #idleProcess. The #eventLoop also counts for a lot. I don't know how to interpret these two results.
Thanks
Hilaire
PS: for those interested, I have a fee scripts to build from scratch a DrGeo image for the iPad, see https://gforge.inria.fr/scm/?group_id=1308 https://gforge.inria.fr/scm/viewvc.php/drgeo2/?root=istoa
On 7/24/2011 10:11, Hilaire Fernandes wrote:
Looking at the profile, I see in the iPad a lot of time spent in the method #idleProcess. The #eventLoop also counts for a lot. I don't know how to interpret these two results.
If time is spent in the idleProcess it is usually a good sign. Time assigned to the idleProcess is time in which your system didn't do a thing, so you have resources to spare. Usually this means you were running a UI interaction in which case there is always some idle time inbetween the Morphic interaction loop.
The bad news about the profile is the time spent in the eventLoop. The reason it's bad is that this is a clear sign that the profiler is bogus. I have commented on that many times in the past; basically the profile you have is almost entirely useless (see [1] for a good example of how bogus the results are).
Your best bet at this point is probably to go back to a VM that doesn't have the problem (probably as far as 3.6 if that's feasible) or to extract the OpenQwaq system profiler which you could then run on the desktop (I'm not sure if it's supported by the Stack VM; you could try it to see if it works on the iPad as well).
[1] http://lists.squeakfoundation.org/pipermail/vm-dev/2007-June/001410.html
Cheers, - Andreas
Moving discussion to vm-dev for follow up
On Sun, Jul 24, 2011 at 01:25:37PM +0200, Andreas Raab wrote:
On 7/24/2011 10:11, Hilaire Fernandes wrote:
Looking at the profile, I see in the iPad a lot of time spent in the method #idleProcess. The #eventLoop also counts for a lot. I don't know how to interpret these two results.
If time is spent in the idleProcess it is usually a good sign. Time assigned to the idleProcess is time in which your system didn't do a thing, so you have resources to spare. Usually this means you were running a UI interaction in which case there is always some idle time inbetween the Morphic interaction loop.
The bad news about the profile is the time spent in the eventLoop. The reason it's bad is that this is a clear sign that the profiler is bogus. I have commented on that many times in the past; basically the profile you have is almost entirely useless (see [1] for a good example of how bogus the results are).
Your best bet at this point is probably to go back to a VM that doesn't have the problem (probably as far as 3.6 if that's feasible) or to extract the OpenQwaq system profiler which you could then run on the desktop (I'm not sure if it's supported by the Stack VM; you could try it to see if it works on the iPad as well).
[1] http://lists.squeakfoundation.org/pipermail/vm-dev/2007-June/001410.html
This discussion seems to have died out prematurely without conclusion.
I opened Mantis 7653 to document the issue:
http://bugs.squeak.org/view.php?id=7653
My impression from reading the earlier discussion is that MessageTally accuracy was sacrificed in an attempt to gain performance, and that the right thing to do is to add the interrupt checks as suggested by Andreas, measure the actual impact on performance, and leave the interrupt checks in place if performance does not measurably suffer.
I cannot follow up further right now, but hopefully the Mantis report will keep the issue from being lost (again).
Dave
Andreas,
As we are writing about bogus, you can explain me one aspect of the profile I found hard to interpret. If you look at this profile snippet (I hope it will print in a readable form):
| | 16.7% {2692ms} DrGeo>>updateDirtyCostumes | | 16.6% {2686ms} DrGAngle3PointsCostume(DrGMathItemCostume)>>update | | 10.4% {1674ms} DrGAngle3PointsCostume>>redraw | | |9.4% {1513ms} DrGAngle3PointsCostume>>redrawShape | | | 9.3% {1496ms} DrGAngle3PointsCostume>>redrawArc | | | 9.2% {1485ms} DrGArcMorph>>center:radius:origin:length: | | | 8.6% {1395ms} DrGArcMorph(PolygonMorph)>>computeBounds | | | 7.8% {1255ms} DrGArcMorph(PolygonMorph)>>curveBounds | | | 7.6% {1231ms} DrGArcMorph(PolygonMorph)>>lineSegmentsDo: | | | 7.2% {1162ms} DrGArcMorph(PolygonMorph)>>coefficients | | | 4.3% {687ms} Cubic>>bestSegments | | | 2.8% {447ms} Cubic>>calcEnoughSegments | | | |1.8% {297ms} Cubic>>enough:withMeasure:withIn: | | | | 1.8% {291ms} Cubic>>measureFor: | | | | 1.6% {251ms} Cubic(SequenceableCollection)>>polynomialEval: | | | 1.5% {239ms} Cubic>>honeIn: | | 3.1% {501ms} DrGSegmentCostume>>redraw
The way the message calls are nested in the profile result, for me it says: DrGSegmentCostume>>redraw is called in the context of DrGAngle3PointsCostume(DrGMathItemCostume)>>update which is absolutely not the case. So what is it?
Le 24/07/2011 13:25, Andreas Raab a écrit :
Your best bet at this point is probably to go back to a VM that doesn't have the problem (probably as far as 3.6 if that's feasible) or to extract the OpenQwaq system profiler which you could then run on the desktop (I'm not sure if it's supported by the Stack VM; you could try it to see if it works on the iPad as well).
Is this OpenQwaq system profiler located at the image level or VM level?
Thanks,
Hilaire
On 7/24/2011 18:42, Hilaire Fernandes wrote:
As we are writing about bogus, you can explain me one aspect of the profile I found hard to interpret. If you look at this profile snippet (I hope it will print in a readable form):
| | 16.7% {2692ms} DrGeo>>updateDirtyCostumes | | 16.6% {2686ms} DrGAngle3PointsCostume(DrGMathItemCostume)>>update | | 10.4% {1674ms} DrGAngle3PointsCostume>>redraw | | |9.4% {1513ms} DrGAngle3PointsCostume>>redrawShape | | | 9.3% {1496ms} DrGAngle3PointsCostume>>redrawArc | | | 9.2% {1485ms} DrGArcMorph>>center:radius:origin:length: | | | 8.6% {1395ms} DrGArcMorph(PolygonMorph)>>computeBounds | | | 7.8% {1255ms} DrGArcMorph(PolygonMorph)>>curveBounds | | | 7.6% {1231ms} DrGArcMorph(PolygonMorph)>>lineSegmentsDo: | | | 7.2% {1162ms} DrGArcMorph(PolygonMorph)>>coefficients | | | 4.3% {687ms} Cubic>>bestSegments | | | 2.8% {447ms} Cubic>>calcEnoughSegments | | | |1.8% {297ms} Cubic>>enough:withMeasure:withIn: | | | | 1.8% {291ms} Cubic>>measureFor: | | | | 1.6% {251ms} Cubic(SequenceableCollection)>>polynomialEval: | | | 1.5% {239ms} Cubic>>honeIn: | | 3.1% {501ms} DrGSegmentCostume>>redraw
The way the message calls are nested in the profile result, for me it says: DrGSegmentCostume>>redraw is called in the context of DrGAngle3PointsCostume(DrGMathItemCostume)>>update which is absolutely not the case. So what is it?
Don't know. I have not seen any problems with incorrectly reported call trees. The only thing I could imagine is that the calls to DrGMathItemCostume are incorrectly coalesced by MessageTally. Alternatively, it's possible that changes to context or compiled method in Pharo have something to do with it (MessageTally relies a lot on method / context comparisons for reporting).
Le 24/07/2011 13:25, Andreas Raab a écrit :
Your best bet at this point is probably to go back to a VM that doesn't have the problem (probably as far as 3.6 if that's feasible) or to extract the OpenQwaq system profiler which you could then run on the desktop (I'm not sure if it's supported by the Stack VM; you could try it to see if it works on the iPad as well).
Is this OpenQwaq system profiler located at the image level or VM level?
It's purely in the image but it needs VM support which I think is only in Cog.
Cheers, - Andreas
On 24.07.2011, at 18:42, Hilaire Fernandes wrote:
Andreas,
As we are writing about bogus, you can explain me one aspect of the profile I found hard to interpret. If you look at this profile snippet (I hope it will print in a readable form):
| | 16.7% {2692ms} DrGeo>>updateDirtyCostumes | | 16.6% {2686ms} DrGAngle3PointsCostume(DrGMathItemCostume)>>update | | 10.4% {1674ms} DrGAngle3PointsCostume>>redraw | | |9.4% {1513ms} DrGAngle3PointsCostume>>redrawShape | | | 9.3% {1496ms} DrGAngle3PointsCostume>>redrawArc | | | 9.2% {1485ms} DrGArcMorph>>center:radius:origin:length: | | | 8.6% {1395ms} DrGArcMorph(PolygonMorph)>>computeBounds | | | 7.8% {1255ms} DrGArcMorph(PolygonMorph)>>curveBounds | | | 7.6% {1231ms} DrGArcMorph(PolygonMorph)>>lineSegmentsDo: | | | 7.2% {1162ms} DrGArcMorph(PolygonMorph)>>coefficients | | | 4.3% {687ms} Cubic>>bestSegments | | | 2.8% {447ms} Cubic>>calcEnoughSegments | | | |1.8% {297ms} Cubic>>enough:withMeasure:withIn: | | | | 1.8% {291ms} Cubic>>measureFor: | | | | 1.6% {251ms} Cubic(SequenceableCollection)>>polynomialEval: | | | 1.5% {239ms} Cubic>>honeIn: | | 3.1% {501ms} DrGSegmentCostume>>redraw
The way the message calls are nested in the profile result, for me it says: DrGSegmentCostume>>redraw is called in the context of DrGAngle3PointsCostume(DrGMathItemCostume)>>update which is absolutely not the case. So what is it?
The class in parenthesis indicates the actual compiled method executed. There is no DrGAngle3PointsCostume>>update but only DrGMathItemCostume>>update. DrGSegmentCostume also inherits #update from DrGMathItemCostume which sends "self redraw". So this looks confusing but okay to me.
Possibly MessageTally should count the different receiver classes separately. This is what Andreas alluded to - it's the same compiled method but different receiver classes for the method context.
- Bert -
squeak-dev@lists.squeakfoundation.org