[Squeakland] help optimizing project, please
Ned Konz
ned at squeakland.org
Fri Jun 11 14:09:16 PDT 2004
On Thursday 10 June 2004 11:43 am, John Voiklis wrote:
> Hello All,
>
> As some of you know, I am doing both Squeak- and Non-Squeak-related
> research at Teachers College. One such non-Squeak project relates to
> Richard Mayer's work on multimedia, interactivity, and learning. Without
> going too much into the details, Mayers experiments included simulations
> and/or animations of drum brakes, air pumps, et al. For our experiments at
> TC, I have built a "how drum brakes work" etoy (first URL below), a highly
> idealized simulation based closely on the simulation used by Mayer. The
> problem is that it moves slower than mollasses. I don't understand why,
> given that there are fewer concurrently running scripts than the version
> of the etoy (second link below) that I used for last semester's
> experiment. Can anyone help?
>
Hi John,
You can profile things yourself. From the World menu (which you can get by hitting the ESC key),
choose "debug...", then "start/browse MessageTally". Say OK to the dialog.
Now run your simulation for a while and then move the mouse to the top of the screen.
You'll see a time profile.
The top part is a representation of the call tree with percentages of time spent in each method,
and the bottom is the source text of the method.
So here's a profile from 11 seconds of running your simulation:
- 598 tallies, 11039 msec.
**Tree**
99.8% {11017ms} PasteUpMorph>>doOneCycle
99.8% {11017ms} WorldState>>doOneCycleFor:
99.7% {11006ms} WorldState>>doOneCycleNowFor:
54.7% {6038ms} WorldState>>displayWorldSafely:
|54.7% {6038ms} PasteUpMorph>>displayWorld
| 54.7% {6038ms} PasteUpMorph>>privateOuterDisplayWorld
| 54.7% {6038ms} WorldState>>displayWorld:submorphs:
| 47.5% {5244ms} WorldState>>drawWorld:submorphs:invalidAreasOn:
| |47.5% {5244ms} FormCanvas(Canvas)>>fullDrawMorph:
| | 47.5% {5244ms} FormCanvas(Canvas)>>fullDraw:
| | 47.5% {5244ms} ViewerFlapTab(Morph)>>fullDrawOn:
| | 25.8% {2848ms} TransformationMorph(TransformMorph)>>drawSubmorphsOn:
| | |24.9% {2749ms} FormCanvas>>transformBy:clippingTo:during:smoothing:
| | | 24.4% {2694ms} WarpBlt>>warpBits
| | 18.7% {2064ms} ViewerFlapTab(Morph)>>drawSubmorphsOn:
| | 18.7% {2064ms} FormCanvas(Canvas)>>fullDrawMorph:
| | 18.7% {2064ms} FormCanvas(Canvas)>>fullDraw:
| | 18.7% {2064ms} ThumbnailMorph(Morph)>>fullDrawOn:
| | 18.2% {2009ms} FormCanvas(Canvas)>>drawMorph:
| | 18.2% {2009ms} FormCanvas(Canvas)>>draw:
[18.2% {2009ms} ThumbnailMorph>>drawOn:
[ 16.2% {1788ms} Time class>>millisecondClockValue
| 7.2% {795ms} WorldState>>forceDamageToScreen:
| 7.2% {795ms} DisplayScreen>>forceDamageToScreen:
| 7.2% {795ms} DisplayScreen>>forceToScreen:
44.6% {4923ms} PasteUpMorph>>runStepMethods
44.6% {4923ms} WorldState>>runStepMethodsIn:
44.6% {4923ms} WorldState>>runLocalStepMethodsIn:
44.5% {4912ms} StepMessage(MorphicAlarm)>>value:
44.5% {4912ms} SketchMorph(Morph)>>stepAt:
43.6% {4813ms} Player178202(Player)>>stepAt:
43.6% {4813ms} Player178202(Player)>>runAllTickingScripts:
43.6% {4813ms} ScriptInstantiation>>runIfTicking:
43.6% {4813ms} Player178202>>spin
43.6% {4813ms} Player178202(Player)>>overlaps:
43.5% {4802ms} TransformationMorph(Morph)>>imageForm
43.5% {4802ms} TransformationMorph(Morph)>>imageFormForRectangle:
43.5% {4802ms} TransformationMorph(Morph)>>imageForm:forRectangle:
43.5% {4802ms} FormCanvas(Canvas)>>fullDrawMorph:
[43.5% {4802ms} FormCanvas(Canvas)>>fullDraw:
[ 43.5% {4802ms} TransformationMorph(Morph)>>fullDrawOn:
[ 43.3% {4780ms} TransformationMorph(TransformMorph)>>drawSubmorphsOn:
[ 42.5% {4692ms} FormCanvas>>transformBy:clippingTo:during:smoothing:
[ 42.1% {4647ms} WarpBlt>>warpBits
**Leaves**
66.6% {7352ms} WarpBlt>>warpBits
16.6% {1832ms} Time class>>millisecondClockValue
7.2% {795ms} DisplayScreen>>forceToScreen:
4.0% {442ms} GrafPort>>copyBits
**Memory**
old +1,758,712 bytes
young -1,218,592 bytes
used +540,120 bytes
free -540,120 bytes
**GCs**
full 0 totalling 0ms (0.0% uptime)
incr 584 totalling 337ms (3.0% uptime), avg 1.0ms
tenures 1 (avg 584 GCs/tenure)
root table 0 overflows
So what does this mean?
First, the lines that start with a '[' square bracket
are just ones that should be indented even further.
I have indented them here.
Where you see the percentage of a child item about the same as its
parent, it means that the parent isn't spending any time of its own.
So we can go down the tree and see that:
* 7.2% of the time is being spent updating the screen (forceDamageToScreen:)
this is because your wheel keeps spinning
* 47.5% of the sime is being spent drawing flap tabs
if you hide the flaps your simulation should speed up greatly
so right there is 55% of the CPU time that's being spent.
Avoid the spinning wheel animation and hide the flap tabs and things
will speed up a lot.
What more can you do?
Looking further,
* the Player178202 (named Drum; I found this by highlighting the
Player178202>>spin line and bringing up the context menu and selecting
"inspect instances") is spending 43.6% of the CPU time spinning.
Almost all of that time is being spent in the overlaps: test, and all
of that time is being spent in updating the imageForm of the morphs
themselves to make stencils to test the overlap. There's no caching
being done of those forms.
I notice that Drum is being turned (which accounts for the
TransformationMorph you see in the list). It is more costly to get the
imageForm from a TransformationMorph (i.e. a rotated Morph) that it is
from a SketchMorph that isn't rotated.
What you might want to do is make a non-rotated copy of the Drum
and put it behind the rotating Drum and check *that* for overlaps.
So making these changes:
- remove flap tabs
- make an unrotated copy of Drum (called Drum1) and put it behind Drum.
- change Drum's spin script to refer to Drum1 instead of Drum in the
overlaps tests
should greatly speed things up.
And in fact, it reduces the time spent in Drum>>spin to 14% (from 43.6%).
Now the thing that's taking up the time is the redraws of
TransformationMorphs (76.8%). What's transformed here? Well, the Drum
itself, and the CarWheel.
I tried pausing the CarWheel's spinWheel script and found that the
percentage of time spent drawing TransformationMorphs went down to
46.6%.
Perhaps you could animate the CarWheel and the Drum using separate
images rather than rotating them?
Beyond that, there is definitely room for improvement (in the Smalltalk
infrastructure) in the overlaps: test, which could perhaps cache image
forms.
--
Ned Konz
http://bike-nomad.com/squeak/
More information about the Squeakland
mailing list