[Pharo-dev] WorkingSession log

[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

[Stephane Ducasse]

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

[p...@highoctane.be]

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

[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.

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

[Stephane Ducasse]

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

[Denis Kudriashov]

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

[Christophe Demarey]

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

[Sven Van Caekenberghe]

> 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

[Denis Kudriashov]

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

[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.

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

[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. 
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

[Denis Kudriashov]

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

[Denis Kudriashov]

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

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

[p...@highoctane.be]

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

[Christophe Demarey]

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