Cycles lost on startup

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|

Cycles lost on startup

Eliot Miranda-2
Hi All,

    we are simulating a full block Pharo image derived from Pharo 6.  On startup we see a very sad loss of cycles due to a very slow rebuild of the selector table in Symbol class.  Why is this done at each startup?  Here is the stack:

  16r107154 M ByteString class(ProtoObject)>identityHash 16r786AE8: a(n) ByteString class
  16r10716C M ByteString class(Object)>hash 16r786AE8: a(n) ByteString class
  16r10718C M ByteSymbol(String)>hash 16rE6A5C8: a(n) ByteSymbol
  16r1071B0 M WeakSet>scanForEmptySlotFor: 16r26B968: a(n) WeakSet
  16r1071DC M WeakSet>noCheckNoGrowFillFrom: 16r26B968: a(n) WeakSet
  16r1071FC M WeakSet>growTo: 16r26B968: a(n) WeakSet
  16r10721C M WeakSet>grow 16r26B968: a(n) WeakSet
  16r107234 M WeakSet(HashedCollection)>fullCheck 16r26B968: a(n) WeakSet
  16r10724C M WeakSet(HashedCollection)>atNewIndex:put: 16r26B968: a(n) WeakSet
  16r107274 M WeakSet>add: 16r26B968: a(n) WeakSet
  16r107294 M [] in Symbol class>(nil) 16r1D319A8: a(n) Symbol class
  16r1072B8 M Array(SequenceableCollection)>do: 16r3C17370: a(n) Array
  16r1072E8 I CompiledMethod class(Behavior)>allInstancesDo: 16r164E260: a(n) CompiledMethod class
  16r10730C I Symbol class>initSelectorTable 16r1D319A8: a(n) Symbol class
  16r10732C I Symbol class>selectorTable 16r1D319A8: a(n) Symbol class
  16r107350 I Symbol class>internSelector: 16r1D319A8: a(n) Symbol class
  16r10737C I CompiledMethod>selector: 16r26AB58: a(n) CompiledMethod
  16r1073A4 I IRMethod>generate: 16r25A030: a(n) IRMethod
  16r1073CC I FFICalloutMethodBuilder>generateMethodFromSpec: 16r255580: a(n) FFICalloutMethodBuilder
  16r1073F0 I FFICalloutMethodBuilder>generate 16r255580: a(n) FFICalloutMethodBuilder
  16r1030C8 I FFICalloutMethodBuilder>build: 16r255580: a(n) FFICalloutMethodBuilder
  16r1030F4 I FFICalloutAPI>function:module: 16r255568: a(n) FFICalloutAPI
  16r10311C I UnixEnvironment(Object)>ffiCall:module: 16r3816180: a(n) UnixEnvironment
  16r103144 I UnixEnvironment(OSEnvironment)>getEnv: 16r3816180: a(n) UnixEnvironment
  16r103168 I UnixEnvironment(OSEnvironment)>at:ifAbsent: 16r3816180: a(n) UnixEnvironment
  16r10318C M [] in MacOSResolver>(nil) 16r241170: a(n) MacOSResolver
  16r1031A4 M FullBlockClosure(BlockClosure)>on:do: 16r2553F0: a(n) FullBlockClosure
  16r1031D0 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed:or: 16r241170: a(n) MacOSResolver
  16r1031F8 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed: 16r241170: a(n) MacOSResolver
  16r10321C I MacOSResolver>home 16r241170: a(n) MacOSResolver
  16r10323C I MacOSResolver>userLibrary 16r241170: a(n) MacOSResolver
  16r103254 M MacOSResolver>userApplicationSupport 16r241170: a(n) MacOSResolver
  16r10326C M MacOSResolver(FileSystemResolver)>resolve: 16r241170: a(n) MacOSResolver
  16r103288 M SystemResolver(FileSystemResolver)>unknownOrigin: 16r240D30: a(n) SystemResolver
  16r1032A4 M SystemResolver(FileSystemResolver)>resolve: 16r240D30: a(n) SystemResolver
  16r1032C4 M InteractiveResolver>unknownOrigin: 16r240CF0: a(n) InteractiveResolver
  16r1032E4 M [] in InteractiveResolver>(nil) 16r240CF0: a(n) InteractiveResolver
  16r103300 M IdentityDictionary(Dictionary)>at:ifAbsent: 16r240D00: a(n) IdentityDictionary
  16r103320 M InteractiveResolver>resolve: 16r240CF0: a(n) InteractiveResolver
  16r10333C M FileLocator>resolve 16r255258: a(n) FileLocator
  16r103354 M FileLocator(AbstractFileReference)>exists 16r255258: a(n) FileLocator
  16r10337C M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener
  16r103398 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener
  16r1033B0 M FullBlockClosure(BlockClosure)>on:do: 16r255190: a(n) FullBlockClosure
  16r1033D0 M FullBlockClosure(BlockClosure)>ifError: 16r255190: a(n) FullBlockClosure
  16r1033EC M PharoFilesOpener>ignoreIfFail: 16rE79FD8: a(n) PharoFilesOpener
  16r102188 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener
  16r1021AC M Array(SequenceableCollection)>do: 16r2495E8: a(n) Array
  16r1021DC I PharoFilesOpener>openSources:forImage: 16rE79FD8: a(n) PharoFilesOpener
  16r102204 I PharoFilesOpener>openSources 16rE79FD8: a(n) PharoFilesOpener
  16r102228 I PharoFilesOpener>sourcesFileOrNil 16rE79FD8: a(n) PharoFilesOpener
  16r10224C I SourceFileArray>ensureOpen 16r8AA128: a(n) SourceFileArray
  16r10226C I SmalltalkImage>openSourceFiles 16rA58A28: a(n) SmalltalkImage
  16r10228C I SmalltalkImage class>startUp: 16rFDA6A8: a(n) SmalltalkImage class
  16r1022A8 M ClassSessionHandler>startup: 16r8B8978: a(n) ClassSessionHandler
  16r1022C8 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession
  16r1022EC M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession
  16r102304 M FullBlockClosure(BlockClosure)>on:do: 16r245640: a(n) FullBlockClosure
  16r102328 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession
  16r10234C M Array(SequenceableCollection)>do: 16r1A47B8: a(n) Array
  16r102370 I WorkingSession>runList:do: 16r1A45D0: a(n) WorkingSession
  16r102398 I WorkingSession>runStartup: 16r1A45D0: a(n) WorkingSession
  16r1023BC I WorkingSession>start: 16r1A45D0: a(n) WorkingSession
  16r1023E8 I SessionManager>snapshot:andQuit: 16r17AA950: a(n) SessionManager

You'll see that Symbol class>selectorTable calls Symbol class> initSelectorTable which then calls CompiledMethod class(Behavior)>allInstancesDo: to enumerate over all methods.  This takes a significant amount of time, even on a fast machine.  For example, on a 2.%GHz machine this takes about 70 milliseconds.  That's a /lot/ of time to squander on startup.  And it will grow the larger the image is.

The selector table seems to be discarded on shut-down, which seems pointless.  If one wants to recompute the table then before or after methods are added or removed seems like a better choice, not on every image startup.

In around 2000 we were able to startup VisualWorks images in about 40 milliseconds on the hardware available at the time.  I hope someone reconsiders this code and a avoids recomputing the selector table on each startup.
_,,,^..^,,,_
best, Eliot
Reply | Threaded
Open this post in threaded view
|

Re: Cycles lost on startup

Nicolai Hess-3-2


