WorkingSession log
Locked
 
|
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 <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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 reply to this post by Stephane Ducasse-3
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 <[hidden email]> wrote: This is really interesting. |
|
|
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 <[hidden email]> 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 <[hidden email]> > 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 <[hidden email]> >> 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 reply to this post by Ben Coman
2017-07-28 7:39 GMT+02:00 Ben Coman <[hidden email]>:
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.
|
|
|
In reply to this post by Sven Van Caekenberghe-2
Hi Sven,
> Le 27 juil. 2017 à 14:49, Sven Van Caekenberghe <[hidden email]> 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: WorkingSession log
|
|
> On 28 Jul 2017, at 09:56, Christophe Demarey <[hidden email]> wrote: > > Hi Sven, > >> Le 27 juil. 2017 à 14:49, Sven Van Caekenberghe <[hidden email]> 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 !! |
|
|
In reply to this post by Sven Van Caekenberghe-2
6ms startup:true a ClassSessionHandler( Most time here is taken by ExternalAddress startUp logic:
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 <[hidden email]>: Hi, |
|
|
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
|
|
|
In reply to this post by Denis Kudriashov
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
|
|
|
In reply to this post by EstebanLM
2017-07-28 10:26 GMT+02:00 Esteban Lorenzano <[hidden email]>:
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.
|
|
|
In reply to this post by EstebanLM
2017-07-28 10:35 GMT+02:00 Esteban Lorenzano <[hidden email]>:
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).
|
|
|
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
|
|
|
In reply to this post by Denis Kudriashov
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 <[hidden email]> wrote:
|
|
|
In reply to this post by Sven Van Caekenberghe-2
> Le 28 juil. 2017 à 10:14, Sven Van Caekenberghe <[hidden email]> a écrit : > >> >> On 28 Jul 2017, at 09:56, Christophe Demarey <[hidden email]> wrote: >> >> Hi Sven, >> >>> Le 27 juil. 2017 à 14:49, Sven Van Caekenberghe <[hidden email]> 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 !! |
«
Return to Pharo Smalltalk Developers
|
1 view|%1 views
| Free forum by Nabble | Edit this page |