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

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
66.6% {7352ms} WarpBlt>>warpBits
16.6% {1832ms} Time class>>millisecondClockValue
7.2% {795ms} DisplayScreen>>forceToScreen:
4.0% {442ms} GrafPort>>copyBits

	old			+1,758,712 bytes
	young		-1,218,592 bytes
	used		+540,120 bytes
	free		-540,120 bytes

	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

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

Ned Konz

More information about the Squeakland mailing list