2016-09-05 18:37 GMT+02:00 Eliot Miranda <[hidden email]>:
Hi All,

    we are simulating a full block Pharo image derived from Pharo 6.  On startup we see a very sad loss of cycles due to a very slow rebuild of the selector table in Symbol class.  Why is this done at each startup?  Here is the stack:

  16r107154 M ByteString class(ProtoObject)>identityHash 16r786AE8: a(n) ByteString class
  16r10716C M ByteString class(Object)>hash 16r786AE8: a(n) ByteString class
  16r10718C M ByteSymbol(String)>hash 16rE6A5C8: a(n) ByteSymbol
  16r1071B0 M WeakSet>scanForEmptySlotFor: 16r26B968: a(n) WeakSet
  16r1071DC M WeakSet>noCheckNoGrowFillFrom: 16r26B968: a(n) WeakSet
  16r1071FC M WeakSet>growTo: 16r26B968: a(n) WeakSet
  16r10721C M WeakSet>grow 16r26B968: a(n) WeakSet
  16r107234 M WeakSet(HashedCollection)>fullCheck 16r26B968: a(n) WeakSet
  16r10724C M WeakSet(HashedCollection)>atNewIndex:put: 16r26B968: a(n) WeakSet
  16r107274 M WeakSet>add: 16r26B968: a(n) WeakSet
  16r107294 M [] in Symbol class>(nil) 16r1D319A8: a(n) Symbol class
  16r1072B8 M Array(SequenceableCollection)>do: 16r3C17370: a(n) Array
  16r1072E8 I CompiledMethod class(Behavior)>allInstancesDo: 16r164E260: a(n) CompiledMethod class
  16r10730C I Symbol class>initSelectorTable 16r1D319A8: a(n) Symbol class
  16r10732C I Symbol class>selectorTable 16r1D319A8: a(n) Symbol class
  16r107350 I Symbol class>internSelector: 16r1D319A8: a(n) Symbol class
  16r10737C I CompiledMethod>selector: 16r26AB58: a(n) CompiledMethod
  16r1073A4 I IRMethod>generate: 16r25A030: a(n) IRMethod
  16r1073CC I FFICalloutMethodBuilder>generateMethodFromSpec: 16r255580: a(n) FFICalloutMethodBuilder
  16r1073F0 I FFICalloutMethodBuilder>generate 16r255580: a(n) FFICalloutMethodBuilder
  16r1030C8 I FFICalloutMethodBuilder>build: 16r255580: a(n) FFICalloutMethodBuilder
  16r1030F4 I FFICalloutAPI>function:module: 16r255568: a(n) FFICalloutAPI
  16r10311C I UnixEnvironment(Object)>ffiCall:module: 16r3816180: a(n) UnixEnvironment
  16r103144 I UnixEnvironment(OSEnvironment)>getEnv: 16r3816180: a(n) UnixEnvironment
  16r103168 I UnixEnvironment(OSEnvironment)>at:ifAbsent: 16r3816180: a(n) UnixEnvironment
  16r10318C M [] in MacOSResolver>(nil) 16r241170: a(n) MacOSResolver
  16r1031A4 M FullBlockClosure(BlockClosure)>on:do: 16r2553F0: a(n) FullBlockClosure
  16r1031D0 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed:or: 16r241170: a(n) MacOSResolver
  16r1031F8 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed: 16r241170: a(n) MacOSResolver
  16r10321C I MacOSResolver>home 16r241170: a(n) MacOSResolver
  16r10323C I MacOSResolver>userLibrary 16r241170: a(n) MacOSResolver
  16r103254 M MacOSResolver>userApplicationSupport 16r241170: a(n) MacOSResolver
  16r10326C M MacOSResolver(FileSystemResolver)>resolve: 16r241170: a(n) MacOSResolver
  16r103288 M SystemResolver(FileSystemResolver)>unknownOrigin: 16r240D30: a(n) SystemResolver
  16r1032A4 M SystemResolver(FileSystemResolver)>resolve: 16r240D30: a(n) SystemResolver
  16r1032C4 M InteractiveResolver>unknownOrigin: 16r240CF0: a(n) InteractiveResolver
  16r1032E4 M [] in InteractiveResolver>(nil) 16r240CF0: a(n) InteractiveResolver
  16r103300 M IdentityDictionary(Dictionary)>at:ifAbsent: 16r240D00: a(n) IdentityDictionary
  16r103320 M InteractiveResolver>resolve: 16r240CF0: a(n) InteractiveResolver
  16r10333C M FileLocator>resolve 16r255258: a(n) FileLocator
  16r103354 M FileLocator(AbstractFileReference)>exists 16r255258: a(n) FileLocator
  16r10337C M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener
  16r103398 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener
  16r1033B0 M FullBlockClosure(BlockClosure)>on:do: 16r255190: a(n) FullBlockClosure
  16r1033D0 M FullBlockClosure(BlockClosure)>ifError: 16r255190: a(n) FullBlockClosure
  16r1033EC M PharoFilesOpener>ignoreIfFail: 16rE79FD8: a(n) PharoFilesOpener
  16r102188 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener
  16r1021AC M Array(SequenceableCollection)>do: 16r2495E8: a(n) Array
  16r1021DC I PharoFilesOpener>openSources:forImage: 16rE79FD8: a(n) PharoFilesOpener
  16r102204 I PharoFilesOpener>openSources 16rE79FD8: a(n) PharoFilesOpener
  16r102228 I PharoFilesOpener>sourcesFileOrNil 16rE79FD8: a(n) PharoFilesOpener
  16r10224C I SourceFileArray>ensureOpen 16r8AA128: a(n) SourceFileArray
  16r10226C I SmalltalkImage>openSourceFiles 16rA58A28: a(n) SmalltalkImage
  16r10228C I SmalltalkImage class>startUp: 16rFDA6A8: a(n) SmalltalkImage class
  16r1022A8 M ClassSessionHandler>startup: 16r8B8978: a(n) ClassSessionHandler
  16r1022C8 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession
  16r1022EC M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession
  16r102304 M FullBlockClosure(BlockClosure)>on:do: 16r245640: a(n) FullBlockClosure
  16r102328 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession
  16r10234C M Array(SequenceableCollection)>do: 16r1A47B8: a(n) Array
  16r102370 I WorkingSession>runList:do: 16r1A45D0: a(n) WorkingSession
  16r102398 I WorkingSession>runStartup: 16r1A45D0: a(n) WorkingSession
  16r1023BC I WorkingSession>start: 16r1A45D0: a(n) WorkingSession
  16r1023E8 I SessionManager>snapshot:andQuit: 16r17AA950: a(n) SessionManager

You'll see that Symbol class>selectorTable calls Symbol class> initSelectorTable which then calls CompiledMethod class(Behavior)>allInstancesDo: to enumerate over all methods.  This takes a significant amount of time, even on a fast machine.  For example, on a 2.%GHz machine this takes about 70 milliseconds.  That's a /lot/ of time to squander on startup.  And it will grow the larger the image is.

Hm, I didn't thought about that.
 

The selector table seems to be discarded on shut-down, which seems pointless.  If one wants to recompute the table then before or after methods are added or removed seems like a better choice, not on every image startup.

I think I wanted to be on the save side and just discard on shutdown and rebuild on startup to be sure to have the correct set of selector symbols.

 

In around 2000 we were able to startup VisualWorks images in about 40 milliseconds on the hardware available at the time.  I hope someone reconsiders this code and a avoids recomputing the selector table on each startup.

I will take a look and try to find a better way.


nicolai
 
_,,,^..^,,,_
best, Eliot

Reply | Threaded
Open this post in threaded view
|

Re: Cycles lost on startup

EstebanLM

On 05 Sep 2016, at 19:52, Nicolai Hess <[hidden email]> wrote:



