Hi, I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones: 1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore) For a total of 318ms I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval. Sven PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
This is really interesting. I would be interested to see why ClassSessionHandler(FreeTypeSettings) takes 2/3 of the computation. Without it we would be 100 ms. Stef On Thu, Jul 27, 2017 at 2:49 PM, Sven Van Caekenberghe <sven@stfx.eu> wrote:
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
In my case it once took eons because I had lots of fonts on a machine. It depends if you have the font check enabled or not I guess. But yeah, loading truetype fonts and all glyphs etc take a while I assume. Having this "boot time sequence log" is nice. Clement told me once to do this in a 5.0 WorkingSession>>#runStartup: isImageStarting | c | Smalltalk at: #LOG11 put: OrderedCollection new. c := Smalltalk at: #LOG11. self runList: manager startupList do: [ :each | c add: each -> DateAndTime now. each startup: isImageStarting ]. self executeDeferredStartupActions: isImageStarting then save and start again, and then inspect the LOG11 global. the thing that took time was the FT2 loading. Phil On Thu, Jul 27, 2017 at 9:14 PM, Stephane Ducasse <stepharo.self@gmail.com> wrote:
This is really interesting. I would be interested to see why ClassSessionHandler(FreeTypeSettings) takes 2/3 of the computation. Without it we would be 100 ms.
Stef
On Thu, Jul 27, 2017 at 2:49 PM, Sven Van Caekenberghe <sven@stfx.eu>
wrote:
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
I vaguely remember StrikeFonts being considered for removal once(??) but this seems a good reason to not do that, and eliminate the FreeType stuff for server-side deployment. cheers -ben On Fri, Jul 28, 2017 at 3:14 AM, Stephane Ducasse <stepharo.self@gmail.com> wrote:
This is really interesting. I would be interested to see why ClassSessionHandler(FreeTypeSettings) takes 2/3 of the computation. Without it we would be 100 ms.
Stef
On Thu, Jul 27, 2017 at 2:49 PM, Sven Van Caekenberghe <sven@stfx.eu> wrote:
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
Remove does not mean that we cannot reload. The font logic is a bit messy. So one of these days we will have to do a pass there. On Fri, Jul 28, 2017 at 7:39 AM, Ben Coman <btc@openinworld.com> wrote:
I vaguely remember StrikeFonts being considered for removal once(??) but this seems a good reason to not do that, and eliminate the FreeType stuff for server-side deployment.
cheers -ben
On Fri, Jul 28, 2017 at 3:14 AM, Stephane Ducasse <stepharo.self@gmail.com> wrote:
This is really interesting. I would be interested to see why ClassSessionHandler(FreeTypeSettings) takes 2/3 of the computation. Without it we would be 100 ms.
Stef
On Thu, Jul 27, 2017 at 2:49 PM, Sven Van Caekenberghe <sven@stfx.eu> wrote:
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
2017-07-28 7:39 GMT+02:00 Ben Coman <btc@openinworld.com>:
I vaguely remember StrikeFonts being considered for removal once(??) but this seems a good reason to not do that, and eliminate the FreeType stuff for server-side deployment.
There was experiment to cache FreeType font in image like StrikeFonts do (Igor did it I guess). It allows to not update anything on startup.
cheers -ben
On Fri, Jul 28, 2017 at 3:14 AM, Stephane Ducasse <stepharo.self@gmail.com
wrote:
This is really interesting. I would be interested to see why ClassSessionHandler(FreeTypeSettings) takes 2/3 of the computation. Without it we would be 100 ms.
Stef
On Thu, Jul 27, 2017 at 2:49 PM, Sven Van Caekenberghe <sven@stfx.eu> wrote:
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
Hi Sven,
Le 27 juil. 2017 à 14:49, Sven Van Caekenberghe <sven@stfx.eu> a écrit :
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Yes, it is a nice feature. Do you have the same thing for #shutdown: ?
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
Thanks but then you should also thanks Guille and Pablo as it was a joint work ;)
On 28 Jul 2017, at 09:56, Christophe Demarey <christophe.demarey@inria.fr> wrote:
Hi Sven,
Le 27 juil. 2017 à 14:49, Sven Van Caekenberghe <sven@stfx.eu> a écrit :
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Yes, it is a nice feature.
I basically did something similar to what Phil/Clement seem to have done: - added a local instance variable #log to WorkingSession holding an OrderedCollection - instrument #runStartup: and #executeDeferredStartupActions: like this runStartup: isImageStarting self runList: manager startupList do: [ :each | | ms | ms := Time millisecondsToRun: [ each startup: isImageStarting ]. log add: { ms. #startup:. isImageStarting. each } ]. self executeDeferredStartupActions: isImageStarting but if we do this for real, we better use a real object (like a log event, like SessionActionExecuted)
Do you have the same thing for #shutdown: ?
I considered that, but if the session shuts down, it will disappear, hence the log will be lost, no ? Unless we also write it (optionally) to a file.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
Thanks but then you should also thanks Guille and Pablo as it was a joint work ;)
Thank you Guille and Pablo !!
Le 28 juil. 2017 à 10:14, Sven Van Caekenberghe <sven@stfx.eu> a écrit :
On 28 Jul 2017, at 09:56, Christophe Demarey <christophe.demarey@inria.fr> wrote:
Hi Sven,
Le 27 juil. 2017 à 14:49, Sven Van Caekenberghe <sven@stfx.eu> a écrit :
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Yes, it is a nice feature.
I basically did something similar to what Phil/Clement seem to have done:
- added a local instance variable #log to WorkingSession holding an OrderedCollection - instrument #runStartup: and #executeDeferredStartupActions: like this
runStartup: isImageStarting self runList: manager startupList do: [ :each | | ms | ms := Time millisecondsToRun: [ each startup: isImageStarting ]. log add: { ms. #startup:. isImageStarting. each } ]. self executeDeferredStartupActions: isImageStarting
but if we do this for real, we better use a real object (like a log event, like SessionActionExecuted)
Do you have the same thing for #shutdown: ?
I considered that, but if the session shuts down, it will disappear, hence the log will be lost, no ?
Yes, an option could be to keep an history of sessions (or just the last one?)
Unless we also write it (optionally) to a file.
That is difficult because while the shutdown list is processed, you loose functionalities and FileSystem is one of them.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
Thanks but then you should also thanks Guille and Pablo as it was a joint work ;)
Thank you Guille and Pablo !!
6ms startup:true a ClassSessionHandler(ExternalObject)
Most time here is taken by ExternalAddress startUp logic: ExternalAddress>>startUp: resuming ... instances := self allInstances. wordSize ~= Smalltalk wordSize ifTrue: "Implement nulling by becomming all existing instances to new (and hence null) pointers of the right size." [wordSize := Smalltalk wordSize. instances elementsForwardIdentityTo: (instances collect: [:ea| self basicNew: wordSize])] ifFalse: [instances do: [:addr| addr beNull]]] It scans all instances which is very expensive. And I thing it can lead to much more time in bigger images. Maybe we can perform this cleanup at "prepare for production" script and add special flag in image that all externals are already clean. 2017-07-27 14:49 GMT+02:00 Sven Van Caekenberghe <sven@stfx.eu>:
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
On 28 Jul 2017, at 10:15, Denis Kudriashov <dionisiydk@gmail.com> wrote:
6ms startup:true a ClassSessionHandler(ExternalObject)
Most time here is taken by ExternalAddress startUp logic:
ExternalAddress>>startUp: resuming ... instances := self allInstances. wordSize ~= Smalltalk wordSize ifTrue: "Implement nulling by becomming all existing instances to new (and hence null) pointers of the right size." [wordSize := Smalltalk wordSize. instances elementsForwardIdentityTo: (instances collect: [:ea| self basicNew: wordSize])] ifFalse: [instances do: [:addr| addr beNull]]]
It scans all instances which is very expensive. And I thing it can lead to much more time in bigger images. Maybe we can perform this cleanup at "prepare for production" script and add special flag in image that all externals are already clean.
Sorry but no :) This will lead to all kind of pain since a lot of functionality depends on that. I played with moving the clean up to shutdown instead (which would be a better approach) but there were also problems. If you want to play in that sense, is cool. But ExternalAddress needs to be cleaned and each new session needs to be started and find instances of EA nulled. Esteban
2017-07-27 14:49 GMT+02:00 Sven Van Caekenberghe <sven@stfx.eu>:
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
2017-07-28 10:26 GMT+02:00 Esteban Lorenzano <estebanlm@gmail.com>:
On 28 Jul 2017, at 10:15, Denis Kudriashov <dionisiydk@gmail.com> wrote:
6ms startup:true a ClassSessionHandler(ExternalObject)
Most time here is taken by ExternalAddress startUp logic:
ExternalAddress>>startUp: resuming
...
instances := self allInstances.
wordSize ~= Smalltalk wordSize ifTrue: "Implement nulling by becomming all existing instances to new (and hence null) pointers of the right size." [wordSize := Smalltalk wordSize. instances elementsForwardIdentityTo: (instances collect: [:ea| self basicNew: wordSize])] ifFalse: [instances do: [:addr| addr beNull]]]
It scans all instances which is very expensive. And I thing it can lead to much more time in bigger images. Maybe we can perform this cleanup at "prepare for production" script and add special flag in image that all externals are already clean.
Sorry but no :)
This will lead to all kind of pain since a lot of functionality depends on
that. I played with moving the clean up to shutdown instead (which would be a better approach) but there were also problems. If you want to play in that sense, is cool. But ExternalAddress needs to be cleaned and each new session needs to be started and find instances of EA nulled.
Imaging that I deploy Seaside application. Why my image should spend time for this useless check while fast server startup is very important? I understand that current logic simplifies a lot of things when we do development with many image saves. But production image can be safe enough for such kind optimization.
Esteban
2017-07-27 14:49 GMT+02:00 Sven Van Caekenberghe <sven@stfx.eu>:
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
If my Seaside app is generating graphics (it is) using FT2 fonts, well, I cannot escape this... Phil On Fri, Jul 28, 2017 at 11:37 AM, Denis Kudriashov <dionisiydk@gmail.com> wrote:
2017-07-28 10:26 GMT+02:00 Esteban Lorenzano <estebanlm@gmail.com>:
On 28 Jul 2017, at 10:15, Denis Kudriashov <dionisiydk@gmail.com> wrote:
6ms startup:true a ClassSessionHandler(ExternalObject)
Most time here is taken by ExternalAddress startUp logic:
ExternalAddress>>startUp: resuming
...
instances := self allInstances.
wordSize ~= Smalltalk wordSize ifTrue: "Implement nulling by becomming all existing instances to new (and hence null) pointers of the right size." [wordSize := Smalltalk wordSize. instances elementsForwardIdentityTo: (instances collect: [:ea| self basicNew: wordSize])] ifFalse: [instances do: [:addr| addr beNull]]]
It scans all instances which is very expensive. And I thing it can lead to much more time in bigger images. Maybe we can perform this cleanup at "prepare for production" script and add special flag in image that all externals are already clean.
Sorry but no :)
This will lead to all kind of pain since a lot of functionality depends on
that. I played with moving the clean up to shutdown instead (which would be a better approach) but there were also problems. If you want to play in that sense, is cool. But ExternalAddress needs to be cleaned and each new session needs to be started and find instances of EA nulled.
Imaging that I deploy Seaside application. Why my image should spend time for this useless check while fast server startup is very important? I understand that current logic simplifies a lot of things when we do development with many image saves. But production image can be safe enough for such kind optimization.
Esteban
2017-07-27 14:49 GMT+02:00 Sven Van Caekenberghe <sven@stfx.eu>:
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
About the FreeType issue: the fonts we use are already cached in the image but they still need to be moved to freetype library when starting. While speeding up will be cool, the only way to avoid this is to not initiate freetype fonts (perfectly doable for headless images) Esteban On 28 Jul 2017, at 10:15, Denis Kudriashov <dionisiydk@gmail.com> wrote:
6ms startup:true a ClassSessionHandler(ExternalObject)
Most time here is taken by ExternalAddress startUp logic:
ExternalAddress>>startUp: resuming ... instances := self allInstances. wordSize ~= Smalltalk wordSize ifTrue: "Implement nulling by becomming all existing instances to new (and hence null) pointers of the right size." [wordSize := Smalltalk wordSize. instances elementsForwardIdentityTo: (instances collect: [:ea| self basicNew: wordSize])] ifFalse: [instances do: [:addr| addr beNull]]]
It scans all instances which is very expensive. And I thing it can lead to much more time in bigger images. Maybe we can perform this cleanup at "prepare for production" script and add special flag in image that all externals are already clean.
2017-07-27 14:49 GMT+02:00 Sven Van Caekenberghe <sven@stfx.eu>:
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
2017-07-28 10:35 GMT+02:00 Esteban Lorenzano <estebanlm@gmail.com>:
About the FreeType issue: the fonts we use are already cached in the image but they still need to be moved to freetype library when starting.
Looks suprizing that moving two fonts takes so much time. Do you know what happens during move? I found two cached fonts in image: SourceCode and SourceSans. There is also LucidaGrandeRegular which always loads font from file. But it is only for Mac (look at #canBeInstalled).
While speeding up will be cool, the only way to avoid this is to not initiate freetype fonts (perfectly doable for headless images)
Esteban
On 28 Jul 2017, at 10:15, Denis Kudriashov <dionisiydk@gmail.com> wrote:
6ms startup:true a ClassSessionHandler(ExternalObject)
Most time here is taken by ExternalAddress startUp logic:
ExternalAddress>>startUp: resuming
...
instances := self allInstances.
wordSize ~= Smalltalk wordSize ifTrue: "Implement nulling by becomming all existing instances to new (and hence null) pointers of the right size." [wordSize := Smalltalk wordSize. instances elementsForwardIdentityTo: (instances collect: [:ea| self basicNew: wordSize])] ifFalse: [instances do: [:addr| addr beNull]]]
It scans all instances which is very expensive. And I thing it can lead to much more time in bigger images. Maybe we can perform this cleanup at "prepare for production" script and add special flag in image that all externals are already clean.
2017-07-27 14:49 GMT+02:00 Sven Van Caekenberghe <sven@stfx.eu>:
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
I too am very keen to get a minimal image that can start as quickly as possible as this gets us into the realm of running Pharo efficiently on AWS Lambda where milliseconds count. We're not bad (at least in the running) and comparable to other languages like GO, but milliseconds do add up and cost money, so any efficiencies are useful. This thread has raised very interesting info as with the jump to 6.1 I've not got a minimal image running reliably yet and the full image does show up that there is lots going on, and processes trying to write to a file system that is read only in the Lambda case. Tim Sent from my iPhone
On 28 Jul 2017, at 11:54, Denis Kudriashov <dionisiydk@gmail.com> wrote:
2017-07-28 10:35 GMT+02:00 Esteban Lorenzano <estebanlm@gmail.com>:
About the FreeType issue: the fonts we use are already cached in the image but they still need to be moved to freetype library when starting.
Looks suprizing that moving two fonts takes so much time. Do you know what happens during move? I found two cached fonts in image: SourceCode and SourceSans. There is also LucidaGrandeRegular which always loads font from file. But it is only for Mac (look at #canBeInstalled).
While speeding up will be cool, the only way to avoid this is to not initiate freetype fonts (perfectly doable for headless images)
Esteban
On 28 Jul 2017, at 10:15, Denis Kudriashov <dionisiydk@gmail.com> wrote:
6ms startup:true a ClassSessionHandler(ExternalObject)
Most time here is taken by ExternalAddress startUp logic:
ExternalAddress>>startUp: resuming ... instances := self allInstances. wordSize ~= Smalltalk wordSize ifTrue: "Implement nulling by becomming all existing instances to new (and hence null) pointers of the right size." [wordSize := Smalltalk wordSize. instances elementsForwardIdentityTo: (instances collect: [:ea| self basicNew: wordSize])] ifFalse: [instances do: [:addr| addr beNull]]]
It scans all instances which is very expensive. And I thing it can lead to much more time in bigger images. Maybe we can perform this cleanup at "prepare for production" script and add special flag in image that all externals are already clean.
2017-07-27 14:49 GMT+02:00 Sven Van Caekenberghe <sven@stfx.eu>:
Hi,
I instrumented WorkingSession with a log collection that holds timing info for each #startUp: executed. In a clean Pharo 6 image, 62 were run. Most of them resulted in a 0ms execution time (#millisecondsToRun: i.e. they were faster than 1ms). Here is the list of the non zero ones:
1ms startup:true a ClassSessionHandler(ProcessorScheduler) 1ms startup:true a ClassSessionHandler(OSPlatform) 6ms startup:true a ClassSessionHandler(ExternalObject) 1ms startup:true a ClassSessionHandler(DiskStore) 5ms startup:true a ClassSessionHandler(SmalltalkImage) 9ms startup:true a ClassSessionHandler(DisplayScreen) 1ms startup:true a ClassSessionHandler(Cursor) 41ms startup:true a ClassSessionHandler(FT2Handle) 238ms startup:true a ClassSessionHandler(FreeTypeSettings) 1ms startup:true a ClassSessionHandler(WorldMorph) 14ms startup:true a ClassSessionHandler(OmSessionStore)
For a total of 318ms
I think being able to inspect the WorkingSession and see this list (ordered, with timing info) would be generally useful (and low cost). Even headless, we could access the list using eval.
Sven
PS: The code of SessionManager/WorkingSession was very readable, well done Christophe !
participants (8)
-
Ben Coman -
Christophe Demarey -
Denis Kudriashov -
Esteban Lorenzano -
phil＠highoctane.be -
Stephane Ducasse -
Sven Van Caekenberghe -
Tim Mackinnon