[IAEP] fixing etoys

Yoshiki Ohshima yoshiki at vpri.org
Wed Jun 25 01:22:01 EDT 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 Devel mailing list