2016-09-05 18:37 GMT+02:00 Eliot Miranda <[hidden email]>:
Hi All,

    we are simulating a full block Pharo image derived from Pharo 6.  On startup we see a very sad loss of cycles due to a very slow rebuild of the selector table in Symbol class.  Why is this done at each startup?  Here is the stack:

  16r107154 M ByteString class(ProtoObject)>identityHash 16r786AE8: a(n) ByteString class
  16r10716C M ByteString class(Object)>hash 16r786AE8: a(n) ByteString class
  16r10718C M ByteSymbol(String)>hash 16rE6A5C8: a(n) ByteSymbol
  16r1071B0 M WeakSet>scanForEmptySlotFor: 16r26B968: a(n) WeakSet
  16r1071DC M WeakSet>noCheckNoGrowFillFrom: 16r26B968: a(n) WeakSet
  16r1071FC M WeakSet>growTo: 16r26B968: a(n) WeakSet
  16r10721C M WeakSet>grow 16r26B968: a(n) WeakSet
  16r107234 M WeakSet(HashedCollection)>fullCheck 16r26B968: a(n) WeakSet
  16r10724C M WeakSet(HashedCollection)>atNewIndex:put: 16r26B968: a(n) WeakSet
  16r107274 M WeakSet>add: 16r26B968: a(n) WeakSet
  16r107294 M [] in Symbol class>(nil) 16r1D319A8: a(n) Symbol class
  16r1072B8 M Array(SequenceableCollection)>do: 16r3C17370: a(n) Array
  16r1072E8 I CompiledMethod class(Behavior)>allInstancesDo: 16r164E260: a(n) CompiledMethod class
  16r10730C I Symbol class>initSelectorTable 16r1D319A8: a(n) Symbol class
  16r10732C I Symbol class>selectorTable 16r1D319A8: a(n) Symbol class
  16r107350 I Symbol class>internSelector: 16r1D319A8: a(n) Symbol class
  16r10737C I CompiledMethod>selector: 16r26AB58: a(n) CompiledMethod
  16r1073A4 I IRMethod>generate: 16r25A030: a(n) IRMethod
  16r1073CC I FFICalloutMethodBuilder>generateMethodFromSpec: 16r255580: a(n) FFICalloutMethodBuilder
  16r1073F0 I FFICalloutMethodBuilder>generate 16r255580: a(n) FFICalloutMethodBuilder
  16r1030C8 I FFICalloutMethodBuilder>build: 16r255580: a(n) FFICalloutMethodBuilder
  16r1030F4 I FFICalloutAPI>function:module: 16r255568: a(n) FFICalloutAPI
  16r10311C I UnixEnvironment(Object)>ffiCall:module: 16r3816180: a(n) UnixEnvironment
  16r103144 I UnixEnvironment(OSEnvironment)>getEnv: 16r3816180: a(n) UnixEnvironment
  16r103168 I UnixEnvironment(OSEnvironment)>at:ifAbsent: 16r3816180: a(n) UnixEnvironment
  16r10318C M [] in MacOSResolver>(nil) 16r241170: a(n) MacOSResolver
  16r1031A4 M FullBlockClosure(BlockClosure)>on:do: 16r2553F0: a(n) FullBlockClosure
  16r1031D0 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed:or: 16r241170: a(n) MacOSResolver
  16r1031F8 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed: 16r241170: a(n) MacOSResolver
  16r10321C I MacOSResolver>home 16r241170: a(n) MacOSResolver
  16r10323C I MacOSResolver>userLibrary 16r241170: a(n) MacOSResolver
  16r103254 M MacOSResolver>userApplicationSupport 16r241170: a(n) MacOSResolver
  16r10326C M MacOSResolver(FileSystemResolver)>resolve: 16r241170: a(n) MacOSResolver
  16r103288 M SystemResolver(FileSystemResolver)>unknownOrigin: 16r240D30: a(n) SystemResolver
  16r1032A4 M SystemResolver(FileSystemResolver)>resolve: 16r240D30: a(n) SystemResolver
  16r1032C4 M InteractiveResolver>unknownOrigin: 16r240CF0: a(n) InteractiveResolver
  16r1032E4 M [] in InteractiveResolver>(nil) 16r240CF0: a(n) InteractiveResolver
  16r103300 M IdentityDictionary(Dictionary)>at:ifAbsent: 16r240D00: a(n) IdentityDictionary
  16r103320 M InteractiveResolver>resolve: 16r240CF0: a(n) InteractiveResolver
  16r10333C M FileLocator>resolve 16r255258: a(n) FileLocator
  16r103354 M FileLocator(AbstractFileReference)>exists 16r255258: a(n) FileLocator
  16r10337C M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener
  16r103398 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener
  16r1033B0 M FullBlockClosure(BlockClosure)>on:do: 16r255190: a(n) FullBlockClosure
  16r1033D0 M FullBlockClosure(BlockClosure)>ifError: 16r255190: a(n) FullBlockClosure
  16r1033EC M PharoFilesOpener>ignoreIfFail: 16rE79FD8: a(n) PharoFilesOpener
  16r102188 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener
  16r1021AC M Array(SequenceableCollection)>do: 16r2495E8: a(n) Array
  16r1021DC I PharoFilesOpener>openSources:forImage: 16rE79FD8: a(n) PharoFilesOpener
  16r102204 I PharoFilesOpener>openSources 16rE79FD8: a(n) PharoFilesOpener
  16r102228 I PharoFilesOpener>sourcesFileOrNil 16rE79FD8: a(n) PharoFilesOpener
  16r10224C I SourceFileArray>ensureOpen 16r8AA128: a(n) SourceFileArray
  16r10226C I SmalltalkImage>openSourceFiles 16rA58A28: a(n) SmalltalkImage
  16r10228C I SmalltalkImage class>startUp: 16rFDA6A8: a(n) SmalltalkImage class
  16r1022A8 M ClassSessionHandler>startup: 16r8B8978: a(n) ClassSessionHandler
  16r1022C8 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession
  16r1022EC M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession
  16r102304 M FullBlockClosure(BlockClosure)>on:do: 16r245640: a(n) FullBlockClosure
  16r102328 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession
  16r10234C M Array(SequenceableCollection)>do: 16r1A47B8: a(n) Array
  16r102370 I WorkingSession>runList:do: 16r1A45D0: a(n) WorkingSession
  16r102398 I WorkingSession>runStartup: 16r1A45D0: a(n) WorkingSession
  16r1023BC I WorkingSession>start: 16r1A45D0: a(n) WorkingSession
  16r1023E8 I SessionManager>snapshot:andQuit: 16r17AA950: a(n) SessionManager

You'll see that Symbol class>selectorTable calls Symbol class> initSelectorTable which then calls CompiledMethod class(Behavior)>allInstancesDo: to enumerate over all methods.  This takes a significant amount of time, even on a fast machine.  For example, on a 2.%GHz machine this takes about 70 milliseconds.  That's a /lot/ of time to squander on startup.  And it will grow the larger the image is.

Hm, I didn't thought about that.

me neither. I think this is wrong behaviour… we need to check why it happens, but it smells bad.

Esteban

 

The selector table seems to be discarded on shut-down, which seems pointless.  If one wants to recompute the table then before or after methods are added or removed seems like a better choice, not on every image startup.

I think I wanted to be on the save side and just discard on shutdown and rebuild on startup to be sure to have the correct set of selector symbols.

 

In around 2000 we were able to startup VisualWorks images in about 40 milliseconds on the hardware available at the time.  I hope someone reconsiders this code and a avoids recomputing the selector table on each startup.

I will take a look and try to find a better way.


nicolai
 
_,,,^..^,,,_
best, Eliot

Reply | Threaded
Open this post in threaded view
|

Re: Cycles lost on startup

Henrik Nergaard
In reply to this post by Nicolai Hess-3-2

Rewriting the implementation of #initSelectorTable to:

 

SelectorTable := WeakSet withAll: (CompiledMethod allInstances collect: [:m | m selector] as: IdentitySet).

 

Makes it 20ms faster, so it looks like there is some overhead when using WeakSet compared to first use a normal set to remove duplicates.

 

Another possibility could be to store the selectors in an IdentityDictionary as #selector->count which keep track of how many users of a selector there is itself, instead of using a WeakArray.

 

Best regards,

Henrik

 

From: Pharo-dev [mailto:[hidden email]] On Behalf Of Nicolai Hess
Sent: Monday, September 5, 2016 7:52 PM
To: Pharo Development List <[hidden email]>
Subject: Re: [Pharo-dev] Cycles lost on startup

 

 

 

2016-09-05 18:37 GMT+02:00 Eliot Miranda <[hidden email]>:

