mac vm startup time

John M McIntosh johnmci at smalltalkconsulting.com
Fri Feb 25 06:11:13 UTC 2005


I'm sure someone today muttered about the slow image startup time. A  
year or more back I looked into this and fixed some mac menu startup  
delays and we adjusted initializeObjectMemory to avoid excessive  
iterations over the image to fix things up. But that was awhile ago so  
this evening I took a look again.

On my powerbook with lots of other things running an image startup,  
from the point of application launch to the request to draw to the  
window takes 1100 milliseconds.
Actually I'm also watching a DVD too so I'm sure things are a bit  
faster on the machine if nothing else was going on.

Of which:
a) 225ms is taken to the point of image reading, mostly in mac menu bar  
creation/menu management. Some api call stacks are 48 levels deep.  Not  
much you can do here.
b) 150ms to read the image from disk/buffers (not much you can do about  
that) (19.2MB) image file
c) 50ms to run adjustAllOopsBy: (this looks at every object and adjusts  
the oops (maybe depending on starting address of oop in memory))
d) 25ms to run flushExternalPrimitives (mmm perhaps that should be  
combined in adjustAllOopsBy:? Someone could look at  that?)

So it is about 450ms to get us to this point.

Now the interpreter loop starts to run
a) 75ms in loading modules and read directory information When plugins  
are first called we attempt to find them as plugins before hunting for  
them internally, this requires disk i/o to search (in multiple places)  
for the nonexistent plugins.
b) someone wastes 20ms doing a nextInstance lookup Lets see what's the  
call stack?

116324392 Behavior>allInstancesDo:
116324300 ExternalAddress class>startUp:
116324208 ExternalObject class>startUp:
114043140 [] in SystemDictionary>send:toClassesNamedIn:with:
114042916 OrderedCollection>do:
114042824 SystemDictionary>send:toClassesNamedIn:with:
114042732 SystemDictionary>processStartUpList:
113811996 SmalltalkImage>snapshot:andQuit:embedded:
113811904 SmalltalkImage>snapshot:andQuit:
113811812 TheWorldMenu>saveAndQuit


c) more reading directory information which takes us to 160ms, plugin  
lookup I'd guess
d) Then copybits and an incremental gc (finally screen interaction   
lets look at the stack.

116380820 GrafPort>copyBits
116380680 GrafPort>fillRect:offset:
116380576  
FormCanvas>frameAndFillRectangle:fillColor:borderWidth:borderColor:
116380484 Canvas>fillRectangle:color:
116380392 FormCanvas>fillRectangle:fillStyle:
116380080 Canvas>fillRectangle:fillStyle:borderStyle:
116379204 Morph>drawOn:
116379112 PasteUpMorph>drawOn:
116346488 [] in WorldState>drawWorld:submorphs:invalidAreasOn:
116341060 Rectangle>allAreasOutsideList:startingAt:do:
116340968 Rectangle>allAreasOutsideList:do:
116346236 [] in WorldState>drawWorld:submorphs:invalidAreasOn:
116340876 SequenceableCollection>do:
116344704 WorldState>drawWorld:submorphs:invalidAreasOn:
116344428 [] in WorldState>displayWorld:submorphs:
116339988 FormCanvas>roundCornersOf:in:during:
116339804 Canvas>roundCornersOf:during:
116338848 WorldState>displayWorld:submorphs:
116338756 PasteUpMorph>privateOuterDisplayWorld
116338664 PasteUpMorph>displayWorld
116338296 [] in WorldState>displayWorldSafely:
116338572 BlockContext>on:do:
116337784 BlockContext>ifError:
116337692 WorldState>displayWorldSafely:
116337600 PasteUpMorph>displayWorldSafely
116270492 PasteUpMorph>install
116270400 AutoStart class>checkForUpdates
116270308 AutoStart class>startUp:
114043140 [] in SystemDictionary>send:toClassesNamedIn:with:
114042916 OrderedCollection>do:
114042824 SystemDictionary>send:toClassesNamedIn:with:
114042732 SystemDictionary>processStartUpList:
113811996 SmalltalkImage>snapshot:andQuit:embedded:
113811904 SmalltalkImage>snapshot:andQuit:
113811812 TheWorldMenu>saveAndQuit


e) more directory reading
f) primitiveRenderScanLine is invoked, copybits, increment gcs

