For the attached profile I downloaded a new pharo 20606 image and ran
the search for senders of #ifTrue: twice. It shows that it took 17
seconds on Ubuntu 13.04 64bit. How long does it take on your machine?
On 06/06/2013 11:27 PM, Marcus Denker wrote:
>
> On Jun 6, 2013, at 5:12 PM, Paul DeBruicker <[email protected]> wrote:
>
>> Hi Damien,
>>
>>
>> Because of the attached Message Tally outputs I don't think the problem
>> is specific to changes I've made to an image. I also don't think that
>> there is much differnece between Eliots vm or the pharo ppa vm. The
>> Message Tally outputs are from profiling the UI while finding the
>> senders of #setUp using various VM & image combinations. On squeak
>> finding the senders of #setUp seems instantaneous. On Pharo it takes
>> multiple seconds to find and display the senders.
>>
>
> This is really strange… here even doing "senders of" for all the >6000 senders
> of ifTrue: is quite fast for 2.0 and even faster in 3.0.
>
> So I really wonder what the problem is...
>
> Marcus
>
- 23840 tallies, 23876 msec.
**Tree**
--------------------------------
Process: other processes
--------------------------------
18.9% {4513ms} ProcessorScheduler class>>idleProcess
1.4% {337ms} WeakArray class>>finalizationProcess
1.3% {302ms} primitives
--------------------------------
Process: (40s) Morphic UI process: nil
--------------------------------
71.2% {16998ms} NautilusUI(AbstractNautilusUI)>>browseSendersOfMessages
71.2% {16998ms} NautilusUI(AbstractTool)>>browseSendersOfMessagesFrom:
70.5% {16821ms}
NautilusUI(AbstractTool)>>getSelectorAndSendQuery:to:with:selector:
70.5% {16821ms} SystemNavigation>>browseAllCallsOn:
70.5% {16821ms} SystemNavigation>>browseAllSendersOf:
34.2% {8160ms} OrderedCollection(Collection)>>asSortedCollection
|34.2% {8160ms} OrderedCollection(Object)>>as:
| 34.2% {8160ms} SortedCollection class(OrderedCollection
class)>>newFrom:
| 34.2% {8160ms} SortedCollection>>addAll:
| 34.2% {8160ms} SortedCollection>>reSort
| 34.2% {8160ms} SortedCollection>>sort:to:
| 34.2% {8160ms} SortedCollection>>defaultSort:to:
| 34.1% {8152ms} SortedCollection>>defaultSort:to:
| 34.1% {8134ms} SortedCollection>>defaultSort:to:
| 33.9% {8104ms} SortedCollection>>defaultSort:to:
| 33.6% {8024ms} SortedCollection>>defaultSort:to:
| 33.2% {7920ms}
SortedCollection>>defaultSort:to:
| 32.5% {7770ms}
SortedCollection>>defaultSort:to:
| 31.4% {7507ms}
SortedCollection>>defaultSort:to:
| |30.0% {7163ms}
SortedCollection>>defaultSort:to:
| | |27.3% {6520ms}
SortedCollection>>defaultSort:to:
| | | |22.5% {5376ms}
SortedCollection>>defaultSort:to:
| | | | |15.8% {3784ms}
SortedCollection>>defaultSort:to:
| | | | | |8.6% {2059ms}
SortedCollection>>defaultSort:to:
| | | | | | |4.7% {1122ms}
RGMethodDefinition>><=
| | | | | | | |4.1% {975ms}
RGMethodDefinition>>timeStamp
| | | | | | | | 3.0% {715ms}
RGMethodDefinition>>stamp
| | | | | | | | 2.9% {687ms}
CompiledMethod>>timeStamp
| | | | | | | | 1.9% {457ms}
CompiledMethod>>timeStampFromFile:
| | | | | | | | 1.7% {397ms}
Scanner>>scanTokens:
| | | | | | | | 1.6%
{375ms} Scanner>>scanLitVec
| | | | | | | | 1.5%
{349ms} Scanner>>scanToken
| | | | | | | | 1.4%
{326ms} Character>>asSymbol
| | | | | | | | 1.4%
{326ms} Symbol class>>internCharacter:
| | | | | | | |
1.4% {324ms} Symbol class>>intern:
| | | | | | | |
1.3% {320ms} Symbol class>>lookup:
| | | | | | | |
1.3% {320ms} WeakSet>>like:
| | | | | | | |
1.3% {320ms} WeakSet>>scanFor:
| | | | | | |3.9% {929ms}
SortedCollection>>defaultSort:to:
| | | | | | | 2.2% {533ms}
RGMethodDefinition>><=
| | | | | | | |1.9% {463ms}
RGMethodDefinition>>timeStamp
| | | | | | | | 1.5% {349ms}
RGMethodDefinition>>stamp
| | | | | | | | 1.4% {335ms}
CompiledMethod>>timeStamp
| | | | | | | 1.6% {393ms}
SortedCollection>>defaultSort:to:
| | | | | | | 1.1% {256ms}
RGMethodDefinition>><=
| | | | | |7.2% {1713ms}
RGMethodDefinition>><=
| | | | | | 6.2% {1484ms}
RGMethodDefinition>>timeStamp
| | | | | | 4.6% {1110ms}
RGMethodDefinition>>stamp
| | | | | | |4.4% {1060ms}
CompiledMethod>>timeStamp
| | | | | | | 2.9% {693ms}
CompiledMethod>>timeStampFromFile:
| | | | | | | |2.4% {583ms}
Scanner>>scanTokens:
| | | | | | | | 2.3% {549ms}
Scanner>>scanLitVec
| | | | | | | | 2.1%
{497ms} Scanner>>scanToken
| | | | | | | | 1.9%
{451ms} Character>>asSymbol
| | | | | | | | 1.9%
{451ms} Symbol class>>internCharacter:
| | | | | | | | 1.9%
{445ms} Symbol class>>intern:
| | | | | | | |
1.8% {437ms} Symbol class>>lookup:
| | | | | | | |
1.8% {437ms} WeakSet>>like:
| | | | | | | |
1.8% {437ms} WeakSet>>scanFor:
| | | | | | | 1.4% {326ms}
CompiledMethod>>sourceFileStreamIfAbsent:
| | | | | | | 1.4% {326ms}
CompiledMethod>>sourceFileStream
| | | | | | | 1.2% {292ms}
RemoteString>>fileStream
| | | | | | | 1.2% {288ms}
MultiByteFileStream(StandardFileStream)>>readOnlyCopy
| | | | | | | 1.2%
{286ms} MultiByteFileStream class(StandardFileStream class)>>readOnlyFileNamed:
| | | | | | 1.2% {276ms}
RGMethodDefinition class(RGElementDefinition class)>>parseTimestampFrom:default:
| | | | |6.6% {1572ms}
RGMethodDefinition>><=
| | | | | 5.7% {1370ms}
RGMethodDefinition>>timeStamp
| | | | | 4.3% {1016ms}
RGMethodDefinition>>stamp
| | | | | |3.9% {937ms}
CompiledMethod>>timeStamp
| | | | | | 2.6% {631ms}
CompiledMethod>>timeStampFromFile:
| | | | | | |2.3% {545ms}
Scanner>>scanTokens:
| | | | | | | 2.1% {505ms}
Scanner>>scanLitVec
| | | | | | | 1.9% {453ms}
Scanner>>scanToken
| | | | | | | 1.7% {411ms}
Character>>asSymbol
| | | | | | | 1.7%
{411ms} Symbol class>>internCharacter:
| | | | | | | 1.7%
{407ms} Symbol class>>intern:
| | | | | | | 1.6%
{391ms} Symbol class>>lookup:
| | | | | | | 1.6%
{391ms} WeakSet>>like:
| | | | | | |
1.6% {391ms} WeakSet>>scanFor:
| | | | | | |
1.0% {244ms} ByteSymbol(Symbol)>>=
| | | | | | 1.1% {274ms}
CompiledMethod>>sourceFileStreamIfAbsent:
| | | | | | 1.1% {272ms}
CompiledMethod>>sourceFileStream
| | | | | | 1.0% {250ms}
RemoteString>>fileStream
| | | | | | 1.0% {248ms}
MultiByteFileStream(StandardFileStream)>>readOnlyCopy
| | | | | | 1.0% {246ms}
MultiByteFileStream class(StandardFileStream class)>>readOnlyFileNamed:
| | | | | 1.2% {278ms}
RGMethodDefinition class(RGElementDefinition class)>>parseTimestampFrom:default:
| | | |4.7% {1134ms}
RGMethodDefinition>><=
| | | | 4.2% {993ms}
RGMethodDefinition>>timeStamp
| | | | 3.1% {751ms}
RGMethodDefinition>>stamp
| | | | 2.9% {701ms}
CompiledMethod>>timeStamp
| | | | 2.0% {485ms}
CompiledMethod>>timeStampFromFile:
| | | | 1.6% {389ms}
Scanner>>scanTokens:
| | | | 1.6% {379ms}
Scanner>>scanLitVec
| | | | 1.5% {351ms}
Scanner>>scanToken
| | | | 1.3% {316ms}
Character>>asSymbol
| | | | 1.3% {316ms}
Symbol class>>internCharacter:
| | | | 1.3% {306ms}
Symbol class>>intern:
| | | | 1.3%
{298ms} Symbol class>>lookup:
| | | | 1.3%
{298ms} WeakSet>>like:
| | | | 1.3%
{298ms} WeakSet>>scanFor:
| | |2.7% {633ms} RGMethodDefinition>><=
| | | 2.2% {519ms}
RGMethodDefinition>>timeStamp
| | | 1.6% {391ms}
RGMethodDefinition>>stamp
| | | 1.5% {369ms}
CompiledMethod>>timeStamp
| |1.4% {345ms} RGMethodDefinition>><=
| | 1.1% {270ms}
RGMethodDefinition>>timeStamp
| 1.1% {256ms} RGMethodDefinition>><=
29.4% {7013ms} SystemNavigation>>openBrowserFor:withMethods:
|29.4% {7013ms} SystemNavigation>>browseMessageList:name:autoSelect:
| 28.0% {6684ms} MessageBrowser
class>>openMessageList:name:autoSelect:
| |19.7% {4715ms} MessageBrowser class>>browseSenders:of:named:
| | |19.7% {4709ms} MessageBrowser>>messages:
| | | 16.4% {3924ms}
MessageBrowser>>sortClassesInCachedHierarchy:b:
| | | |6.9% {1648ms} ByteSymbol(Object)>>name
| | | | |6.6% {1582ms} ByteSymbol(Object)>>printString
| | | | | 6.6% {1582ms}
ByteSymbol(Object)>>printStringLimitedTo:
| | | | | 6.4% {1528ms} ByteSymbol(String)>>printOn:
| | | | | 6.4% {1528ms} ByteSymbol(Symbol)>>storeOn:
| | | | | 5.9% {1408ms}
LimitedWriteStream>>nextPutAll:
| | | | | 5.9% {1406ms}
LimitedWriteStream(WriteStream)>>nextPutAll:
| | | | | 5.8% {1396ms}
LimitedWriteStream(Stream)>>nextPutAll:
| | | | | 5.6% {1336ms} primitives
| | | |3.5% {845ms} Morph class(Class)>>name
| | | |3.3% {783ms} ByteString(String)>>compare:
| | | | |1.9% {457ms}
ByteSymbol(String)>>compare:caseSensitive:
| | | | |1.4% {326ms} primitives
| | | |2.0% {469ms} SmallInteger(ProtoObject)>>~~
| | | 3.2% {761ms} MessageBrowser>>cacheHierarchyForClasses:
| | | 3.2% {761ms} MessageBrowser>>buildHierarchyForMessages:
| | | 1.3% {310ms} Set>>includes:
| | | 1.1% {252ms}
Set(HashedCollection)>>findElementOrNil:
| | | 1.1% {252ms} Set>>scanFor:
| |8.2% {1967ms} MessageBrowser>>openWithSpec
| | 8.2% {1965ms} MessageBrowser(ComposableModel)>>openWithSpec
| | 8.2% {1963ms}
MessageBrowser(ComposableModel)>>openWithSpec:
| | 8.2% {1961ms} WindowModel>>openWithSpec:
| | 6.3% {1498ms} WindowModel>>buildWithSpec:
| | |6.1% {1466ms} WindowModel>>addModelIn:withSpec:
| | | 5.9% {1408ms}
MessageBrowser(ComposableModel)>>buildWithSpec:
| | | 5.4% {1296ms} SpecInterpreter
class>>buildWidgetFor:withSpec:
| | | 5.4% {1294ms} SpecInterpreter
class>>interpretASpec:model:
| | | 5.4% {1294ms} SpecInterpreter
class>>interpretASpec:model:superSpec:
| | | 5.4% {1294ms} SpecInterpreter
class>>private_interpretASpec:model:superSpec:
| | | 5.4% {1294ms}
SpecInterpreter>>interpretASpec:model:superSpec:
| | | 5.4% {1294ms}
SpecInterpreter>>interpretASpec:
| | | 5.4% {1292ms} SpecInterpreter
class>>private_interpretASpec:model:superSpec:
| | | 5.4% {1292ms}
SpecInterpreter>>interpretASpec:model:superSpec:
| | | 5.4% {1292ms}
SpecInterpreter>>interpretASpec:
| | | 5.4% {1290ms}
SpecInterpreter>>retreiveSpecFrom:
| | | 2.7% {647ms}
SpecInterpreter class>>private_interpretASpec:model:superSpec:
| | | |2.7% {647ms}
SpecInterpreter>>interpretASpec:model:superSpec:
| | | | 2.7% {647ms}
SpecInterpreter>>interpretASpec:
| | | | 2.7% {643ms}
SpecInterpreter class>>private_interpretASpec:model:superSpec:
| | | | 2.7% {643ms}
SpecInterpreter>>interpretASpec:model:superSpec:
| | | | 2.7% {643ms}
SpecInterpreter>>interpretASpec:
| | | | 2.7% {643ms}
SpecInterpreter>>retreiveSpecFrom:
| | | | 1.4%
{328ms} RawSpec>>defaultReceiver:model:
| | | | |1.4%
{328ms} SpecInterpreter class>>private_interpretASpec:model:
| | | | | 1.4%
{328ms} SpecInterpreter>>interpretASpec:model:
| | | | | 1.4%
{324ms} SpecInterpreter>>interpretASpec:model:superSpec:
| | | | |
1.4% {324ms} SpecInterpreter>>interpretASpec:
| | | | |
1.4% {324ms} MultiColumnListModel(ComposableModel)>>private_buildWithSpec
| | | | |
1.4% {322ms} MultiColumnListModel(ComposableModel)>>private_buildWithSpec:
| | | | |
1.3% {316ms} SpecInterpreter class>>private_buildWidgetFor:withSpec:
| | | | |
1.3% {314ms} SpecInterpreter class>>private_interpretASpec:model:
| | | | |
1.3% {314ms} SpecInterpreter>>interpretASpec:model:
| | | | |
1.3% {314ms} SpecInterpreter>>interpretASpec:model:superSpec:
| | | | |
1.3% {314ms} SpecInterpreter>>interpretASpec:
| | | | 1.3%
{312ms} SpecInterpreter class>>private_interpretASpec:model:superSpec:
| | | | 1.3%
{312ms} SpecInterpreter>>interpretASpec:model:superSpec:
| | | | 1.3%
{312ms} SpecInterpreter>>interpretASpec:
| | | | 1.3%
{310ms} MultiColumnListModel(ComposableModel)>>private_buildWithSpec
| | | |
1.3% {308ms} MultiColumnListModel(ComposableModel)>>private_buildWithSpec:
| | | |
1.3% {306ms} SpecInterpreter class>>private_buildWidgetFor:withSpec:
| | | |
1.3% {306ms} SpecInterpreter class>>private_interpretASpec:model:
| | | |
1.3% {306ms} SpecInterpreter>>interpretASpec:model:
| | | |
1.3% {300ms} SpecInterpreter>>interpretASpec:model:superSpec:
| | | |
1.3% {300ms} SpecInterpreter>>interpretASpec:
| | | 2.7% {643ms}
RawSpec>>defaultReceiver:model:
| | | 2.7% {643ms}
SpecInterpreter class>>private_interpretASpec:model:
| | | 2.7% {643ms}
SpecInterpreter>>interpretASpec:model:
| | | 2.7% {643ms}
SpecInterpreter>>interpretASpec:model:superSpec:
| | | 2.7% {643ms}
SpecInterpreter>>interpretASpec:
| | | 2.7% {641ms}
SpecInterpreter class>>private_interpretASpec:model:superSpec:
| | | 2.7% {641ms}
SpecInterpreter>>interpretASpec:model:superSpec:
| | | 2.7% {641ms}
SpecInterpreter>>interpretASpec:
| | | 2.7%
{637ms} SpecInterpreter>>retreiveSpecFrom:
| | | 1.3%
{320ms} SpecInterpreter class>>private_interpretASpec:model:superSpec:
| | | |1.3%
{320ms} SpecInterpreter>>interpretASpec:model:superSpec:
| | | |
1.3% {320ms} SpecInterpreter>>interpretASpec:
| | | |
1.3% {318ms} MultiColumnListModel(ComposableModel)>>private_buildWithSpec
| | | |
1.3% {314ms} MultiColumnListModel(ComposableModel)>>private_buildWithSpec:
| | | |
1.3% {314ms} SpecInterpreter class>>private_buildWidgetFor:withSpec:
| | | |
1.3% {314ms} SpecInterpreter class>>private_interpretASpec:model:
| | | |
1.3% {314ms} SpecInterpreter>>interpretASpec:model:
| | | |
1.3% {312ms} SpecInterpreter>>interpretASpec:model:superSpec:
| | | |
1.3% {312ms} SpecInterpreter>>interpretASpec:
| | | 1.3%
{316ms} RawSpec>>defaultReceiver:model:
| | | 1.3%
{316ms} SpecInterpreter class>>private_interpretASpec:model:
| | | 1.3%
{316ms} SpecInterpreter>>interpretASpec:model:
| | |
1.3% {316ms} SpecInterpreter>>interpretASpec:model:superSpec:
| | |
1.3% {316ms} SpecInterpreter>>interpretASpec:
| | |
1.3% {314ms} MultiColumnListModel(ComposableModel)>>private_buildWithSpec
| | |
1.3% {308ms} MultiColumnListModel(ComposableModel)>>private_buildWithSpec:
| | |
1.3% {306ms} SpecInterpreter class>>private_buildWidgetFor:withSpec:
| | |
1.3% {306ms} SpecInterpreter class>>private_interpretASpec:model:
| | |
1.3% {306ms} SpecInterpreter>>interpretASpec:model:
| | |
1.3% {306ms} SpecInterpreter>>interpretASpec:model:superSpec:
| | |
1.3% {306ms} SpecInterpreter>>interpretASpec:
| | 1.9% {461ms} StandardWindow(Morph)>>openInWorld
| | 1.9% {461ms}
StandardWindow(SystemWindow)>>openInWorld:
| | 1.1% {264ms} StandardWindow>>openAsIsIn:
| | 1.1% {262ms}
StandardWindow(SystemWindow)>>openAsIsIn:
| 1.3% {310ms} RGMethodDefinition>>isFromTrait
| 1.3% {308ms} RGMethodDefinition>>origin
6.9% {1648ms} SystemNavigation>>allCallsOn:
6.9% {1648ms} SystemNavigation>>allReferencesTo:
5.2% {1248ms}
Metaclass(Behavior)>>thoroughWhichSelectorsReferTo:special:byte:
|4.9% {1182ms} CompiledMethod>>refersToLiteral:
| 2.1% {497ms} Array>>refersToLiteral:
| |1.8% {425ms} primitives
| 1.6% {383ms} primitives
| 1.1% {272ms} ByteSymbol(Object)>>literalEqual:
| 1.1% {260ms} ByteSymbol(Symbol)>>=
1.3% {316ms} SystemNavigation>>createMethodNamed:realParent:
1.3% {316ms} RGMethodDefinition class>>realClass:selector:
1.1% {264ms} CompiledMethod>>asActiveRingDefinition
7.8% {1853ms} WorldState>>doOneCycleFor:
5.5% {1310ms} WorldState>>doOneCycleNowFor:
|3.4% {821ms} HandMorph>>processEvents
| |2.9% {699ms} HandMorph>>handleEvent:
| | 1.9% {461ms} HandMorph>>sendMouseEvent:
| | 1.9% {461ms} HandMorph>>sendEvent:focus:clear:
| | 1.7% {395ms} PasteUpMorph(Morph)>>processEvent:
| | 1.7% {395ms} PasteUpMorph>>processEvent:using:
| | 1.7% {395ms} PasteUpMorph(Morph)>>processEvent:using:
| | 1.6% {393ms} MorphicEventDispatcher>>dispatchEvent:with:
| | 1.6% {383ms}
MorphicEventDispatcher>>dispatchMouseDown:with:
| | 1.6% {383ms} NautilusWindow(Morph)>>processEvent:using:
| | 1.6% {383ms}
MorphicEventDispatcher>>dispatchEvent:with:
| | 1.6% {383ms}
MorphicEventDispatcher>>dispatchMouseDown:with:
| | 1.1% {264ms}
PluggableIconListMorph(Morph)>>processEvent:using:
| | 1.1% {264ms}
MorphicEventDispatcher>>dispatchEvent:with:
| | 1.1% {264ms}
MorphicEventDispatcher>>dispatchMouseDown:with:
| | 1.1% {264ms}
PluggableIconListMorph(Morph)>>handleEvent:
| | 1.1% {264ms} MouseButtonEvent>>sentTo:
| | 1.1% {264ms}
PluggableIconListMorph(Morph)>>handleMouseDown:
| | 1.1% {264ms}
PluggableIconListMorph(PluggableListMorph)>>mouseDown:
|2.0% {483ms} WorldState>>displayWorldSafely:
| 2.0% {483ms} PasteUpMorph>>displayWorld
| 2.0% {483ms} PasteUpMorph>>privateOuterDisplayWorld
| 2.0% {479ms} WorldState>>displayWorld:submorphs:
| 1.8% {435ms} WorldState>>drawWorld:submorphs:invalidAreasOn:
| 1.7% {415ms} FormCanvas(Canvas)>>fullDrawMorph:
| 1.7% {413ms} FormCanvas(Canvas)>>fullDraw:
| 1.7% {413ms} StandardWindow(Morph)>>fullDrawOn:
| 1.6% {375ms} StandardWindow(Morph)>>drawSubmorphsOn:
| 1.6% {373ms} FormCanvas(Canvas)>>fullDrawMorph:
| 1.6% {373ms} FormCanvas(Canvas)>>fullDraw:
| 1.6% {373ms} PanelMorph(Morph)>>fullDrawOn:
| 1.1% {260ms} PanelMorph(Morph)>>drawSubmorphsOn:
| 1.1% {258ms} FormCanvas(Canvas)>>fullDrawMorph:
| 1.1% {258ms} FormCanvas(Canvas)>>fullDraw:
| 1.1% {258ms} PanelMorph(Morph)>>fullDrawOn:
2.3% {543ms} WorldState>>interCyclePause:
2.3% {541ms} Delay>>wait
2.2% {533ms} primitives
**Leaves**
18.9% {4513ms} ProcessorScheduler class>>idleProcess
5.6% {1344ms} WriteStream(Stream)>>nextPutAll:
4.5% {1070ms} StringMorph(Object)>>=
3.6% {871ms} HelpHowToHelpTopicsFromCode class(Class)>>name
3.0% {717ms} ByteSymbol(String)>>compare:with:collated:
2.4% {571ms} UndefinedObject(ProtoObject)>>~~
2.3% {551ms} ByteSymbol(String)>>=
2.2% {533ms} Delay>>wait
2.1% {507ms} SystemDictionary(IdentityDictionary)>>scanFor:
2.0% {485ms} Array>>refersToLiteral:
1.8% {435ms} ByteSymbol(Symbol)>>=
1.6% {383ms} CompiledMethod>>refersToLiteral:
1.4% {330ms} String class>>compare:with:collated:
1.4% {326ms} ByteString(String)>>compare:
1.3% {302ms} WeakArray class>>finalizationProcess
1.2% {292ms} RGMethodDefinition(RGElementDefinition)>>parentName
**Memory**
old +3,904,924 bytes
young -489,728 bytes
used +3,415,196 bytes
free +988,004 bytes
**GCs**
full 0 totalling 0ms (0.0% uptime)
incr 157 totalling 334ms (1.0% uptime), avg 2.0ms
tenures 37 (avg 4 GCs/tenure)
root table 0 overflows