Hi All,

 

    we are simulating a full block Pharo image derived from Pharo 6.  On startup we see a very sad loss of cycles due to a very slow rebuild of the selector table in Symbol class.  Why is this done at each startup?  Here is the stack:

 

  16r107154 M ByteString class(ProtoObject)>identityHash 16r786AE8: a(n) ByteString class

  16r10716C M ByteString class(Object)>hash 16r786AE8: a(n) ByteString class

  16r10718C M ByteSymbol(String)>hash 16rE6A5C8: a(n) ByteSymbol

  16r1071B0 M WeakSet>scanForEmptySlotFor: 16r26B968: a(n) WeakSet

  16r1071DC M WeakSet>noCheckNoGrowFillFrom: 16r26B968: a(n) WeakSet

  16r1071FC M WeakSet>growTo: 16r26B968: a(n) WeakSet

  16r10721C M WeakSet>grow 16r26B968: a(n) WeakSet

  16r107234 M WeakSet(HashedCollection)>fullCheck 16r26B968: a(n) WeakSet

  16r10724C M WeakSet(HashedCollection)>atNewIndex:put: 16r26B968: a(n) WeakSet

  16r107274 M WeakSet>add: 16r26B968: a(n) WeakSet

  16r107294 M [] in Symbol class>(nil) 16r1D319A8: a(n) Symbol class

  16r1072B8 M Array(SequenceableCollection)>do: 16r3C17370: a(n) Array

  16r1072E8 I CompiledMethod class(Behavior)>allInstancesDo: 16r164E260: a(n) CompiledMethod class

  16r10730C I Symbol class>initSelectorTable 16r1D319A8: a(n) Symbol class

  16r10732C I Symbol class>selectorTable 16r1D319A8: a(n) Symbol class

  16r107350 I Symbol class>internSelector: 16r1D319A8: a(n) Symbol class

  16r10737C I CompiledMethod>selector: 16r26AB58: a(n) CompiledMethod

  16r1073A4 I IRMethod>generate: 16r25A030: a(n) IRMethod

  16r1073CC I FFICalloutMethodBuilder>generateMethodFromSpec: 16r255580: a(n) FFICalloutMethodBuilder

  16r1073F0 I FFICalloutMethodBuilder>generate 16r255580: a(n) FFICalloutMethodBuilder

  16r1030C8 I FFICalloutMethodBuilder>build: 16r255580: a(n) FFICalloutMethodBuilder

  16r1030F4 I FFICalloutAPI>function:module: 16r255568: a(n) FFICalloutAPI

  16r10311C I UnixEnvironment(Object)>ffiCall:module: 16r3816180: a(n) UnixEnvironment

  16r103144 I UnixEnvironment(OSEnvironment)>getEnv: 16r3816180: a(n) UnixEnvironment

  16r103168 I UnixEnvironment(OSEnvironment)>at:ifAbsent: 16r3816180: a(n) UnixEnvironment

  16r10318C M [] in MacOSResolver>(nil) 16r241170: a(n) MacOSResolver

  16r1031A4 M FullBlockClosure(BlockClosure)>on:do: 16r2553F0: a(n) FullBlockClosure

  16r1031D0 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed:or: 16r241170: a(n) MacOSResolver

  16r1031F8 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed: 16r241170: a(n) MacOSResolver

  16r10321C I MacOSResolver>home 16r241170: a(n) MacOSResolver

  16r10323C I MacOSResolver>userLibrary 16r241170: a(n) MacOSResolver

  16r103254 M MacOSResolver>userApplicationSupport 16r241170: a(n) MacOSResolver

  16r10326C M MacOSResolver(FileSystemResolver)>resolve: 16r241170: a(n) MacOSResolver

  16r103288 M SystemResolver(FileSystemResolver)>unknownOrigin: 16r240D30: a(n) SystemResolver

  16r1032A4 M SystemResolver(FileSystemResolver)>resolve: 16r240D30: a(n) SystemResolver

  16r1032C4 M InteractiveResolver>unknownOrigin: 16r240CF0: a(n) InteractiveResolver

  16r1032E4 M [] in InteractiveResolver>(nil) 16r240CF0: a(n) InteractiveResolver

  16r103300 M IdentityDictionary(Dictionary)>at:ifAbsent: 16r240D00: a(n) IdentityDictionary

  16r103320 M InteractiveResolver>resolve: 16r240CF0: a(n) InteractiveResolver

  16r10333C M FileLocator>resolve 16r255258: a(n) FileLocator

  16r103354 M FileLocator(AbstractFileReference)>exists 16r255258: a(n) FileLocator

  16r10337C M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r103398 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r1033B0 M FullBlockClosure(BlockClosure)>on:do: 16r255190: a(n) FullBlockClosure

  16r1033D0 M FullBlockClosure(BlockClosure)>ifError: 16r255190: a(n) FullBlockClosure

  16r1033EC M PharoFilesOpener>ignoreIfFail: 16rE79FD8: a(n) PharoFilesOpener

  16r102188 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r1021AC M Array(SequenceableCollection)>do: 16r2495E8: a(n) Array

  16r1021DC I PharoFilesOpener>openSources:forImage: 16rE79FD8: a(n) PharoFilesOpener

  16r102204 I PharoFilesOpener>openSources 16rE79FD8: a(n) PharoFilesOpener

  16r102228 I PharoFilesOpener>sourcesFileOrNil 16rE79FD8: a(n) PharoFilesOpener

  16r10224C I SourceFileArray>ensureOpen 16r8AA128: a(n) SourceFileArray

  16r10226C I SmalltalkImage>openSourceFiles 16rA58A28: a(n) SmalltalkImage

  16r10228C I SmalltalkImage class>startUp: 16rFDA6A8: a(n) SmalltalkImage class

  16r1022A8 M ClassSessionHandler>startup: 16r8B8978: a(n) ClassSessionHandler

  16r1022C8 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r1022EC M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r102304 M FullBlockClosure(BlockClosure)>on:do: 16r245640: a(n) FullBlockClosure

  16r102328 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r10234C M Array(SequenceableCollection)>do: 16r1A47B8: a(n) Array

  16r102370 I WorkingSession>runList:do: 16r1A45D0: a(n) WorkingSession

  16r102398 I WorkingSession>runStartup: 16r1A45D0: a(n) WorkingSession

  16r1023BC I WorkingSession>start: 16r1A45D0: a(n) WorkingSession

  16r1023E8 I SessionManager>snapshot:andQuit: 16r17AA950: a(n) SessionManager

 

You'll see that Symbol class>selectorTable calls Symbol class> initSelectorTable which then calls CompiledMethod class(Behavior)>allInstancesDo: to enumerate over all methods.  This takes a significant amount of time, even on a fast machine.  For example, on a 2.%GHz machine this takes about 70 milliseconds.  That's a /lot/ of time to squander on startup.  And it will grow the larger the image is.

 

Hm, I didn't thought about that.

 

 

The selector table seems to be discarded on shut-down, which seems pointless.  If one wants to recompute the table then before or after methods are added or removed seems like a better choice, not on every image startup.

 

I think I wanted to be on the save side and just discard on shutdown and rebuild on startup to be sure to have the correct set of selector symbols.

 

 

In around 2000 we were able to startup VisualWorks images in about 40 milliseconds on the hardware available at the time.  I hope someone reconsiders this code and a avoids recomputing the selector table on each startup.

 

I will take a look and try to find a better way.

nicolai

 

_,,,^..^,,,_

best, Eliot

 

Reply | Threaded
Open this post in threaded view
|

Re: Cycles lost on startup

Nicolai Hess-3-2


2016-09-06 11:47 GMT+02:00 Henrik Nergaard <[hidden email]>:

Rewriting the implementation of #initSelectorTable to:

 

SelectorTable := WeakSet withAll: (CompiledMethod allInstances collect: [:m | m selector] as: IdentitySet).

 

Makes it 20ms faster, so it looks like there is some overhead when using WeakSet compared to first use a normal set to remove duplicates.

 

Another possibility could be to store the selectors in an IdentityDictionary as #selector->count which keep track of how many users of a selector there is itself, instead of using a WeakArray.

 

Best regards,

Henrik


Maybe we can just move the rebuilding to the image shutdown instead of the image startup ?

 

 

From: Pharo-dev [mailto:[hidden email]] On Behalf Of Nicolai Hess
Sent: Monday, September 5, 2016 7:52 PM
To: Pharo Development List <[hidden email]>
Subject: Re: [Pharo-dev] Cycles lost on startup

 

 

 

2016-09-05 18:37 GMT+02:00 Eliot Miranda <[hidden email]>:

