WorkingSession log

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

WorkingSession log

Sven Van Caekenberghe-2
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 !




Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

Stephane Ducasse-3
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 !
>
>
>
>

Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

philippeback
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 !
> >
> >
> >
> >
>
Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

Ben Coman
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.
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 !
>
>
>
>


Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

Stephane Ducasse-3
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 !
>> >
>> >
>> >
>> >
>>
>

Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

Denis Kudriashov
In reply to this post by Ben Coman

2017-07-28 7:39 GMT+02:00 Ben Coman <[hidden email]>:
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 <[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 !
>
>
>
>



Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

demarey
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 ;)
Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

Sven Van Caekenberghe-2

> 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 !!


Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

Denis Kudriashov
In reply to this post by Sven Van Caekenberghe-2
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 <[hidden email]>:
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 !





Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

EstebanLM


On 28 Jul 2017, at 10:15, Denis Kudriashov <[hidden email]> 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 <[hidden email]>:
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 !





Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

EstebanLM
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 

On 28 Jul 2017, at 10:15, Denis Kudriashov <[hidden email]> 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 <[hidden email]>:
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 !





Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

Denis Kudriashov
In reply to this post by EstebanLM
2017-07-28 10:26 GMT+02:00 Esteban Lorenzano <[hidden email]>:


On 28 Jul 2017, at 10:15, Denis Kudriashov <[hidden email]> 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 <[hidden email]>:
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 !






Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

Denis Kudriashov
In reply to this post by EstebanLM
2017-07-28 10:35 GMT+02:00 Esteban Lorenzano <[hidden email]>:
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 <[hidden email]> 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 <[hidden email]>:
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 !






Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

Tim Mackinnon
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 <[hidden email]> wrote:

2017-07-28 10:35 GMT+02:00 Esteban Lorenzano <[hidden email]>:
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 <[hidden email]> 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 <[hidden email]>:
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 !






Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

philippeback
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:
2017-07-28 10:26 GMT+02:00 Esteban Lorenzano <[hidden email]>:


On 28 Jul 2017, at 10:15, Denis Kudriashov <[hidden email]> 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 <[hidden email]>:
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 !







Reply | Threaded
Open this post in threaded view
|

Re: WorkingSession log

demarey
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 !!