[Pharo-dev] WorkingSession log
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 !
Re: [Pharo-dev] WorkingSession log
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 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 ! > > > >
Re: [Pharo-dev] WorkingSession log
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 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 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 ! > > > > > > > > >
Re: [Pharo-dev] WorkingSession log
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 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 > 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 ! > > > > > > > > > >
Re: [Pharo-dev] WorkingSession log
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 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 > 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 >> 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 ! >> > >> > >> > >> > >> >
Re: [Pharo-dev] WorkingSession log
2017-07-28 7:39 GMT+02:00 Ben Coman : > 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 > 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 >> 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 ! >> > >> > >> > >> > >> >> >
Re: [Pharo-dev] WorkingSession log
Hi Sven, > Le 27 juil. 2017 à 14:49, Sven Van Caekenberghe 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 ;)
Re: [Pharo-dev] WorkingSession log
> On 28 Jul 2017, at 09:56, Christophe Demarey > wrote: > > Hi Sven, > >> Le 27 juil. 2017 à 14:49, Sven Van Caekenberghe 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 !!
Re: [Pharo-dev] WorkingSession log
> > 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 : > 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 ! > > > > >
Re: [Pharo-dev] WorkingSession log
On 28 Jul 2017, at 10:15, Denis Kudriashov 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 : >> 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 ! >> >> >> >> >
Re: [Pharo-dev] WorkingSession log
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 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 : >> 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 ! >> >> >> >> >
Re: [Pharo-dev] WorkingSession log
2017-07-28 10:26 GMT+02:00 Esteban Lorenzano : > > > On 28 Jul 2017, at 10:15, Denis Kudriashov 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 : > >> 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 ! >> >> >> >> >> >
Re: [Pharo-dev] WorkingSession log
2017-07-28 10:35 GMT+02:00 Esteban Lorenzano : > 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 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 : > >> 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 ! >> >> >> >> >> >
Re: [Pharo-dev] WorkingSession log
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 wrote: > > 2017-07-28 10:35 GMT+02:00 Esteban Lorenzano : >> 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 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 : 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 ! >>> >
Re: [Pharo-dev] WorkingSession log
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 wrote: > 2017-07-28 10:26 GMT+02:00 Esteban Lorenzano : > >> >> >> On 28 Jul 2017, at 10:15, Denis Kudriashov 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 : >> >>> 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 ! >>> >>> >>> >>> >>> >> >
Re: [Pharo-dev] WorkingSession log
> Le 28 juil. 2017 à 10:14, Sven Van Caekenberghe a écrit : > >> >> On 28 Jul 2017, at 09:56, Christophe Demarey >> wrote: >> >> Hi Sven, >> >>> Le 27 juil. 2017 à 14:49, Sven Van Caekenberghe 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 !!