Hi All,

 

    we are simulating a full block Pharo image derived from Pharo 6.  On startup we see a very sad loss of cycles due to a very slow rebuild of the selector table in Symbol class.  Why is this done at each startup?  Here is the stack:

 

  16r107154 M ByteString class(ProtoObject)>identityHash 16r786AE8: a(n) ByteString class

  16r10716C M ByteString class(Object)>hash 16r786AE8: a(n) ByteString class

  16r10718C M ByteSymbol(String)>hash 16rE6A5C8: a(n) ByteSymbol

  16r1071B0 M WeakSet>scanForEmptySlotFor: 16r26B968: a(n) WeakSet

  16r1071DC M WeakSet>noCheckNoGrowFillFrom: 16r26B968: a(n) WeakSet

  16r1071FC M WeakSet>growTo: 16r26B968: a(n) WeakSet

  16r10721C M WeakSet>grow 16r26B968: a(n) WeakSet

  16r107234 M WeakSet(HashedCollection)>fullCheck 16r26B968: a(n) WeakSet

  16r10724C M WeakSet(HashedCollection)>atNewIndex:put: 16r26B968: a(n) WeakSet

  16r107274 M WeakSet>add: 16r26B968: a(n) WeakSet

  16r107294 M [] in Symbol class>(nil) 16r1D319A8: a(n) Symbol class

  16r1072B8 M Array(SequenceableCollection)>do: 16r3C17370: a(n) Array

  16r1072E8 I CompiledMethod class(Behavior)>allInstancesDo: 16r164E260: a(n) CompiledMethod class

  16r10730C I Symbol class>initSelectorTable 16r1D319A8: a(n) Symbol class

  16r10732C I Symbol class>selectorTable 16r1D319A8: a(n) Symbol class

  16r107350 I Symbol class>internSelector: 16r1D319A8: a(n) Symbol class

  16r10737C I CompiledMethod>selector: 16r26AB58: a(n) CompiledMethod

  16r1073A4 I IRMethod>generate: 16r25A030: a(n) IRMethod

  16r1073CC I FFICalloutMethodBuilder>generateMethodFromSpec: 16r255580: a(n) FFICalloutMethodBuilder

  16r1073F0 I FFICalloutMethodBuilder>generate 16r255580: a(n) FFICalloutMethodBuilder

  16r1030C8 I FFICalloutMethodBuilder>build: 16r255580: a(n) FFICalloutMethodBuilder

  16r1030F4 I FFICalloutAPI>function:module: 16r255568: a(n) FFICalloutAPI

  16r10311C I UnixEnvironment(Object)>ffiCall:module: 16r3816180: a(n) UnixEnvironment

  16r103144 I UnixEnvironment(OSEnvironment)>getEnv: 16r3816180: a(n) UnixEnvironment

  16r103168 I UnixEnvironment(OSEnvironment)>at:ifAbsent: 16r3816180: a(n) UnixEnvironment

  16r10318C M [] in MacOSResolver>(nil) 16r241170: a(n) MacOSResolver

  16r1031A4 M FullBlockClosure(BlockClosure)>on:do: 16r2553F0: a(n) FullBlockClosure

  16r1031D0 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed:or: 16r241170: a(n) MacOSResolver

  16r1031F8 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed: 16r241170: a(n) MacOSResolver

  16r10321C I MacOSResolver>home 16r241170: a(n) MacOSResolver

  16r10323C I MacOSResolver>userLibrary 16r241170: a(n) MacOSResolver

  16r103254 M MacOSResolver>userApplicationSupport 16r241170: a(n) MacOSResolver

  16r10326C M MacOSResolver(FileSystemResolver)>resolve: 16r241170: a(n) MacOSResolver

  16r103288 M SystemResolver(FileSystemResolver)>unknownOrigin: 16r240D30: a(n) SystemResolver

  16r1032A4 M SystemResolver(FileSystemResolver)>resolve: 16r240D30: a(n) SystemResolver

  16r1032C4 M InteractiveResolver>unknownOrigin: 16r240CF0: a(n) InteractiveResolver

  16r1032E4 M [] in InteractiveResolver>(nil) 16r240CF0: a(n) InteractiveResolver

  16r103300 M IdentityDictionary(Dictionary)>at:ifAbsent: 16r240D00: a(n) IdentityDictionary

  16r103320 M InteractiveResolver>resolve: 16r240CF0: a(n) InteractiveResolver

  16r10333C M FileLocator>resolve 16r255258: a(n) FileLocator

  16r103354 M FileLocator(AbstractFileReference)>exists 16r255258: a(n) FileLocator

  16r10337C M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r103398 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r1033B0 M FullBlockClosure(BlockClosure)>on:do: 16r255190: a(n) FullBlockClosure

  16r1033D0 M FullBlockClosure(BlockClosure)>ifError: 16r255190: a(n) FullBlockClosure

  16r1033EC M PharoFilesOpener>ignoreIfFail: 16rE79FD8: a(n) PharoFilesOpener

  16r102188 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r1021AC M Array(SequenceableCollection)>do: 16r2495E8: a(n) Array

  16r1021DC I PharoFilesOpener>openSources:forImage: 16rE79FD8: a(n) PharoFilesOpener

  16r102204 I PharoFilesOpener>openSources 16rE79FD8: a(n) PharoFilesOpener

  16r102228 I PharoFilesOpener>sourcesFileOrNil 16rE79FD8: a(n) PharoFilesOpener

  16r10224C I SourceFileArray>ensureOpen 16r8AA128: a(n) SourceFileArray

  16r10226C I SmalltalkImage>openSourceFiles 16rA58A28: a(n) SmalltalkImage

  16r10228C I SmalltalkImage class>startUp: 16rFDA6A8: a(n) SmalltalkImage class

  16r1022A8 M ClassSessionHandler>startup: 16r8B8978: a(n) ClassSessionHandler

  16r1022C8 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r1022EC M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r102304 M FullBlockClosure(BlockClosure)>on:do: 16r245640: a(n) FullBlockClosure

  16r102328 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r10234C M Array(SequenceableCollection)>do: 16r1A47B8: a(n) Array

  16r102370 I WorkingSession>runList:do: 16r1A45D0: a(n) WorkingSession

  16r102398 I WorkingSession>runStartup: 16r1A45D0: a(n) WorkingSession

  16r1023BC I WorkingSession>start: 16r1A45D0: a(n) WorkingSession

  16r1023E8 I SessionManager>snapshot:andQuit: 16r17AA950: a(n) SessionManager

 

You'll see that Symbol class>selectorTable calls Symbol class> initSelectorTable which then calls CompiledMethod class(Behavior)>allInstancesDo: to enumerate over all methods.  This takes a significant amount of time, even on a fast machine.  For example, on a 2.%GHz machine this takes about 70 milliseconds.  That's a /lot/ of time to squander on startup.  And it will grow the larger the image is.

 

Hm, I didn't thought about that.

 

 

The selector table seems to be discarded on shut-down, which seems pointless.  If one wants to recompute the table then before or after methods are added or removed seems like a better choice, not on every image startup.

 

I think I wanted to be on the save side and just discard on shutdown and rebuild on startup to be sure to have the correct set of selector symbols.

 

 

In around 2000 we were able to startup VisualWorks images in about 40 milliseconds on the hardware available at the time.  I hope someone reconsiders this code and a avoids recomputing the selector table on each startup.

 

I will take a look and try to find a better way.

nicolai

 

_,,,^..^,,,_

best, Eliot

 


Reply | Threaded
Open this post in threaded view
|

Re: Cycles lost on startup

Eliot Miranda-2


On Sep 6, 2016, at 12:25 PM, Nicolai Hess <[hidden email]> wrote:



2016-09-06 11:47 GMT+02:00 Henrik Nergaard <[hidden email]>:

Rewriting the implementation of #initSelectorTable to:

 

SelectorTable := WeakSet withAll: (CompiledMethod allInstances collect: [:m | m selector] as: IdentitySet).

 

Makes it 20ms faster, so it looks like there is some overhead when using WeakSet compared to first use a normal set to remove duplicates.

 

Another possibility could be to store the selectors in an IdentityDictionary as #selector->count which keep track of how many users of a selector there is itself, instead of using a WeakArray.

 

Best regards,

Henrik


Maybe we can just move the rebuilding to the image shutdown instead of the image startup ?

That's a much better idea.  But only if the image snapshots.  There is no point doing it on an exit without saving.

And just to drive home the point, 70ms is an age in a web server.  This kind of thing really damages Pharo performance in web servers.  One wants startup times in the few tens of milliseconds or better.


 

 

From: Pharo-dev [mailto:[hidden email]] On Behalf Of Nicolai Hess
Sent: Monday, September 5, 2016 7:52 PM
To: Pharo Development List <[hidden email]>
Subject: Re: [Pharo-dev] Cycles lost on startup

 

 

 

2016-09-05 18:37 GMT+02:00 Eliot Miranda <[hidden email]>:

Hi All,

 

    we are simulating a full block Pharo image derived from Pharo 6.  On startup we see a very sad loss of cycles due to a very slow rebuild of the selector table in Symbol class.  Why is this done at each startup?  Here is the stack:

 

  16r107154 M ByteString class(ProtoObject)>identityHash 16r786AE8: a(n) ByteString class

  16r10716C M ByteString class(Object)>hash 16r786AE8: a(n) ByteString class

  16r10718C M ByteSymbol(String)>hash 16rE6A5C8: a(n) ByteSymbol

  16r1071B0 M WeakSet>scanForEmptySlotFor: 16r26B968: a(n) WeakSet

  16r1071DC M WeakSet>noCheckNoGrowFillFrom: 16r26B968: a(n) WeakSet

  16r1071FC M WeakSet>growTo: 16r26B968: a(n) WeakSet

  16r10721C M WeakSet>grow 16r26B968: a(n) WeakSet

  16r107234 M WeakSet(HashedCollection)>fullCheck 16r26B968: a(n) WeakSet

  16r10724C M WeakSet(HashedCollection)>atNewIndex:put: 16r26B968: a(n) WeakSet

  16r107274 M WeakSet>add: 16r26B968: a(n) WeakSet

  16r107294 M [] in Symbol class>(nil) 16r1D319A8: a(n) Symbol class

  16r1072B8 M Array(SequenceableCollection)>do: 16r3C17370: a(n) Array

  16r1072E8 I CompiledMethod class(Behavior)>allInstancesDo: 16r164E260: a(n) CompiledMethod class

  16r10730C I Symbol class>initSelectorTable 16r1D319A8: a(n) Symbol class

  16r10732C I Symbol class>selectorTable 16r1D319A8: a(n) Symbol class

  16r107350 I Symbol class>internSelector: 16r1D319A8: a(n) Symbol class

  16r10737C I CompiledMethod>selector: 16r26AB58: a(n) CompiledMethod

  16r1073A4 I IRMethod>generate: 16r25A030: a(n) IRMethod

  16r1073CC I FFICalloutMethodBuilder>generateMethodFromSpec: 16r255580: a(n) FFICalloutMethodBuilder

  16r1073F0 I FFICalloutMethodBuilder>generate 16r255580: a(n) FFICalloutMethodBuilder

  16r1030C8 I FFICalloutMethodBuilder>build: 16r255580: a(n) FFICalloutMethodBuilder

  16r1030F4 I FFICalloutAPI>function:module: 16r255568: a(n) FFICalloutAPI

  16r10311C I UnixEnvironment(Object)>ffiCall:module: 16r3816180: a(n) UnixEnvironment

  16r103144 I UnixEnvironment(OSEnvironment)>getEnv: 16r3816180: a(n) UnixEnvironment

  16r103168 I UnixEnvironment(OSEnvironment)>at:ifAbsent: 16r3816180: a(n) UnixEnvironment

  16r10318C M [] in MacOSResolver>(nil) 16r241170: a(n) MacOSResolver

  16r1031A4 M FullBlockClosure(BlockClosure)>on:do: 16r2553F0: a(n) FullBlockClosure

  16r1031D0 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed:or: 16r241170: a(n) MacOSResolver

  16r1031F8 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed: 16r241170: a(n) MacOSResolver

  16r10321C I MacOSResolver>home 16r241170: a(n) MacOSResolver

  16r10323C I MacOSResolver>userLibrary 16r241170: a(n) MacOSResolver

  16r103254 M MacOSResolver>userApplicationSupport 16r241170: a(n) MacOSResolver

  16r10326C M MacOSResolver(FileSystemResolver)>resolve: 16r241170: a(n) MacOSResolver

  16r103288 M SystemResolver(FileSystemResolver)>unknownOrigin: 16r240D30: a(n) SystemResolver

  16r1032A4 M SystemResolver(FileSystemResolver)>resolve: 16r240D30: a(n) SystemResolver

  16r1032C4 M InteractiveResolver>unknownOrigin: 16r240CF0: a(n) InteractiveResolver

  16r1032E4 M [] in InteractiveResolver>(nil) 16r240CF0: a(n) InteractiveResolver

  16r103300 M IdentityDictionary(Dictionary)>at:ifAbsent: 16r240D00: a(n) IdentityDictionary

  16r103320 M InteractiveResolver>resolve: 16r240CF0: a(n) InteractiveResolver

  16r10333C M FileLocator>resolve 16r255258: a(n) FileLocator

  16r103354 M FileLocator(AbstractFileReference)>exists 16r255258: a(n) FileLocator

  16r10337C M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r103398 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r1033B0 M FullBlockClosure(BlockClosure)>on:do: 16r255190: a(n) FullBlockClosure

  16r1033D0 M FullBlockClosure(BlockClosure)>ifError: 16r255190: a(n) FullBlockClosure

  16r1033EC M PharoFilesOpener>ignoreIfFail: 16rE79FD8: a(n) PharoFilesOpener

  16r102188 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r1021AC M Array(SequenceableCollection)>do: 16r2495E8: a(n) Array

  16r1021DC I PharoFilesOpener>openSources:forImage: 16rE79FD8: a(n) PharoFilesOpener

  16r102204 I PharoFilesOpener>openSources 16rE79FD8: a(n) PharoFilesOpener

  16r102228 I PharoFilesOpener>sourcesFileOrNil 16rE79FD8: a(n) PharoFilesOpener

  16r10224C I SourceFileArray>ensureOpen 16r8AA128: a(n) SourceFileArray

  16r10226C I SmalltalkImage>openSourceFiles 16rA58A28: a(n) SmalltalkImage

  16r10228C I SmalltalkImage class>startUp: 16rFDA6A8: a(n) SmalltalkImage class

  16r1022A8 M ClassSessionHandler>startup: 16r8B8978: a(n) ClassSessionHandler

  16r1022C8 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r1022EC M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r102304 M FullBlockClosure(BlockClosure)>on:do: 16r245640: a(n) FullBlockClosure

  16r102328 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r10234C M Array(SequenceableCollection)>do: 16r1A47B8: a(n) Array

  16r102370 I WorkingSession>runList:do: 16r1A45D0: a(n) WorkingSession

  16r102398 I WorkingSession>runStartup: 16r1A45D0: a(n) WorkingSession

  16r1023BC I WorkingSession>start: 16r1A45D0: a(n) WorkingSession

  16r1023E8 I SessionManager>snapshot:andQuit: 16r17AA950: a(n) SessionManager

 

You'll see that Symbol class>selectorTable calls Symbol class> initSelectorTable which then calls CompiledMethod class(Behavior)>allInstancesDo: to enumerate over all methods.  This takes a significant amount of time, even on a fast machine.  For example, on a 2.%GHz machine this takes about 70 milliseconds.  That's a /lot/ of time to squander on startup.  And it will grow the larger the image is.

 

Hm, I didn't thought about that.

 

 

The selector table seems to be discarded on shut-down, which seems pointless.  If one wants to recompute the table then before or after methods are added or removed seems like a better choice, not on every image startup.

 

I think I wanted to be on the save side and just discard on shutdown and rebuild on startup to be sure to have the correct set of selector symbols.

 

 

In around 2000 we were able to startup VisualWorks images in about 40 milliseconds on the hardware available at the time.  I hope someone reconsiders this code and a avoids recomputing the selector table on each startup.

 

I will take a look and try to find a better way.

nicolai

 

_,,,^..^,,,_

best, Eliot

 


Reply | Threaded
Open this post in threaded view
|

Re: Cycles lost on startup

philippeback
Very interesting, especially with ephemeral runs.

Phil

On Tue, Sep 6, 2016 at 12:34 PM, Eliot Miranda <[hidden email]> wrote:


On Sep 6, 2016, at 12:25 PM, Nicolai Hess <[hidden email]> wrote:



2016-09-06 11:47 GMT+02:00 Henrik Nergaard <[hidden email]>:

Rewriting the implementation of #initSelectorTable to:

 

SelectorTable := WeakSet withAll: (CompiledMethod allInstances collect: [:m | m selector] as: IdentitySet).

 

Makes it 20ms faster, so it looks like there is some overhead when using WeakSet compared to first use a normal set to remove duplicates.

 

Another possibility could be to store the selectors in an IdentityDictionary as #selector->count which keep track of how many users of a selector there is itself, instead of using a WeakArray.

 

Best regards,

Henrik


Maybe we can just move the rebuilding to the image shutdown instead of the image startup ?

That's a much better idea.  But only if the image snapshots.  There is no point doing it on an exit without saving.

And just to drive home the point, 70ms is an age in a web server.  This kind of thing really damages Pharo performance in web servers.  One wants startup times in the few tens of milliseconds or better.


 

 

From: Pharo-dev [mailto:[hidden email]] On Behalf Of Nicolai Hess
Sent: Monday, September 5, 2016 7:52 PM
To: Pharo Development List <[hidden email]>
Subject: Re: [Pharo-dev] Cycles lost on startup

 

 

 

2016-09-05 18:37 GMT+02:00 Eliot Miranda <[hidden email]>:

Hi All,

 

    we are simulating a full block Pharo image derived from Pharo 6.  On startup we see a very sad loss of cycles due to a very slow rebuild of the selector table in Symbol class.  Why is this done at each startup?  Here is the stack:

 

  16r107154 M ByteString class(ProtoObject)>identityHash 16r786AE8: a(n) ByteString class

  16r10716C M ByteString class(Object)>hash 16r786AE8: a(n) ByteString class

  16r10718C M ByteSymbol(String)>hash 16rE6A5C8: a(n) ByteSymbol

  16r1071B0 M WeakSet>scanForEmptySlotFor: 16r26B968: a(n) WeakSet

  16r1071DC M WeakSet>noCheckNoGrowFillFrom: 16r26B968: a(n) WeakSet

  16r1071FC M WeakSet>growTo: 16r26B968: a(n) WeakSet

  16r10721C M WeakSet>grow 16r26B968: a(n) WeakSet

  16r107234 M WeakSet(HashedCollection)>fullCheck 16r26B968: a(n) WeakSet

  16r10724C M WeakSet(HashedCollection)>atNewIndex:put: 16r26B968: a(n) WeakSet

  16r107274 M WeakSet>add: 16r26B968: a(n) WeakSet

  16r107294 M [] in Symbol class>(nil) 16r1D319A8: a(n) Symbol class

  16r1072B8 M Array(SequenceableCollection)>do: 16r3C17370: a(n) Array

  16r1072E8 I CompiledMethod class(Behavior)>allInstancesDo: 16r164E260: a(n) CompiledMethod class

  16r10730C I Symbol class>initSelectorTable 16r1D319A8: a(n) Symbol class

  16r10732C I Symbol class>selectorTable 16r1D319A8: a(n) Symbol class

  16r107350 I Symbol class>internSelector: 16r1D319A8: a(n) Symbol class

  16r10737C I CompiledMethod>selector: 16r26AB58: a(n) CompiledMethod

  16r1073A4 I IRMethod>generate: 16r25A030: a(n) IRMethod

  16r1073CC I FFICalloutMethodBuilder>generateMethodFromSpec: 16r255580: a(n) FFICalloutMethodBuilder

  16r1073F0 I FFICalloutMethodBuilder>generate 16r255580: a(n) FFICalloutMethodBuilder

  16r1030C8 I FFICalloutMethodBuilder>build: 16r255580: a(n) FFICalloutMethodBuilder

  16r1030F4 I FFICalloutAPI>function:module: 16r255568: a(n) FFICalloutAPI

  16r10311C I UnixEnvironment(Object)>ffiCall:module: 16r3816180: a(n) UnixEnvironment

  16r103144 I UnixEnvironment(OSEnvironment)>getEnv: 16r3816180: a(n) UnixEnvironment

  16r103168 I UnixEnvironment(OSEnvironment)>at:ifAbsent: 16r3816180: a(n) UnixEnvironment

  16r10318C M [] in MacOSResolver>(nil) 16r241170: a(n) MacOSResolver

  16r1031A4 M FullBlockClosure(BlockClosure)>on:do: 16r2553F0: a(n) FullBlockClosure

  16r1031D0 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed:or: 16r241170: a(n) MacOSResolver

  16r1031F8 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed: 16r241170: a(n) MacOSResolver

  16r10321C I MacOSResolver>home 16r241170: a(n) MacOSResolver

  16r10323C I MacOSResolver>userLibrary 16r241170: a(n) MacOSResolver

  16r103254 M MacOSResolver>userApplicationSupport 16r241170: a(n) MacOSResolver

  16r10326C M MacOSResolver(FileSystemResolver)>resolve: 16r241170: a(n) MacOSResolver

  16r103288 M SystemResolver(FileSystemResolver)>unknownOrigin: 16r240D30: a(n) SystemResolver

  16r1032A4 M SystemResolver(FileSystemResolver)>resolve: 16r240D30: a(n) SystemResolver

  16r1032C4 M InteractiveResolver>unknownOrigin: 16r240CF0: a(n) InteractiveResolver

  16r1032E4 M [] in InteractiveResolver>(nil) 16r240CF0: a(n) InteractiveResolver

  16r103300 M IdentityDictionary(Dictionary)>at:ifAbsent: 16r240D00: a(n) IdentityDictionary

  16r103320 M InteractiveResolver>resolve: 16r240CF0: a(n) InteractiveResolver

  16r10333C M FileLocator>resolve 16r255258: a(n) FileLocator

  16r103354 M FileLocator(AbstractFileReference)>exists 16r255258: a(n) FileLocator

  16r10337C M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r103398 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r1033B0 M FullBlockClosure(BlockClosure)>on:do: 16r255190: a(n) FullBlockClosure

  16r1033D0 M FullBlockClosure(BlockClosure)>ifError: 16r255190: a(n) FullBlockClosure

  16r1033EC M PharoFilesOpener>ignoreIfFail: 16rE79FD8: a(n) PharoFilesOpener

  16r102188 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r1021AC M Array(SequenceableCollection)>do: 16r2495E8: a(n) Array

  16r1021DC I PharoFilesOpener>openSources:forImage: 16rE79FD8: a(n) PharoFilesOpener

  16r102204 I PharoFilesOpener>openSources 16rE79FD8: a(n) PharoFilesOpener

  16r102228 I PharoFilesOpener>sourcesFileOrNil 16rE79FD8: a(n) PharoFilesOpener

  16r10224C I SourceFileArray>ensureOpen 16r8AA128: a(n) SourceFileArray

  16r10226C I SmalltalkImage>openSourceFiles 16rA58A28: a(n) SmalltalkImage

  16r10228C I SmalltalkImage class>startUp: 16rFDA6A8: a(n) SmalltalkImage class

  16r1022A8 M ClassSessionHandler>startup: 16r8B8978: a(n) ClassSessionHandler

  16r1022C8 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r1022EC M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r102304 M FullBlockClosure(BlockClosure)>on:do: 16r245640: a(n) FullBlockClosure

  16r102328 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r10234C M Array(SequenceableCollection)>do: 16r1A47B8: a(n) Array

  16r102370 I WorkingSession>runList:do: 16r1A45D0: a(n) WorkingSession

  16r102398 I WorkingSession>runStartup: 16r1A45D0: a(n) WorkingSession

  16r1023BC I WorkingSession>start: 16r1A45D0: a(n) WorkingSession

  16r1023E8 I SessionManager>snapshot:andQuit: 16r17AA950: a(n) SessionManager

 

You'll see that Symbol class>selectorTable calls Symbol class> initSelectorTable which then calls CompiledMethod class(Behavior)>allInstancesDo: to enumerate over all methods.  This takes a significant amount of time, even on a fast machine.  For example, on a 2.%GHz machine this takes about 70 milliseconds.  That's a /lot/ of time to squander on startup.  And it will grow the larger the image is.

 

Hm, I didn't thought about that.

 

 

The selector table seems to be discarded on shut-down, which seems pointless.  If one wants to recompute the table then before or after methods are added or removed seems like a better choice, not on every image startup.

 

I think I wanted to be on the save side and just discard on shutdown and rebuild on startup to be sure to have the correct set of selector symbols.

 

 

In around 2000 we were able to startup VisualWorks images in about 40 milliseconds on the hardware available at the time.  I hope someone reconsiders this code and a avoids recomputing the selector table on each startup.

 

I will take a look and try to find a better way.

nicolai

 

_,,,^..^,,,_

best, Eliot

 



Reply | Threaded
Open this post in threaded view
|

Re: Cycles lost on startup

Nicolai Hess-3-2
In reply to this post by Eliot Miranda-2


2016-09-06 12:34 GMT+02:00 Eliot Miranda <[hidden email]>:


On Sep 6, 2016, at 12:25 PM, Nicolai Hess <[hidden email]> wrote:



2016-09-06 11:47 GMT+02:00 Henrik Nergaard <[hidden email]>:

Rewriting the implementation of #initSelectorTable to:

 

SelectorTable := WeakSet withAll: (CompiledMethod allInstances collect: [:m | m selector] as: IdentitySet).

 

Makes it 20ms faster, so it looks like there is some overhead when using WeakSet compared to first use a normal set to remove duplicates.

 

Another possibility could be to store the selectors in an IdentityDictionary as #selector->count which keep track of how many users of a selector there is itself, instead of using a WeakArray.

 

Best regards,

Henrik


Maybe we can just move the rebuilding to the image shutdown instead of the image startup ?