116366536 BalloonEngine>copyLoopFaster
116366444 BalloonEngine>copyBits
116366336 BalloonEngine>postFlushIfNeeded
116315708  
BalloonEngine>drawRectangle:fill:borderWidth:borderColor:transform:
116315568 BalloonCanvas>drawRectangle:color:borderWidth:borderColor:
116315464 BalloonCanvas>fillRectangle:fillStyle:
116315372 FormCanvas>balloonFillRectangle:fillStyle:
116315280 FormCanvas>fillRectangle:fillStyle:
116315096 Canvas>fillRectangle:fillStyle:borderStyle:
116311452 Morph>drawOn:
116311288 Canvas>draw:
116311184 Canvas>drawMorph:
116310356 [] in Morph>fullDrawOn:
116310908 CornerRounder  
class>roundCornersOf:on:in:displayBlock:borderWidth:corners:
116310264 FormCanvas>roundCornersOf:in:during:
116310172 Canvas>roundCornersOf:during:
116308608 Morph>fullDrawOn:
116308516 Canvas>fullDraw:
116308424 Canvas>fullDrawMorph:
116297296 [] in Morph>drawSubmorphsOn:
116296520 SequenceableCollection>reverseDo:
116297020 [] in Morph>drawSubmorphsOn:
116296000 Morph>drawSubmorphsOn:
116294436 [] in Morph>fullDrawOn:
116294344 FormCanvas>roundCornersOf:in:during:
116294252 Canvas>roundCornersOf:during:
116290944 Morph>fullDrawOn:
116290840 Canvas>fullDraw:
116290428 Canvas>fullDrawMorph:
116292964 [] in Morph>drawSubmorphsOn:
116290336 SequenceableCollection>reverseDo:
116292688 [] in Morph>drawSubmorphsOn:
116289784 Morph>drawSubmorphsOn:
116284608 [] in Morph>fullDrawOn:
116285344 CornerRounder  
class>roundCornersOf:on:in:displayBlock:borderWidth:corners:
116284516 FormCanvas>roundCornersOf:in:during:
116284424 Canvas>roundCornersOf:during:
116284292 Morph>fullDrawOn:
116284200 Canvas>fullDraw:
116284108 Canvas>fullDrawMorph:
116274292 [] in WorldState>drawWorld:submorphs:invalidAreasOn:
116272416 Rectangle>allAreasOutsideList:startingAt:do:
116272324 Rectangle>allAreasOutsideList:do:
116274040 [] in WorldState>drawWorld:submorphs:invalidAreasOn:
116272232 SequenceableCollection>do:
116272760 WorldState>drawWorld:submorphs:invalidAreasOn:
116272668 [] in WorldState>displayWorld:submorphs:
116272140 FormCanvas>roundCornersOf:in:during:
116272048 Canvas>roundCornersOf:during:
116271956 WorldState>displayWorld:submorphs:
116271864 PasteUpMorph>privateOuterDisplayWorld
116271772 PasteUpMorph>displayWorld
116271404 [] in WorldState>displayWorldSafely:
116271680 BlockContext>on:do:
116271312 BlockContext>ifError:
116271220 WorldState>displayWorldSafely:
116271128 PasteUpMorph>displayWorldSafely
116270124 PasteUpMorph>install
116270032 AutoStart class>checkForUpdates
116269940 AutoStart class>startUp:
114043140 [] in SystemDictionary>send:toClassesNamedIn:with:
114042916 OrderedCollection>do:
114042824 SystemDictionary>send:toClassesNamedIn:with:
114042732 SystemDictionary>processStartUpList:
113811996 SmalltalkImage>snapshot:andQuit:embedded:
113811904 SmalltalkImage>snapshot:andQuit:
113811812 TheWorldMenu>saveAndQuit


g) 610ms elapsed time (say 450 ms of time doing (f)) before we finally  
attempt to flush the results to the hardware.


--
======================================================================== 
===
John M. McIntosh <johnmci at smalltalkconsulting.com> 1-800-477-2659
Corporate Smalltalk Consulting Ltd.  http://www.smalltalkconsulting.com
======================================================================== 
===




More information about the Squeak-dev mailing list