Monticello ProfilingPhilippe Marschall philippe.marschall at gmail.comSat Jul 1 12:50:00 UTC 2006
Hi
Loading of Monticello packages in the current 3.9 is already much
faster thanks to Adrian. But I think it's still far from optimal. So I
did a trace of loading several packages with Monticello (attached).
The parts I find interesting
29.0% {75168ms} PackageInfo>>includesClass:
28.0% {72576ms} RBParser class(Class)>>category
11.7% {30326ms} Delay>>wait (sent by EventSensor>>wait2ms)
More the 10% of the time is spent doing nothing. Although Class >>
#category has seen a major speedup (thanks Adrian) it's still a
bottleneck.
Cheers
Philippe
-------------- next part --------------
- 243061 tallies, 259199 msec.
**Tree**
96.3% {249609ms} JLoader>>loadPackages
|96.3% {249609ms} JLoader>>loadLatestPackage:from:
| 88.4% {229132ms} MCVersion>>load
| |88.4% {229132ms} MCVersionLoader class>>loadVersion:
| | 88.4% {229132ms} MCVersionLoader>>load
| | 83.7% {216950ms} MCPackageLoader>>loadWithNameLike:
| | |79.6% {206322ms} MCPackageLoader>>basicLoad
| | | |71.7% {185846ms} MCPackageLoader>>tryToLoad:
| | | | |71.1% {184290ms} MCMethodDefinition(MCDefinition)>>loadOver:
| | | | | 57.7% {149558ms} MCMethodDefinition>>load
| | | | | |57.1% {148003ms} CompiledMethod class(ClassDescription)>>compile:classified:withStamp:notifying:
| | | | | | 57.1% {148003ms} CompiledMethod class(ClassDescription)>>compile:classified:wi...notifying:logSource:
| | | | | | 37.1% {96163ms} CompiledMethod class(ClassDescription)>>addAndClassifySelecto...nProtocol:notifying:
| | | | | | |34.2% {88646ms} SystemChangeNotifier>>methodAdded:selecto...l:class:requestor:
| | | | | | | 34.0% {88128ms} SystemChangeNotifier>>trigger:
| | | | | | | 34.0% {88128ms} AddedEvent(AbstractEvent)>>trigger:
| | | | | | | 34.0% {88128ms} SystemEventManager(Object)>>triggerEvent:with:
| | | | | | | 34.0% {88128ms} SystemEventManager(Object)>>triggerEvent:withArguments:
| | | | | | | 33.7% {87350ms} WeakActionSequenceTrappingErrors>>valueWithArguments:
| | | | | | | 33.7% {87350ms} WeakActionSequenceTrappingErrors>>valueWithArgum...startingFrom:
| | | | | | | 33.1% {85795ms} WeakMessageSend>>valueWithArguments:
| | | | | | | 30.4% {78796ms} MCWorkingCopy class(MCPackageManager class)>>methodModified:
| | | | | | | 30.3% {78537ms} MCWorkingCopy class(MCPackageManager class)>>managersForClass:selector:do:
| | | | | | | 30.2% {78278ms} MCWorkingCopy class(MCPackageManager class)>>managersForClass:category:do:
| | | | | | | 30.2% {78278ms} MCWorkingCopy class(MCPackageManager class)>>managersForClass:do:
| | | | | | | 29.0% {75168ms} PackageInfo>>includesClass:
| | | | | | | 28.0% {72576ms} RBParser class(Class)>>category
| | | | | | | 26.8% {69465ms} SystemOrganizer(Categorizer)>>listAtCategoryNamed:
| | | | | | | 26.5% {68688ms} Array(SequenceableCollection)>>indexOf:ifAbsent:
| | | | | | | 26.4% {68429ms} Array(SequenceableCollection)>>indexOf:startingAt:ifAbsent:
| | | | | | | 13.2% {34214ms} primitives
| | | | | | | 13.2% {34214ms} ByteSymbol(Symbol)>>=
| | | | | | 10.9% {28253ms} CompiledMethod class(ClassDescription)>>logMethodSource:forMe...withStamp:notifying:
| | | | | | |10.8% {27993ms} CompiledMethod>>putSource:fromParseNod...p:inFile:priorMethod:
| | | | | | | 8.3% {21514ms} CompiledMethod>>putSource:fromParseNode:inFile:withPreamble:
| | | | | | | |7.6% {19699ms} RemoteString class>>newString:onFileNumber:toFile:
| | | | | | | | 7.6% {19699ms} RemoteString>>string:onFileNumber:toFile:
| | | | | | | | 7.6% {19699ms} MultiByteFileStream(WriteStream)>>nextChunkPutWithStyle:
| | | | | | | | 7.6% {19699ms} MultiByteFileStream(WriteStream)>>nextChunkPut:
| | | | | | | | 7.6% {19699ms} MultiByteFileStream>>nextPutAll:
| | | | | | | | 6.8% {17626ms} MultiByteFileStream>>nextPut:
| | | | | | | | 3.9% {10109ms} UTF8TextConverter>>nextPut:toStream:
| | | | | | | 2.5% {6480ms} CompiledMethod class(ClassDescription)>>printCategoryChunk:on:withStamp:priorMethod:
| | | | | | 9.1% {23587ms} CompiledMethod class(Behavior)>>compile:classified:notifying:trailer:ifFail:
| | | | | | 6.6% {17107ms} Compiler>>compile:in:classified:notifying:ifFail:
| | | | | | 6.6% {17107ms} Compiler>>translate:noPattern:ifFail:
| | | | | | 6.6% {17107ms} Parser>>parse:class:category:noPat...context:notifying:ifFail:
| | | | | | 6.6% {17107ms} Parser>>parse:class:noPattern:context:notifying:ifFail:
| | | | | | 5.2% {13478ms} Parser>>method:context:encoder:
| | | | | | 4.6% {11923ms} Parser>>statements:innerBlock:
| | | | | | 4.4% {11405ms} Parser>>expression
| | | | | | 2.8% {7258ms} Parser>>messagePart:repeat:
| | | | | 13.3% {34473ms} MCClassDefinition>>load
| | | | | 12.4% {32141ms} MCClassDefinition>>createClass
| | | | | 11.3% {29289ms} ClassBuilder>>name:inEnvironment:subc...Dictionaries:category:
| | | | | 11.3% {29289ms} ClassBuilder>>name:inEnvironment:subc...aries:category:unsafe:
| | | | | 7.9% {20477ms} ClassBuilder>>recompile:from:to:mutate:
| | | | | |7.7% {19958ms} ClassBuilder>>informUserDuring:
| | | | | | 7.7% {19958ms} Utilities class>>informUserDuring:
| | | | | | 7.7% {19958ms} MVCMenuMorph>>informUserAt:during:
| | | | | | 7.6% {19699ms} EventSensor(InputSensor)>>cursorPoint
| | | | | | 7.6% {19699ms} EventSensor(InputSensor)>>mousePoint
| | | | | | 7.6% {19699ms} EventSensor>>primMousePt
| | | | | | 7.6% {19699ms} EventSensor>>wait2ms
| | | | | | 7.6% {19699ms} Delay>>wait
| | | | | 2.5% {6480ms} SystemChangeNotifier>>classAdded:inCategory:
| | | | | 2.5% {6480ms} SystemChangeNotifier>>trigger:
| | | | | 2.5% {6480ms} AddedEvent(AbstractEvent)>>trigger:
| | | | | 2.5% {6480ms} SystemEventManager(Object)>>triggerEvent:with:
| | | | | 2.5% {6480ms} SystemEventManager(Object)>>triggerEvent:withArguments:
| | | | | 2.5% {6480ms} WeakActionSequenceTrappingErrors>>valueWithArguments:
| | | | | 2.5% {6480ms} WeakActionSequenceTrappingErrors>>valueWithArgum...startingFrom:
| | | | | 2.5% {6480ms} WeakMessageSend>>valueWithArguments:
| | | | | 2.4% {6221ms} MCWorkingCopy class(MCPackageManager class)>>classModified:
| | | | | 2.4% {6221ms} MCWorkingCopy class(MCPackageManager class)>>managersForClass:do:
| | | | | 2.3% {5962ms} PackageInfo>>includesClass:
| | | | | 2.3% {5962ms} RBParser class(Class)>>category
| | | |4.0% {10368ms} OrderedCollection(SequenceableCollection)>>do:displayingProgress:
| | | | |4.0% {10368ms} EventSensor(InputSensor)>>cursorPoint
| | | | | 4.0% {10368ms} EventSensor(InputSensor)>>mousePoint
| | | | | 4.0% {10368ms} EventSensor>>primMousePt
| | | | | 4.0% {10368ms} EventSensor>>wait2ms
| | | | | 4.0% {10368ms} Delay>>wait
| | | |3.2% {8294ms} MCOrganizationDefinition>>postloadOver:
| | | | 3.2% {8294ms} SystemOrganizer(Categorizer)>>categories:
| | | | 3.1% {8035ms} Array(SequenceableCollection)>>includes:
| | | | 3.1% {8035ms} Array(SequenceableCollection)>>indexOf:
| | | | 3.1% {8035ms} Array(SequenceableCollection)>>indexOf:ifAbsent:
| | | | 3.1% {8035ms} Array(SequenceableCollection)>>indexOf:startingAt:ifAbsent:
| | |4.0% {10368ms} MCPackageLoader>>analyze
| | | 4.0% {10368ms} MCPackageLoader>>sorterForItems:
| | | 2.2% {5702ms} MCDependencySorter class>>items:
| | | 2.2% {5702ms} MCDependencySorter>>addAll:
| | 4.3% {11146ms} MCPackageLoader>>updatePackage:withSnapshot:
| | 4.0% {10368ms} MCPackage>>snapshot
| | 2.7% {6998ms} MethodReference>>asMethodDefinition
| | 2.7% {6998ms} MCMethodDefinition class>>forMethodReference:
| 4.8% {12442ms} MCMczReader(MCVersionReader)>>version
| |4.8% {12442ms} MCMczReader(MCVersionReader)>>basicVersion
| | 4.1% {10627ms} MCMczReader(MCVersionReader)>>snapshot
| | 4.1% {10627ms} MCMczReader(MCVersionReader)>>definitions
| | 4.1% {10627ms} MCMczReader>>loadDefinitions
| | 2.1% {5443ms} DataStream>>next
| | 2.1% {5443ms} DataStream>>readInstance
| | 2.1% {5443ms} MCSnapshot(Object)>>readDataFrom:size:
| | 2.1% {5443ms} DataStream>>next
| | 2.1% {5443ms} DataStream>>readInstance
| | 2.1% {5443ms} OrderedCollection(Object)>>readDataFrom:size:
| | 2.1% {5443ms} DataStream>>next
| | 2.1% {5443ms} DataStream>>readArray
| | 2.1% {5443ms} DataStream>>next
| | 2.1% {5443ms} DataStream>>readInstance
| 3.1% {8035ms} MCHttpRepository>>versionReaderForFileNamed:
| 3.1% {8035ms} MCHttpRepository(MCFileBasedRepository)>>versionReaderForFileNamed:do:
| 3.1% {8035ms} MCHttpRepository>>readStreamForFileNamed:do:
| 3.1% {8035ms} HTTPSocket class>>httpGet:args:user:passwd:
| 3.1% {8035ms} HTTPSocket class>>httpGet:args:accept:request:
| 3.1% {8035ms} HTTPSocket class>>httpGetDocument:args:accept:request:
2.6% {6739ms} SystemProgressMorph>>label:min:max:
2.5% {6480ms} PasteUpMorph>>displayWorld
2.5% {6480ms} PasteUpMorph>>privateOuterDisplayWorld
2.5% {6480ms} WorldState>>displayWorld:submorphs:
2.5% {6480ms} WorldState>>drawWorld:submorphs:invalidAreasOn:
2.3% {5962ms} FormCanvas(Canvas)>>fullDrawMorph:
2.3% {5962ms} FormCanvas(Canvas)>>fullDraw:
2.3% {5962ms} SystemWindow(Morph)>>fullDrawOn:
**Leaves**
17.8% {46137ms} Array(SequenceableCollection)>>indexOf:startingAt:ifAbsent:
17.6% {45619ms} ByteSymbol(Symbol)>>=
11.7% {30326ms} Delay>>wait
3.7% {9590ms} Semaphore>>waitTimeoutMSecs:
3.4% {8813ms} String class>>stringHash:initialHash:
**Memory**
old +7,310,188 bytes
young -3,004,508 bytes
used +4,305,680 bytes
free +2,914,712 bytes
**GCs**
full 28 totalling 15,294ms (6.0% uptime), avg 546.0ms
incr 10826 totalling 23,621ms (9.0% uptime), avg 2.0ms
tenures 119 (avg 90 GCs/tenure)
root table 0 overflows
More information about the Squeak-dev mailing list |