That's a much better idea.  But only if the image snapshots.  There is no point doing it on an exit without saving.

Is there a way to see whether we are just quitting or "quit & save" in Pharos Session/Shutdown list "shutDown:" method ?
 

And just to drive home the point, 70ms is an age in a web server.  This kind of thing really damages Pharo performance in web servers.  One wants startup times in the few tens of milliseconds or better.


 

 

From: Pharo-dev [mailto:[hidden email]] On Behalf Of Nicolai Hess
Sent: Monday, September 5, 2016 7:52 PM
To: Pharo Development List <[hidden email]>
Subject: Re: [Pharo-dev] Cycles lost on startup

 

 

 

2016-09-05 18:37 GMT+02:00 Eliot Miranda <[hidden email]>:

Hi All,

 

    we are simulating a full block Pharo image derived from Pharo 6.  On startup we see a very sad loss of cycles due to a very slow rebuild of the selector table in Symbol class.  Why is this done at each startup?  Here is the stack:

 

  16r107154 M ByteString class(ProtoObject)>identityHash 16r786AE8: a(n) ByteString class

  16r10716C M ByteString class(Object)>hash 16r786AE8: a(n) ByteString class

  16r10718C M ByteSymbol(String)>hash 16rE6A5C8: a(n) ByteSymbol

  16r1071B0 M WeakSet>scanForEmptySlotFor: 16r26B968: a(n) WeakSet

  16r1071DC M WeakSet>noCheckNoGrowFillFrom: 16r26B968: a(n) WeakSet

  16r1071FC M WeakSet>growTo: 16r26B968: a(n) WeakSet

  16r10721C M WeakSet>grow 16r26B968: a(n) WeakSet

  16r107234 M WeakSet(HashedCollection)>fullCheck 16r26B968: a(n) WeakSet

  16r10724C M WeakSet(HashedCollection)>atNewIndex:put: 16r26B968: a(n) WeakSet

  16r107274 M WeakSet>add: 16r26B968: a(n) WeakSet

  16r107294 M [] in Symbol class>(nil) 16r1D319A8: a(n) Symbol class

  16r1072B8 M Array(SequenceableCollection)>do: 16r3C17370: a(n) Array

  16r1072E8 I CompiledMethod class(Behavior)>allInstancesDo: 16r164E260: a(n) CompiledMethod class

  16r10730C I Symbol class>initSelectorTable 16r1D319A8: a(n) Symbol class

  16r10732C I Symbol class>selectorTable 16r1D319A8: a(n) Symbol class

  16r107350 I Symbol class>internSelector: 16r1D319A8: a(n) Symbol class

  16r10737C I CompiledMethod>selector: 16r26AB58: a(n) CompiledMethod

  16r1073A4 I IRMethod>generate: 16r25A030: a(n) IRMethod

  16r1073CC I FFICalloutMethodBuilder>generateMethodFromSpec: 16r255580: a(n) FFICalloutMethodBuilder

  16r1073F0 I FFICalloutMethodBuilder>generate 16r255580: a(n) FFICalloutMethodBuilder

  16r1030C8 I FFICalloutMethodBuilder>build: 16r255580: a(n) FFICalloutMethodBuilder

  16r1030F4 I FFICalloutAPI>function:module: 16r255568: a(n) FFICalloutAPI

  16r10311C I UnixEnvironment(Object)>ffiCall:module: 16r3816180: a(n) UnixEnvironment

  16r103144 I UnixEnvironment(OSEnvironment)>getEnv: 16r3816180: a(n) UnixEnvironment

  16r103168 I UnixEnvironment(OSEnvironment)>at:ifAbsent: 16r3816180: a(n) UnixEnvironment

  16r10318C M [] in MacOSResolver>(nil) 16r241170: a(n) MacOSResolver

  16r1031A4 M FullBlockClosure(BlockClosure)>on:do: 16r2553F0: a(n) FullBlockClosure

  16r1031D0 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed:or: 16r241170: a(n) MacOSResolver

  16r1031F8 I MacOSResolver(PlatformResolver)>directoryFromEnvVariableNamed: 16r241170: a(n) MacOSResolver

  16r10321C I MacOSResolver>home 16r241170: a(n) MacOSResolver

  16r10323C I MacOSResolver>userLibrary 16r241170: a(n) MacOSResolver

  16r103254 M MacOSResolver>userApplicationSupport 16r241170: a(n) MacOSResolver

  16r10326C M MacOSResolver(FileSystemResolver)>resolve: 16r241170: a(n) MacOSResolver

  16r103288 M SystemResolver(FileSystemResolver)>unknownOrigin: 16r240D30: a(n) SystemResolver

  16r1032A4 M SystemResolver(FileSystemResolver)>resolve: 16r240D30: a(n) SystemResolver

  16r1032C4 M InteractiveResolver>unknownOrigin: 16r240CF0: a(n) InteractiveResolver

  16r1032E4 M [] in InteractiveResolver>(nil) 16r240CF0: a(n) InteractiveResolver

  16r103300 M IdentityDictionary(Dictionary)>at:ifAbsent: 16r240D00: a(n) IdentityDictionary

  16r103320 M InteractiveResolver>resolve: 16r240CF0: a(n) InteractiveResolver

  16r10333C M FileLocator>resolve 16r255258: a(n) FileLocator

  16r103354 M FileLocator(AbstractFileReference)>exists 16r255258: a(n) FileLocator

  16r10337C M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r103398 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r1033B0 M FullBlockClosure(BlockClosure)>on:do: 16r255190: a(n) FullBlockClosure

  16r1033D0 M FullBlockClosure(BlockClosure)>ifError: 16r255190: a(n) FullBlockClosure

  16r1033EC M PharoFilesOpener>ignoreIfFail: 16rE79FD8: a(n) PharoFilesOpener

  16r102188 M [] in PharoFilesOpener>(nil) 16rE79FD8: a(n) PharoFilesOpener

  16r1021AC M Array(SequenceableCollection)>do: 16r2495E8: a(n) Array

  16r1021DC I PharoFilesOpener>openSources:forImage: 16rE79FD8: a(n) PharoFilesOpener

  16r102204 I PharoFilesOpener>openSources 16rE79FD8: a(n) PharoFilesOpener

  16r102228 I PharoFilesOpener>sourcesFileOrNil 16rE79FD8: a(n) PharoFilesOpener

  16r10224C I SourceFileArray>ensureOpen 16r8AA128: a(n) SourceFileArray

  16r10226C I SmalltalkImage>openSourceFiles 16rA58A28: a(n) SmalltalkImage

  16r10228C I SmalltalkImage class>startUp: 16rFDA6A8: a(n) SmalltalkImage class

  16r1022A8 M ClassSessionHandler>startup: 16r8B8978: a(n) ClassSessionHandler

  16r1022C8 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r1022EC M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r102304 M FullBlockClosure(BlockClosure)>on:do: 16r245640: a(n) FullBlockClosure

  16r102328 M [] in WorkingSession>(nil) 16r1A45D0: a(n) WorkingSession

  16r10234C M Array(SequenceableCollection)>do: 16r1A47B8: a(n) Array

  16r102370 I WorkingSession>runList:do: 16r1A45D0: a(n) WorkingSession

  16r102398 I WorkingSession>runStartup: 16r1A45D0: a(n) WorkingSession

  16r1023BC I WorkingSession>start: 16r1A45D0: a(n) WorkingSession

  16r1023E8 I SessionManager>snapshot:andQuit: 16r17AA950: a(n) SessionManager

 

You'll see that Symbol class>selectorTable calls Symbol class> initSelectorTable which then calls CompiledMethod class(Behavior)>allInstancesDo: to enumerate over all methods.  This takes a significant amount of time, even on a fast machine.  For example, on a 2.%GHz machine this takes about 70 milliseconds.  That's a /lot/ of time to squander on startup.  And it will grow the larger the image is.

 

Hm, I didn't thought about that.

 

 

The selector table seems to be discarded on shut-down, which seems pointless.  If one wants to recompute the table then before or after methods are added or removed seems like a better choice, not on every image startup.

 

I think I wanted to be on the save side and just discard on shutdown and rebuild on startup to be sure to have the correct set of selector symbols.

 

 

In around 2000 we were able to startup VisualWorks images in about 40 milliseconds on the hardware available at the time.  I hope someone reconsiders this code and a avoids recomputing the selector table on each startup.

 

I will take a look and try to find a better way.

nicolai

 

_,,,^..^,,,_

best, Eliot