[IAEP] fixing etoys
Yoshiki Ohshima
yoshiki at vpri.org
Wed Jun 25 07:22:01 CEST 2008
> Yoshiki Ohshima wrote:
> > Again, start up time is not a problem. Etoys start up looks a bit
> > slow on XO, but that is because the DBus communication that has to be
> > done.
>
> I frequently hear DBus being accused of latency. As badly
> implemented as it might be, I can't believe a daemon relaying
> a bunch of bytes over a UNIX domain socket can introduce more
> than 1ms of lag per message, even on a very slow processor.
>
> Has anybody ever analyzed the actual DBus traffic? With timings?
> How many messages are we talking about?
It seems that you are right! I took profile data in Etoys and the
DBus part accounts for about 60-70ms on start up. Other 3 seconds are
spent on Squeak part and I think I could speed them up a bit.
The following two message tallys are taken from two different part
of code upon start up. They should cover most of it.
Sorry for the false alerm.
-- Yoshiki
------------------------------------------------------
- 1761 tallies, 2164 msec.
**Tree**
95.3% {2062ms} SystemDictionary>>send:toClassesNamedIn:with:
|43.2% {935ms} Delay class(Behavior)>>startUp:
| |17.0% {368ms} SecurityManager class>>startUp
| | |17.0% {368ms} SecurityManager>>startUp
| | | 17.0% {368ms} SecurityManager>>loadSecurityKeys
| | | 16.8% {364ms} Object class>>readFrom:
| | | 10.6% {229ms} Array(Object)>>isKindOf:
| | | 6.2% {134ms} Compiler class>>evaluate:
| | | 6.2% {134ms} Compiler class>>evaluate:for:logged:
| | | 6.2% {134ms} Compiler class>>evaluate:for:notifying:logged:
| | | 6.2% {134ms} Compiler>>evaluate:in:to:notifying:ifFail:logged:
| | | 6.0% {130ms} Compiler>>translate:noPattern:ifFail:
| | | 6.0% {130ms} Parser>>parse:class:noPattern:context:notifying:ifFail:
| | | 4.7% {102ms} Parser>>init:notifying:failBlock:
| | | 4.7% {102ms} Parser(Scanner)>>scan:
| | | 4.7% {102ms} Parser(Scanner)>>scanToken
| | | 4.7% {102ms} Parser(Scanner)>>xLitQuote
| | | 4.7% {102ms} Parser(Scanner)>>scanToken
[4.7% {102ms} Parser(Scanner)>>xLitQuote
[ 2.4% {52ms} Parser(Scanner)>>scanToken
[ |2.4% {52ms} Parser(Scanner)>>xLitQuote
[ 2.3% {50ms} Parser(Scanner)>>scanLitVec
[ 2.3% {50ms} Parser(Scanner)>>scanToken
[ 2.3% {50ms} Parser(Scanner)>>xLitQuote
| |14.2% {307ms} FileDirectory class>>startUp
| | |9.7% {210ms} FileDirectory class>>setDefaultDirectory:
| | | |9.4% {203ms} FilePath class>>pathName:
| | | | 9.4% {203ms} FilePath class>>pathName:isEncoded:
| | | | 9.4% {203ms} FilePath>>pathName:isEncoded:
| | | | 9.4% {203ms} LanguageEnvironment class>>defaultFileNameConverter
| | | | 9.4% {203ms} SystemDictionary>>platformName
| | | | 9.4% {203ms} SystemDictionary>>getSystemAttribute:
| | | | 9.4% {203ms} SystemDictionary(Object)>>deprecated:block:
| | | | 9.4% {203ms} Preferences class>>showDeprecationWarnings
| | | | 9.4% {203ms} Preferences class>>valueOfFlag:ifAbsent:
| | |3.1% {67ms} SmalltalkImage>>openSourceFiles
| | | 3.0% {65ms} FileDirectory class>>openSources:andChanges:forImage:
| | | 2.6% {56ms} FileDirectory class>>openSources:forImage:
| |7.3% {158ms} ExternalSettings class>>startUp
| | |7.3% {158ms} ExternalSettings class>>preferenceDirectory
| | | 6.2% {134ms} SmalltalkImage>>vmPath
| | | 6.2% {134ms} FilePath class>>pathName:isEncoded:
| | | 6.2% {134ms} FilePath>>pathName:isEncoded:
| | | 6.2% {134ms} ByteString(String)>>convertFromWithConverter:
| |3.8% {82ms} Delay class>>startUp
|34.4% {744ms} WeakArray class>>startUp:
| |34.4% {744ms} WeakArray class>>restartFinalizationProcess
| | 34.2% {740ms} Semaphore class>>forMutualExclusion
|13.0% {281ms} AutoStart class>>startUp:
| |7.4% {160ms} AutoStart class>>checkForPluginUpdate
| | |7.4% {160ms} PasteUpMorph>>install
| | | 6.2% {134ms} PasteUpMorph>>installFlaps
| | | 4.8% {104ms} Project>>assureFlapIntegrity
| | | 4.8% {104ms} IdentityDictionary(Dictionary)>>removeKey:ifAbsent:
| |5.6% {121ms} AutoStart class>>checkForUpdates
| | 5.6% {121ms} PasteUpMorph>>install
| | 3.5% {76ms} PasteUpMorph>>displayWorldSafely
| | |3.5% {76ms} WorldState>>displayWorldSafely:
| | | 3.5% {76ms} PasteUpMorph>>displayWorld
| | | 3.5% {76ms} PasteUpMorph>>privateOuterDisplayWorld
| | | 3.5% {76ms} WorldState>>displayWorld:submorphs:
| | | 3.5% {76ms} WorldState>>drawWorld:submorphs:invalidAreasOn:
| | | 3.5% {76ms} FormCanvas(Canvas)>>fullDrawMorph:
| | | 3.5% {76ms} FormCanvas(Canvas)>>fullDraw:
| | | 3.5% {76ms} SugarNavTab(Morph)>>fullDrawOn:
| | | 3.5% {76ms} SugarNavTab(Morph)>>drawSubmorphsOn:
| | | 3.5% {76ms} FormCanvas(Canvas)>>fullDrawMorph:
| | | 3.5% {76ms} FormCanvas(Canvas)>>fullDraw:
| | | 2.3% {50ms} SugarNavigatorBar(AlignmentMorphBob1)>>fullDrawOn:
[2.3% {50ms} SugarNavigatorBar(Morph)>>fullDrawOn:
| | 2.2% {48ms} PasteUpMorph>>installFlaps
|4.7% {102ms} NaturalLanguageTranslator class>>startUp:
| 4.7% {102ms} NaturalLanguageTranslator class>>privateStartUp
| 2.8% {61ms} GetTextTranslator class>>privateStartUp
| 2.7% {58ms} GetTextTranslator class>>availableLanguageLocaleIDs
4.7% {102ms} RenamedEvent class(AbstractEvent class)>>eventSelectorBlock
4.7% {102ms} ByteString(SequenceableCollection)>>,
4.7% {102ms} ByteString(SequenceableCollection)>>copyReplaceFrom:to:with:
4.7% {102ms} ByteString class(String class)>>new:
**Leaves**
34.2% {740ms} Semaphore class>>forMutualExclusion
10.6% {229ms} Array(Object)>>isKindOf:
9.4% {203ms} Preferences class>>valueOfFlag:ifAbsent:
6.5% {141ms} ByteString(String)>>convertFromWithConverter:
5.2% {113ms} ByteString class(String class)>>new:
4.8% {104ms} IdentityDictionary(Dictionary)>>removeKey:ifAbsent:
3.8% {82ms} Delay class>>startUp
**Memory**
old +2,110,620 bytes
young +23,448 bytes
used +2,134,068 bytes
free -16,362,732 bytes
**GCs**
full 1 totalling 602ms (28.0% uptime), avg 602.0ms
incr 13 totalling 76ms (4.0% uptime), avg 6.0ms
tenures 1 (avg 13 GCs/tenure)
root table 0 overflows
------------------------------------------------------
- 180 tallies, 196 msec.
**Tree**
65.0% {127ms} SugarLauncher>>joinSharedActivity
|50.6% {99ms} Utilities class>>informUser:during:
| |38.9% {76ms} MVCMenuMorph>>displayAt:during:
| | |37.2% {73ms} PasteUpMorph>>displayWorld
| | | 37.2% {73ms} PasteUpMorph>>privateOuterDisplayWorld
| | | 37.2% {73ms} WorldState>>displayWorld:submorphs:
| | | 35.6% {70ms} WorldState>>drawWorld:submorphs:invalidAreasOn:
| | | 32.2% {63ms} FormCanvas(Canvas)>>fullDrawMorph:
| | | 32.2% {63ms} FormCanvas(Canvas)>>fullDraw:
| | | 32.2% {63ms} SystemWindow(Morph)>>fullDrawOn:
| | | 28.9% {57ms} SystemWindow(Morph)>>drawSubmorphsOn:
| | | |28.9% {57ms} FormCanvas(Canvas)>>fullDrawMorph:
| | | | 28.9% {57ms} FormCanvas(Canvas)>>fullDraw:
| | | | 26.1% {51ms} PluggableTextMorph(Morph)>>fullDrawOn:
| | | | |25.0% {49ms} PluggableTextMorph(Morph)>>drawSubmorphsOn:
| | | | | 25.0% {49ms} FormCanvas(Canvas)>>fullDrawMorph:
| | | | | 25.0% {49ms} FormCanvas(Canvas)>>fullDraw:
[25.0% {49ms} TransformMorph(Morph)>>fullDrawOn:
[ 8.9% {17ms} ScrollBar(Morph)>>drawSubmorphsOn:
[ |8.9% {17ms} FormCanvas(Canvas)>>fullDrawMorph:
[ | 8.9% {17ms} FormCanvas(Canvas)>>fullDraw:
[ | 8.9% {17ms} RectangleMorph(Morph)>>fullDrawOn:
[ | 4.4% {9ms} FormCanvas(Canvas)>>drawMorph:
[ | |4.4% {9ms} FormCanvas(Canvas)>>draw:
[ | | 2.8% {5ms} RectangleMorph(Morph)>>drawOn:
[ | | 2.8% {5ms} FormCanvas(Canvas)>>fillRectangle:fillStyle:borderStyle:
[ | | 2.8% {5ms} RaisedBorder(SimpleBorder)>>frameRectangle:on:
[ | | 2.8% {5ms} FormCanvas>>frameAndFillRectangle:fi...Color:bottomRightColor:
[ | 4.4% {9ms} FormCanvas(Canvas)>>roundCornersOf:during:
[ | 4.4% {9ms} FormCanvas>>roundCornersOf:in:during:
[ | 4.4% {9ms} SketchMorph(Morph)>>wantsRoundedCorners
[ | 4.4% {9ms} SketchMorph(Morph)>>cornerStyle
[ | 4.4% {9ms} SketchMorph(Morph)>>valueOfProperty:ifAbsent:
[ 7.2% {14ms} FormCanvas(Canvas)>>roundCornersOf:during:
[ |7.2% {14ms} FormCanvas>>roundCornersOf:in:during:
[ | 5.0% {10ms} CornerRounder class>>roundCornersOf:on:i...orderWidth:corners:
[ | 2.8% {5ms} CornerRounder>>tweakCornersOf:on:in:borderWidth:corners:
[ 3.3% {6ms} FormCanvas(Canvas)>>drawMorph:
[ |3.3% {6ms} FormCanvas(Canvas)>>draw:
[ 3.3% {6ms} IconicButton(Morph)>>drawMouseDownHighlightOn:
[ 3.3% {6ms} IconicButton(Morph)>>highlightedForMouseDown
| | | | 2.8% {5ms} SugarNavigatorBar(AlignmentMorphBob1)>>fullDrawOn:
| | | | 2.8% {5ms} SugarNavigatorBar(Morph)>>fullDrawOn:
| | | | 2.8% {5ms} SugarNavigatorBar(Morph)>>drawSubmorphsOn:
| | | | 2.8% {5ms} FormCanvas(Canvas)>>fullDrawMorph:
[2.8% {5ms} FormCanvas(Canvas)>>fullDraw:
[ 2.8% {5ms} Morph>>fullDrawOn:
[ 2.8% {5ms} Morph>>drawSubmorphsOn:
[ 2.8% {5ms} FormCanvas(Canvas)>>fullDrawMorph:
[ 2.8% {5ms} FormCanvas(Canvas)>>fullDraw:
[ 2.8% {5ms} VariableSpacer(Morph)>>fullDrawOn:
| | | 3.3% {6ms} FormCanvas(Canvas)>>drawMorph:
| | | 3.3% {6ms} FormCanvas(Canvas)>>draw:
| | | 3.3% {6ms} SystemWindow(Morph)>>drawOn:
| | | 3.3% {6ms} SystemWindow(Morph)>>fillStyle
| | | 3.3% {6ms} SystemWindow(Morph)>>valueOfProperty:ifAbsent:
| |11.7% {23ms} MVCMenuMorph class>>from:title:
| | 11.7% {23ms} MVCMenuMorph(MenuMorph)>>addTitle:
| | 11.7% {23ms} MVCMenuMorph(MenuMorph)>>addTitle:updatingSelector:updateTarget:
| | 11.7% {23ms} StringMorph>>font:
| | 11.7% {23ms} StringMorph>>font:emphasis:
| | 11.7% {23ms} StringMorph>>fitContents
| | 11.7% {23ms} StringMorph>>measureContents
| | 11.7% {23ms} TTCFont(AbstractFont)>>widthOfString:
| | 11.7% {23ms} TTCFont(AbstractFont)>>widthOfString:from:to:
| | 11.7% {23ms} TTCFont>>widthOf:
| | 11.7% {23ms} TTCFont>>computeForm:
| | 11.7% {23ms} TTGlyph>>asFormWithScale:ascender:...er:fgColor:bgColor:depth:
| | 11.7% {23ms} TTGlyph>>asFormWithScale:ascender:...Color:depth:replaceColor:
| | 9.4% {18ms} TTGlyph>>asFormWithScale:ascender:...:lingGlyphWidth:emphasis:
| | 6.1% {12ms} BalloonCanvas>>drawGeneralBezierShape...rderWidth:borderColor:
[3.9% {8ms} BalloonCanvas>>ensuredEngine
|14.4% {28ms} SugarPresence>>getActivityById:
| 14.4% {28ms} SugarPresence(DBusProxy)>>dbusPerform:interface:withArguments:
| 14.4% {28ms} DBus>>sendDBusMessage:
| 14.4% {28ms} DBus>>sendDBusMessage:timeout:
| 14.4% {28ms} DBus>>sendDBusMessage:timeout:onSuccess:onError:
| 14.4% {28ms} DBus>>sendMessage:timeout:
| 14.4% {28ms} DBus(DBusConnection)>>sendMessage:timeout:
| 14.4% {28ms} DBusMessageMethodCall(DBusMessage)>>serial:
16.7% {33ms} DBus class(DBusConnection class)>>sessionBus
|16.7% {33ms} DBus class(DBusConnection class)>>getBus:from:
| 16.7% {33ms} DBus>>startUp
| 16.7% {33ms} DBus>>restartMainloop
| 16.7% {33ms} BlockContext>>forkAt:named:
| 16.7% {33ms} Process>>resume
13.3% {26ms} SugarPresenceBuddy>>nick
|13.3% {26ms} SugarPresenceBuddy>>getProperties
| 13.3% {26ms} SugarPresenceBuddy(DBusProxy)>>dbusPerform:interface:
| 13.3% {26ms} SugarPresenceBuddy(DBusProxy)>>dbusPerform:interface:withArguments:
| 13.3% {26ms} DBus>>sendDBusMessage:
| 13.3% {26ms} DBus>>sendDBusMessage:timeout:
| 13.3% {26ms} DBus>>sendDBusMessage:timeout:onSuccess:onError:
| 13.3% {26ms} DBus>>sendMessage:timeout:
| 13.3% {26ms} DBus(DBusConnection)>>sendMessage:timeout:
| 13.3% {26ms} DBusMessageMethodCall(DBusMessage)>>serial:
3.9% {8ms} SugarPresence>>getOwner
3.9% {8ms} SugarPresence(DBusProxy)>>dbusPerform:interface:
3.9% {8ms} SugarPresence(DBusProxy)>>dbusPerform:interface:withArguments:
3.9% {8ms} DBus>>sendDBusMessage:
3.9% {8ms} DBus>>sendDBusMessage:timeout:
3.9% {8ms} DBus>>sendDBusMessage:timeout:onSuccess:onError:
3.9% {8ms} DBus>>sendMessage:timeout:
3.9% {8ms} DBus(DBusConnection)>>sendMessage:timeout:
3.9% {8ms} DBusMessageMethodCall(DBusMessage)>>serial:
**Leaves**
31.7% {62ms} DBusMessageMethodCall(DBusMessage)>>serial:
16.7% {33ms} Process>>resume
8.9% {17ms} SystemWindow(Morph)>>valueOfProperty:ifAbsent:
4.4% {9ms} Rectangle>>left
**Memory**
old +109,772 bytes
young -187,040 bytes
used -77,268 bytes
free +77,268 bytes
**GCs**
full 0 totalling 0ms (0.0% uptime)
incr 4 totalling 13ms (7.0% uptime), avg 3.0ms
tenures 1 (avg 4 GCs/tenure)
root table 0 overflows
More information about the Its.an.education.project
mailing list