Ahhh... gmail pre-emptive send strikes again.... To continue... I am curious about the recursive calls to ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer and multiple accumulations from DelayExperimentalSpinScheduler>>unschedule: but that method doesn't really do a lot. I wouldn't expect the whileTrue loop to be spinning much, but you could examine that by trying something like... Object subclass: #SpinCount instanceVariableNames: 'counter' classVariableNames: '' package: 'Play' SpinCount>>initialize counter := 0. SpinCount>>count counter := counter + 1. SpinCount>>printOn: aStream super printOn: aStream. aStream nextPut: $=. counter printOn: aStream. DelayMicrosecondScheduler subclass: #DelayExperimentalSpinScheduler instanceVariableNames: '' classVariableNames: 'Tally' package: 'Kernel-Processes' DelayExperimentalSpinScheduler class >> startTally Tally := WaitfreeQueue new. DelayExperimentalSpinScheduler class >> endTally |result finalTally| finalTally := Tally. Tally := nil. result := OrderedCollection new. finalTally flush: [ :item | result add: item ]. ^ result DelayExperimentalSpinScheduler >> unschedule: aDelay |spinCount| "self startTally" "self endTally inspect" spinCount := SpinCount new. Tally ifNotNil: [Tally nextPut: spinCount]. aDelay schedulerBeingWaitedOn ifTrue: [^self error: 'This Delay has already been scheduled.']. [ Tally ifNotNil: [spinCount count]. scheduledDelay == nil ifTrue: [ scheduledDelay := aDelay. timingSemaphore signal. ^self]. true. ] whileTrue. Actually, I wonder does the "timingSemaphore signal" invoking the priority 80 DelaySchedulingProcess to wake up and run above the priority of the profiler? So all of that activity gets attributed to #unschedule: ??? cheers -ben

On 08 Sep 2016, at 14:01, Vitor Medina Cruz <vitormcruz@gmail.com> wrote:

Thanks for the answers!

If this is time spent on I/O it is really strange. I am consuming the Twitter API and it don't get so much time like this to get a response. Besides, while those profiles were made at a Windows 10 local machine, the same code on a Pharo 5 (get.pharo.org) deployed on a linux deploy on Digital Ocean takes ~6 seconds, which means that a lot less time is spent on I/O. Isn't that Strange? I will try to spin up a local linux machine with both a headfull and headless Pharo to see if this time changes.

Is there a way to profile a remote image? I would like to see what is happening in the Digital Ocean deploy. Maybe put the headless Pharo there in profiling mode?

Ben: this is a heavy json parser procedure, I would expect to NeoJson to take some time. Perhaps there is a way to optimize this, but what catch my attention was the huge amount of time spent on the idleProcess. Been that I/O wait, it shouldn't be like this.

Why not ? You are doing (lot's of) network I/O. It is normal that your image code has to wait from time to time for data to come in from the network. By definition that is slow (in CPU terms). The Digital Ocean instance is probably faster in that respect. Also, having the IDE UI with lot's of tools open might influence things. Best do some more experiments. But benchmarking is very tricky.

Thanks, Vitor

On Thu, Sep 8, 2016 at 4:42 AM, Clément Bera <bera.clement@gmail.com> wrote:

On Thu, Sep 8, 2016 at 3:44 AM, Vitor Medina Cruz <vitormcruz@gmail.com> wrote: Hello,

While profiling some I/O code that takes ~20 seconds to execute under my local image, the report says that about ~13 seconds is waste on OtherProcesses -> ProcessorScheduler class>>idleProcess. I could not understand what this idleProcess do by looking at the code. First I thought this could be time waiting the I/O operation to terminate, but that don't make much sense because I have the same code on a Digital Ocean Doplet and it takes ~6 seconds to execute.

Can someone help me understand what does this time on idleProcess means?

The VM is not event-driven. Hence when all the processes are suspended or terminated, the VM falls back to the idle process. The idle process waits for 1ms, checks if any event has occurred and/or if a process can restart, and if not waits for 1 more ms to check again. That's kind of dumb but it works and we need both time and funds to make the VM event-driven (in the latter case the VM restarts directly when an event happens, instead of checking at the next ms).

Basically the idle process profiled time is the time where Pharo has nothing to do because all processes are terminated or suspended. You can say that it is the time spent in I/O operations + the time before Pharo notices the I/O operation is terminated, which can be up to 1ms.

The full report is:

- 18407 tallies, 18605 msec.

**Tree** -------------------------------- Process: (40s) Morphic UI Process: nil -------------------------------- 25.1% {4663ms} UndefinedObject>>DoIt 25.1% {4663ms} TweetsServiceRestConsumer(TweetsService)>>hashesTop:usingLastTweetsUpTo:fromHandler: 25.0% {4656ms} TweetsServiceRestConsumer>>fetchLastTweetsUpTo:fromHandler: 14.3% {2653ms} OAuthProvider>>httpGet: |14.3% {2653ms} ZnOAuth1Service>>httpGet:using: | 14.3% {2653ms} ZnOAuth1Service>>executeRequest:token: | 14.3% {2653ms} ZnOAuth1Service>>executeRequest:token:followRedirects: | 14.2% {2646ms} ZnClient>>execute | 14.2% {2646ms} ZnClient>>withProgressDo: | 14.2% {2646ms} ZnSignalProgress class(DynamicVariable class)>>value:during: | 14.2% {2646ms} ZnSignalProgress(DynamicVariable)>>value:during: | 14.2% {2646ms} BlockClosure>>ensure: | 14.2% {2646ms} ZnSignalProgress(DynamicVariable)>>value:during: | 14.2% {2646ms} ZnClient>>withProgressDo: | 14.2% {2646ms} ZnClient>>execute | 14.2% {2646ms} ZnClient>>executeWithTimeout | 14.2% {2646ms} ZnClient>>withTimeoutDo: | 14.2% {2646ms} ZnConnectionTimeout class(DynamicVariable class)>>value:during: | 14.2% {2646ms} ZnConnectionTimeout(DynamicVariable)>>value:during: | 14.2% {2646ms} BlockClosure>>ensure: | 14.2% {2646ms} ZnConnectionTimeout(DynamicVariable)>>value:during: | 14.2% {2646ms} ZnClient>>withTimeoutDo: | 14.2% {2646ms} ZnClient>>executeWithTimeout | 14.2% {2646ms} BlockClosure>>on:do: | 14.2% {2646ms} ZnClient>>executeWithTimeout | 14.2% {2646ms} ZnClient>>executeWithRetriesRemaining: | 14.2% {2644ms} BlockClosure>>on:do: | 14.2% {2644ms} ZnClient>>executeWithRetriesRemaining: | 14.2% {2644ms} ZnClient>>executeWithRedirectsRemaining: | 14.2% {2641ms} ZnClient>>getConnectionAndExecute | 13.8% {2569ms} BlockClosure>>ensure: | 13.8% {2569ms} ZnClient>>getConnectionAndExecute | 13.8% {2569ms} ZnClient>>executeRequestResponse | 13.8% {2569ms} ZnClient>>readResponse | 13.8% {2569ms} ZnResponse class(ZnMessage class)>>readFrom: | 13.8% {2569ms} ZnResponse(ZnMessage)>>readFrom: | 13.8% {2559ms} ZnResponse>>readEntityFrom: | 13.8% {2559ms} ZnResponse(ZnMessage)>>readEntityFrom: | 13.8% {2559ms} ZnEntityReader>>readEntity | 13.8% {2559ms} ZnEntityReader>>readEntityFromStream | 13.7% {2555ms} ZnEntityReader>>readFrom:usingType:andLength: | 13.7% {2555ms} ZnEntity class>>readFrom:usingType:andLength: | 13.7% {2555ms} ZnStringEntity>>readFrom: | 13.7% {2550ms} BlockClosure>>on:do: | 13.7% {2550ms} ZnStringEntity>>readFrom: | 13.7% {2550ms} ZnUTF8Encoder>>readInto:startingAt:count:fromStream: | 13.7% {2550ms} ZnUTF8Encoder>>optimizedReadInto:startingAt:count:fromStream: | 13.7% {2550ms} ZnLimitedReadStream>>readInto:startingAt:count: | 13.7% {2547ms} ZdcSecureSocketStream(ZdcOptimizedSocketStream)>>readInto:startingAt:count: | 13.7% {2547ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | 9.0% {1669ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | |5.8% {1076ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | |3.6% {671ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | | |1.8% {337ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | | | |1.2% {225ms} BlockClosure>>on:do: | | | | | 1.2% {225ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | | | | 1.2% {225ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData | | | | | 1.2% {225ms} Socket>>waitForDataFor: | | | | | 1.2% {225ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: | | | | | 1.2% {225ms} Semaphore>>waitTimeoutMSecs: | | | | | 1.2% {225ms} DelayWaitTimeout>>wait | | | | | 1.2% {225ms} BlockClosure>>ensure: | | | | | 1.2% {225ms} DelayWaitTimeout>>wait | | | | | 1.1% {196ms} DelayWaitTimeout(Delay)>>unschedule | | | | | 1.1% {196ms} DelayExperimentalSpinScheduler>>unschedule: | | | |1.8% {335ms} BlockClosure>>on:do: | | | | 1.8% {335ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | | | 1.8% {335ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData | | | | 1.8% {335ms} Socket>>waitForDataFor: | | | | 1.8% {335ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: | | | | 1.8% {335ms} Semaphore>>waitTimeoutMSecs: | | | | 1.8% {335ms} DelayWaitTimeout>>wait | | | | 1.8% {335ms} BlockClosure>>ensure: | | | | 1.8% {335ms} DelayWaitTimeout>>wait | | | | 1.5% {273ms} DelayWaitTimeout(Delay)>>unschedule | | | | 1.5% {273ms} DelayExperimentalSpinScheduler>>unschedule: | | |2.2% {405ms} BlockClosure>>on:do: | | | 2.2% {405ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | | 2.2% {405ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData | | | 2.2% {405ms} Socket>>waitForDataFor: | | | 2.2% {405ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: | | | 2.2% {405ms} Semaphore>>waitTimeoutMSecs: | | | 2.2% {405ms} DelayWaitTimeout>>wait | | | 2.2% {405ms} BlockClosure>>ensure: | | | 2.2% {405ms} DelayWaitTimeout>>wait | | | 1.7% {314ms} DelayWaitTimeout(Delay)>>unschedule | | | 1.7% {314ms} DelayExperimentalSpinScheduler>>unschedule: | |3.2% {592ms} BlockClosure>>on:do: | | 3.2% {592ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | 3.2% {592ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData | | 3.2% {592ms} Socket>>waitForDataFor: | | 3.2% {592ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: | | 3.2% {592ms} Semaphore>>waitTimeoutMSecs: | | 3.2% {592ms} DelayWaitTimeout>>wait | | 3.2% {592ms} BlockClosure>>ensure: | | 3.2% {592ms} DelayWaitTimeout>>wait | | 2.3% {429ms} DelayWaitTimeout(Delay)>>unschedule | | 2.3% {429ms} DelayExperimentalSpinScheduler>>unschedule: | 4.7% {876ms} BlockClosure>>on:do: | 4.7% {876ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | 4.7% {876ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData | 4.7% {876ms} Socket>>waitForDataFor: | 4.7% {876ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: | 4.7% {876ms} Semaphore>>waitTimeoutMSecs: | 4.7% {876ms} DelayWaitTimeout>>wait | 4.7% {876ms} BlockClosure>>ensure: | 4.7% {876ms} DelayWaitTimeout>>wait | 2.9% {532ms} DelayWaitTimeout(Delay)>>unschedule | |2.9% {532ms} DelayExperimentalSpinScheduler>>unschedule: | 1.4% {268ms} primitives 10.8% {2002ms} NeoJSONObject class>>fromString: 10.8% {2002ms} NeoJSONReader>>next 10.8% {2002ms} NeoJSONReader>>parseValue 10.8% {2002ms} NeoJSONReader>>parseList 10.8% {2002ms} Array class(SequenceableCollection class)>>streamContents: 10.8% {2002ms} Array class(SequenceableCollection class)>>new:streamContents: 10.8% {2002ms} NeoJSONReader>>parseList 10.8% {2002ms} NeoJSONReader>>parseListElementsDo: 10.8% {2002ms} NeoJSONReader>>parseListDo: 10.8% {2002ms} NeoJSONReader>>parseListElementsDo: 10.8% {2002ms} NeoJSONReader>>parseValue 10.8% {2002ms} NeoJSONReader>>parseMap 10.8% {2002ms} NeoJSONReader>>parseMapKeysAndValuesDo: 10.8% {2002ms} NeoJSONReader>>parseMapKeysDo: 10.8% {2002ms} NeoJSONReader>>parseMapDo: 10.7% {1994ms} NeoJSONReader>>parseMapKeysDo: 9.6% {1785ms} NeoJSONReader>>parseMapKeysAndValuesDo: |9.2% {1717ms} NeoJSONReader>>parseValue | 8.6% {1600ms} NeoJSONReader>>parseMap | 8.6% {1600ms} NeoJSONReader>>parseMapKeysAndValuesDo: | 8.6% {1600ms} NeoJSONReader>>parseMapKeysDo: | 8.6% {1600ms} NeoJSONReader>>parseMapDo: | 8.5% {1577ms} NeoJSONReader>>parseMapKeysDo: | 6.4% {1187ms} NeoJSONReader>>parseMapKeysAndValuesDo: | |5.6% {1041ms} NeoJSONReader>>parseValue | | 3.8% {708ms} NeoJSONReader>>parseList | | 3.8% {706ms} Array class(SequenceableCollection class)>>streamContents: | | 3.8% {706ms} Array class(SequenceableCollection class)>>new:streamContents: | | 3.7% {693ms} NeoJSONReader>>parseList | | 3.7% {693ms} NeoJSONReader>>parseListElementsDo: | | 3.7% {693ms} NeoJSONReader>>parseListDo: | | 3.7% {689ms} NeoJSONReader>>parseListElementsDo: | | 3.7% {689ms} NeoJSONReader>>parseValue | | 3.7% {687ms} NeoJSONReader>>parseMap | | 3.7% {687ms} NeoJSONReader>>parseMapKeysAndValuesDo: | | 3.7% {687ms} NeoJSONReader>>parseMapKeysDo: | | 3.7% {687ms} NeoJSONReader>>parseMapDo: | | 3.6% {672ms} NeoJSONReader>>parseMapKeysDo: | | 3.0% {550ms} NeoJSONReader>>parseMapKeysAndValuesDo: | | 2.6% {486ms} NeoJSONReader>>parseValue | | 1.5% {285ms} NeoJSONReader>>parseMap | | 1.5% {285ms} NeoJSONReader>>parseMapKeysAndValuesDo: | | 1.5% {285ms} NeoJSONReader>>parseMapKeysDo: | | 1.5% {285ms} NeoJSONReader>>parseMapDo: | | 1.5% {285ms} NeoJSONReader>>parseMapKeysDo: | | 1.4% {252ms} NeoJSONReader>>parseMapKeysAndValuesDo: | | 1.3% {236ms} NeoJSONReader>>parseValue | | 1.0% {193ms} NeoJSONReader>>parseMap | | 1.0% {193ms} NeoJSONReader>>parseMapKeysAndValuesDo: | | 1.0% {193ms} NeoJSONReader>>parseMapKeysDo: | | 1.0% {188ms} NeoJSONReader>>parseMapDo: | 1.9% {347ms} NeoJSONReader>>parsePropertyName | 1.1% {196ms} NeoJSONReader>>parseValue | 1.0% {189ms} NeoJSONReader>>parseString 1.0% {189ms} NeoJSONReader>>parsePropertyName -------------------------------- Process: other processes -------------------------------- 73.2% {13628ms} ProcessorScheduler class>>startUp |73.2% {13628ms} ProcessorScheduler class>>idleProcess 1.4% {259ms} WeakArray class>>restartFinalizationProcess 1.4% {259ms} WeakArray class>>finalizationProcess 1.4% {257ms} primitives **Leaves** 73.3% {13631ms} ProcessorScheduler class>>idleProcess 10.0% {1861ms} DelayExperimentalSpinScheduler>>unschedule: 3.1% {581ms} DelayWaitTimeout>>wait 1.4% {257ms} WeakArray class>>finalizationProcess 1.0% {191ms} WeakSet>>scanFor:

**Memory** old +16,777,216 bytes young -17,303,480 bytes used -526,264 bytes free +17,303,480 bytes

**GCs** full 1 totalling 247ms (1.0% uptime), avg 247.0ms incr 127 totalling 199ms (1.0% uptime), avg 2.0ms tenures 480,033 (avg 0 GCs/tenure) root table 0 overflows

Thanks in advance, Vitor

Ok, my mistake was not take in account that DO has a MUCH faster link than the the one I have at home... :/ Those ten I/O calls traffics more than 5Mb, so you are right Sven :) Ben: I tried to change the Delay Scheduler, but the problem is that there is actually too much I/O wait.There was also no difference between running on Windows or Linux platform. On Thu, Sep 8, 2016 at 2:48 PM, Vitor Medina Cruz <vitormcruz@gmail.com> wrote:

Why not ? You are doing (lot's of) network I/O. It is normal that your

...

image code has to wait from time to time for data to come in from the network. By definition that is slow (in CPU terms). The Digital Ocean instance is probably faster in that respect.

But only the wait time corresponds to 73% (~13 seconds in no CPU time) of the entire procedure, which is taking ~18 seconds total. In the remote server the same procedure takes only ~6 seconds, supposing it still takes 73% in waiting it would give us ~4 seconds in wait time. I think 4 seconds to 13 seconds of difference for wait time is too much, it is not? The maximum I/O calls I am doing is ten. It is like it takes more than one second waiting for response, which does not seems right. I will do additional tests.

...

Also, having the IDE UI with lot's of tools open might influence things. Best do some more experiments. But benchmarking is very tricky.

Yes, I will try doing different stuff here!

Thanks! Vitor

On Thu, Sep 8, 2016 at 9:09 AM, Sven Van Caekenberghe <sven@stfx.eu> wrote:

...

...

On 08 Sep 2016, at 14:01, Vitor Medina Cruz <vitormcruz@gmail.com> wrote:

Thanks for the answers!

If this is time spent on I/O it is really strange. I am consuming the Twitter API and it don't get so much time like this to get a response. Besides, while those profiles were made at a Windows 10 local machine, the same code on a Pharo 5 (get.pharo.org) deployed on a linux deploy on Digital Ocean takes ~6 seconds, which means that a lot less time is spent on I/O. Isn't that Strange? I will try to spin up a local linux machine with both a headfull and headless Pharo to see if this time changes.

Is there a way to profile a remote image? I would like to see what is happening in the Digital Ocean deploy. Maybe put the headless Pharo there in profiling mode?

Ben: this is a heavy json parser procedure, I would expect to NeoJson to take some time. Perhaps there is a way to optimize this, but what catch my attention was the huge amount of time spent on the idleProcess. Been that I/O wait, it shouldn't be like this.

Why not ? You are doing (lot's of) network I/O. It is normal that your image code has to wait from time to time for data to come in from the network. By definition that is slow (in CPU terms). The Digital Ocean instance is probably faster in that respect.

Also, having the IDE UI with lot's of tools open might influence things. Best do some more experiments. But benchmarking is very tricky.

...

Thanks, Vitor

On Thu, Sep 8, 2016 at 4:42 AM, Clément Bera <bera.clement@gmail.com> wrote:

On Thu, Sep 8, 2016 at 3:44 AM, Vitor Medina Cruz <vitormcruz@gmail.com> wrote: Hello,

While profiling some I/O code that takes ~20 seconds to execute under my local image, the report says that about ~13 seconds is waste on OtherProcesses -> ProcessorScheduler class>>idleProcess. I could not understand what this idleProcess do by looking at the code. First I thought this could be time waiting the I/O operation to terminate, but that don't make much sense because I have the same code on a Digital Ocean Doplet and it takes ~6 seconds to execute.

Can someone help me understand what does this time on idleProcess means?

The VM is not event-driven. Hence when all the processes are suspended or terminated, the VM falls back to the idle process. The idle process waits for 1ms, checks if any event has occurred and/or if a process can restart, and if not waits for 1 more ms to check again. That's kind of dumb but it works and we need both time and funds to make the VM event-driven (in the latter case the VM restarts directly when an event happens, instead of checking at the next ms).

Basically the idle process profiled time is the time where Pharo has nothing to do because all processes are terminated or suspended. You can say that it is the time spent in I/O operations + the time before Pharo notices the I/O operation is terminated, which can be up to 1ms.

The full report is:

- 18407 tallies, 18605 msec.

**Tree** -------------------------------- Process: (40s) Morphic UI Process: nil -------------------------------- 25.1% {4663ms} UndefinedObject>>DoIt 25.1% {4663ms} TweetsServiceRestConsumer(Twee tsService)>>hashesTop:usingLastTweetsUpTo:fromHandler: 25.0% {4656ms} TweetsServiceRestConsumer>>fet chLastTweetsUpTo:fromHandler: 14.3% {2653ms} OAuthProvider>>httpGet: |14.3% {2653ms} ZnOAuth1Service>>httpGet:using: | 14.3% {2653ms} ZnOAuth1Service>>executeRequest:token: | 14.3% {2653ms} ZnOAuth1Service>>executeReques t:token:followRedirects: | 14.2% {2646ms} ZnClient>>execute | 14.2% {2646ms} ZnClient>>withProgressDo: | 14.2% {2646ms} ZnSignalProgress class(DynamicVariable class)>>value:during: | 14.2% {2646ms} ZnSignalProgress(DynamicVariab le)>>value:during: | 14.2% {2646ms} BlockClosure>>ensure: | 14.2% {2646ms} ZnSignalProgress(DynamicVariab le)>>value:during: | 14.2% {2646ms} ZnClient>>withProgressDo: | 14.2% {2646ms} ZnClient>>execute | 14.2% {2646ms} ZnClient>>executeWithTimeout | 14.2% {2646ms} ZnClient>>withTimeoutDo: | 14.2% {2646ms} ZnConnectionTimeout class(DynamicVariable class)>>value:during: | 14.2% {2646ms} ZnConnectionTimeout(DynamicVariable)>>value:during: | 14.2% {2646ms} BlockClosure>>ensure: | 14.2% {2646ms} ZnConnectionTimeout(DynamicVariable)>>value:during: | 14.2% {2646ms} ZnClient>>withTimeoutDo: | 14.2% {2646ms} ZnClient>>executeWithTimeout | 14.2% {2646ms} BlockClosure>>on:do: | 14.2% {2646ms} ZnClient>>executeWithTimeout | 14.2% {2646ms} ZnClient>>executeWithRetriesRemaining: | 14.2% {2644ms} BlockClosure>>on:do: | 14.2% {2644ms} ZnClient>>executeWithRetriesRemaining: | 14.2% {2644ms} ZnClient>>executeWithRedirectsRemaining: | 14.2% {2641ms} ZnClient>>getConnectionAndExecute | 13.8% {2569ms} BlockClosure>>ensure: | 13.8% {2569ms} ZnClient>>getConnectionAndExecute | 13.8% {2569ms} ZnClient>>executeRequestResponse | 13.8% {2569ms} ZnClient>>readResponse | 13.8% {2569ms} ZnResponse class(ZnMessage class)>>readFrom: | 13.8% {2569ms} ZnResponse(ZnMessage)>>readFrom: | 13.8% {2559ms} ZnResponse>>readEntityFrom: | 13.8% {2559ms} ZnResponse(ZnMessage)>>readEntityFrom: | 13.8% {2559ms} ZnEntityReader>>readEntity | 13.8% {2559ms} ZnEntityReader>>readEntityFromStream | 13.7% {2555ms} ZnEntityReader>>readFrom:usingType:andLength: | 13.7% {2555ms} ZnEntity class>>readFrom:usingType:andLength: | 13.7% {2555ms} ZnStringEntity>>readFrom: | 13.7% {2550ms} BlockClosure>>on:do: | 13.7% {2550ms} ZnStringEntity>>readFrom: | 13.7% {2550ms} ZnUTF8Encoder>>readInto:starti ngAt:count:fromStream: | 13.7% {2550ms} ZnUTF8Encoder>>optimizedReadIn to:startingAt:count:fromStream: | 13.7% {2550ms} ZnLimitedReadStream>>readInto: startingAt:count: | 13.7% {2547ms} ZdcSecureSocketStream(ZdcOptim izedSocketStream)>>readInto:startingAt:count: | 13.7% {2547ms} ZdcSecureSocketStream(ZdcSimpl eSocketStream)>>fillReadBuffer | 9.0% {1669ms} ZdcSecureSocketStream(ZdcSimpl eSocketStream)>>fillReadBuffer | |5.8% {1076ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | |3.6% {671ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | | |1.8% {337ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | | | |1.2% {225ms} BlockClosure>>on:do: | | | | | 1.2% {225ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | | | | 1.2% {225ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData | | | | | 1.2% {225ms} Socket>>waitForDataFor: | | | | | 1.2% {225ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: | | | | | 1.2% {225ms} Semaphore>>waitTimeoutMSecs: | | | | | 1.2% {225ms} DelayWaitTimeout>>wait | | | | | 1.2% {225ms} BlockClosure>>ensure: | | | | | 1.2% {225ms} DelayWaitTimeout>>wait | | | | | 1.1% {196ms} DelayWaitTimeout(Delay)>>unschedule | | | | | 1.1% {196ms} DelayExperimentalSpinScheduler>>unschedule: | | | |1.8% {335ms} BlockClosure>>on:do: | | | | 1.8% {335ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | | | 1.8% {335ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData | | | | 1.8% {335ms} Socket>>waitForDataFor: | | | | 1.8% {335ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: | | | | 1.8% {335ms} Semaphore>>waitTimeoutMSecs: | | | | 1.8% {335ms} DelayWaitTimeout>>wait | | | | 1.8% {335ms} BlockClosure>>ensure: | | | | 1.8% {335ms} DelayWaitTimeout>>wait | | | | 1.5% {273ms} DelayWaitTimeout(Delay)>>unschedule | | | | 1.5% {273ms} DelayExperimentalSpinScheduler>>unschedule: | | |2.2% {405ms} BlockClosure>>on:do: | | | 2.2% {405ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | | 2.2% {405ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData | | | 2.2% {405ms} Socket>>waitForDataFor: | | | 2.2% {405ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: | | | 2.2% {405ms} Semaphore>>waitTimeoutMSecs: | | | 2.2% {405ms} DelayWaitTimeout>>wait | | | 2.2% {405ms} BlockClosure>>ensure: | | | 2.2% {405ms} DelayWaitTimeout>>wait | | | 1.7% {314ms} DelayWaitTimeout(Delay)>>unschedule | | | 1.7% {314ms} DelayExperimentalSpinScheduler>>unschedule: | |3.2% {592ms} BlockClosure>>on:do: | | 3.2% {592ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer | | 3.2% {592ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData | | 3.2% {592ms} Socket>>waitForDataFor: | | 3.2% {592ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: | | 3.2% {592ms} Semaphore>>waitTimeoutMSecs: | | 3.2% {592ms} DelayWaitTimeout>>wait | | 3.2% {592ms} BlockClosure>>ensure: | | 3.2% {592ms} DelayWaitTimeout>>wait | | 2.3% {429ms} DelayWaitTimeout(Delay)>>unschedule | | 2.3% {429ms} DelayExperimentalSpinScheduler>>unschedule: | 4.7% {876ms} BlockClosure>>on:do: | 4.7% {876ms} ZdcSecureSocketStream(ZdcSimpl eSocketStream)>>fillReadBuffer | 4.7% {876ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData | 4.7% {876ms} Socket>>waitForDataFor: | 4.7% {876ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: | 4.7% {876ms} Semaphore>>waitTimeoutMSecs: | 4.7% {876ms} DelayWaitTimeout>>wait | 4.7% {876ms} BlockClosure>>ensure: | 4.7% {876ms} DelayWaitTimeout>>wait | 2.9% {532ms} DelayWaitTimeout(Delay)>>unschedule | |2.9% {532ms} DelayExperimentalSpinScheduler>>unschedule: | 1.4% {268ms} primitives 10.8% {2002ms} NeoJSONObject class>>fromString: 10.8% {2002ms} NeoJSONReader>>next 10.8% {2002ms} NeoJSONReader>>parseValue 10.8% {2002ms} NeoJSONReader>>parseList 10.8% {2002ms} Array class(SequenceableCollection class)>>streamContents: 10.8% {2002ms} Array class(SequenceableCollection class)>>new:streamContents: 10.8% {2002ms} NeoJSONReader>>parseList 10.8% {2002ms} NeoJSONReader>>parseListElementsDo: 10.8% {2002ms} NeoJSONReader>>parseListDo: 10.8% {2002ms} NeoJSONReader>>parseListElemen tsDo: 10.8% {2002ms} NeoJSONReader>>parseValue 10.8% {2002ms} NeoJSONReader>>parseMap 10.8% {2002ms} NeoJSONReader>>parseMapKeysAndValuesDo: 10.8% {2002ms} NeoJSONReader>>parseMapKeysDo: 10.8% {2002ms} NeoJSONReader>>parseMapDo: 10.7% {1994ms} NeoJSONReader>>parseMapKeysDo: 9.6% {1785ms} NeoJSONReader>>parseMapKeysAndValuesDo: |9.2% {1717ms} NeoJSONReader>>parseValue | 8.6% {1600ms} NeoJSONReader>>parseMap | 8.6% {1600ms} NeoJSONReader>>parseMapKeysAndValuesDo: | 8.6% {1600ms} NeoJSONReader>>parseMapKeysDo: | 8.6% {1600ms} NeoJSONReader>>parseMapDo: | 8.5% {1577ms} NeoJSONReader>>parseMapKeysDo: | 6.4% {1187ms} NeoJSONReader>>parseMapKeysAndValuesDo: | |5.6% {1041ms} NeoJSONReader>>parseValue | | 3.8% {708ms} NeoJSONReader>>parseList | | 3.8% {706ms} Array class(SequenceableCollection class)>>streamContents: | | 3.8% {706ms} Array class(SequenceableCollection class)>>new:streamContents: | | 3.7% {693ms} NeoJSONReader>>parseList | | 3.7% {693ms} NeoJSONReader>>parseListElementsDo: | | 3.7% {693ms} NeoJSONReader>>parseListDo: | | 3.7% {689ms} NeoJSONReader>>parseListElementsDo: | | 3.7% {689ms} NeoJSONReader>>parseValue | | 3.7% {687ms} NeoJSONReader>>parseMap | | 3.7% {687ms} NeoJSONReader>>parseMapKeysAndValuesDo: | | 3.7% {687ms} NeoJSONReader>>parseMapKeysDo: | | 3.7% {687ms} NeoJSONReader>>parseMapDo: | | 3.6% {672ms} NeoJSONReader>>parseMapKeysDo: | | 3.0% {550ms} NeoJSONReader>>parseMapKeysAndValuesDo: | | 2.6% {486ms} NeoJSONReader>>parseValue | | 1.5% {285ms} NeoJSONReader>>parseMap | | 1.5% {285ms} NeoJSONReader>>parseMapKeysAndValuesDo: | | 1.5% {285ms} NeoJSONReader>>parseMapKeysDo: | | 1.5% {285ms} NeoJSONReader>>parseMapDo: | | 1.5% {285ms} NeoJSONReader>>parseMapKeysDo: | | 1.4% {252ms} NeoJSONReader>>parseMapKeysAnd ValuesDo: | | 1.3% {236ms} NeoJSONReader>>parseValue | | 1.0% {193ms} NeoJSONReader>>parseMap | | 1.0% {193ms} NeoJSONReader>>parseMapKeysAnd ValuesDo: | | 1.0% {193ms} NeoJSONReader>>parseMapKeysDo: | | 1.0% {188ms} NeoJSONReader>>parseMapDo: | 1.9% {347ms} NeoJSONReader>>parsePropertyName | 1.1% {196ms} NeoJSONReader>>parseValue | 1.0% {189ms} NeoJSONReader>>parseString 1.0% {189ms} NeoJSONReader>>parsePropertyName -------------------------------- Process: other processes -------------------------------- 73.2% {13628ms} ProcessorScheduler class>>startUp |73.2% {13628ms} ProcessorScheduler class>>idleProcess 1.4% {259ms} WeakArray class>>restartFinalizationProcess 1.4% {259ms} WeakArray class>>finalizationProcess 1.4% {257ms} primitives **Leaves** 73.3% {13631ms} ProcessorScheduler class>>idleProcess 10.0% {1861ms} DelayExperimentalSpinScheduler>>unschedule: 3.1% {581ms} DelayWaitTimeout>>wait 1.4% {257ms} WeakArray class>>finalizationProcess 1.0% {191ms} WeakSet>>scanFor:

**Memory** old +16,777,216 bytes young -17,303,480 bytes used -526,264 bytes free +17,303,480 bytes

**GCs** full 1 totalling 247ms (1.0% uptime), avg 247.0ms incr 127 totalling 199ms (1.0% uptime), avg 2.0ms tenures 480,033 (avg 0 GCs/tenure) root table 0 overflows

Thanks in advance, Vitor

Hi vitor can you open a bug entry about the clean up process because it should work? if I remember well every image we produce gets the clean for production code run. Stef Le 10/9/16 à 17:32, Vitor Medina Cruz a écrit :

Also, I could not test with a cleaned image since this procedure doesn't seems to be working.... I get errors in a UI pharo or it goes forever in the headless mode.

On Sat, Sep 10, 2016 at 12:30 PM, Vitor Medina Cruz <vitormcruz@gmail.com <mailto:vitormcruz@gmail.com>> wrote:

Ok, my mistake was not take in account that DO has a MUCH faster link than the the one I have at home... :/ Those ten I/O calls traffics more than 5Mb, so you are right Sven :)

Ben: I tried to change the Delay Scheduler, but the problem is that there is actually too much I/O wait.There was also no difference between running on Windows or Linux platform.

On Thu, Sep 8, 2016 at 2:48 PM, Vitor Medina Cruz <vitormcruz@gmail.com <mailto:vitormcruz@gmail.com>> wrote:

Why not ? You are doing (lot's of) network I/O. It is normal that your image code has to wait from time to time for data to come in from the network. By definition that is slow (in CPU terms). The Digital Ocean instance is probably faster in that respect.

But only the wait time corresponds to 73% (~13 seconds in no CPU time) of the entire procedure, which is taking ~18 seconds total. In the remote server the same procedure takes only ~6 seconds, supposing it still takes 73% in waiting it would give us ~4 seconds in wait time. I think 4 seconds to 13 seconds of difference for wait time is too much, it is not? The maximum I/O calls I am doing is ten. It is like it takes more than one second waiting for response, which does not seems right. I will do additional tests.

Also, having the IDE UI with lot's of tools open might influence things. Best do some more experiments. But benchmarking is very tricky.

Yes, I will try doing different stuff here!

Thanks! Vitor

On Thu, Sep 8, 2016 at 9:09 AM, Sven Van Caekenberghe <sven@stfx.eu <mailto:sven@stfx.eu>> wrote:

> On 08 Sep 2016, at 14:01, Vitor Medina Cruz <vitormcruz@gmail.com <mailto:vitormcruz@gmail.com>> wrote: > > Thanks for the answers! > > If this is time spent on I/O it is really strange. I am consuming the Twitter API and it don't get so much time like this to get a response. Besides, while those profiles were made at a Windows 10 local machine, the same code on a Pharo 5 (get.pharo.org <http://get.pharo.org>) deployed on a linux deploy on Digital Ocean takes ~6 seconds, which means that a lot less time is spent on I/O. Isn't that Strange? I will try to spin up a local linux machine with both a headfull and headless Pharo to see if this time changes. > > Is there a way to profile a remote image? I would like to see what is happening in the Digital Ocean deploy. Maybe put the headless Pharo there in profiling mode? > > Ben: this is a heavy json parser procedure, I would expect to NeoJson to take some time. Perhaps there is a way to optimize this, but what catch my attention was the huge amount of time spent on the idleProcess. Been that I/O wait, it shouldn't be like this.

Why not ? You are doing (lot's of) network I/O. It is normal that your image code has to wait from time to time for data to come in from the network. By definition that is slow (in CPU terms). The Digital Ocean instance is probably faster in that respect.

Also, having the IDE UI with lot's of tools open might influence things. Best do some more experiments. But benchmarking is very tricky.

> Thanks, > Vitor > > On Thu, Sep 8, 2016 at 4:42 AM, Clément Bera <bera.clement@gmail.com <mailto:bera.clement@gmail.com>> wrote: > > > On Thu, Sep 8, 2016 at 3:44 AM, Vitor Medina Cruz <vitormcruz@gmail.com <mailto:vitormcruz@gmail.com>> wrote: > Hello, > > While profiling some I/O code that takes ~20 seconds to execute under my local image, the report says that about ~13 seconds is waste on OtherProcesses -> ProcessorScheduler class>>idleProcess. I could not understand what this idleProcess do by looking at the code. First I thought this could be time waiting the I/O operation to terminate, but that don't make much sense because I have the same code on a Digital Ocean Doplet and it takes ~6 seconds to execute. > > Can someone help me understand what does this time on idleProcess means? > > The VM is not event-driven. Hence when all the processes are suspended or terminated, the VM falls back to the idle process. The idle process waits for 1ms, checks if any event has occurred and/or if a process can restart, and if not waits for 1 more ms to check again. That's kind of dumb but it works and we need both time and funds to make the VM event-driven (in the latter case the VM restarts directly when an event happens, instead of checking at the next ms). > > Basically the idle process profiled time is the time where Pharo has nothing to do because all processes are terminated or suspended. You can say that it is the time spent in I/O operations + the time before Pharo notices the I/O operation is terminated, which can be up to 1ms. > > > > The full report is: > > - 18407 tallies, 18605 msec. > > **Tree** > -------------------------------- > Process: (40s) Morphic UI Process: nil > -------------------------------- > 25.1% {4663ms} UndefinedObject>>DoIt > 25.1% {4663ms} TweetsServiceRestConsumer(TweetsService)>>hashesTop:usingLastTweetsUpTo:fromHandler: > 25.0% {4656ms} TweetsServiceRestConsumer>>fetchLastTweetsUpTo:fromHandler: > 14.3% {2653ms} OAuthProvider>>httpGet: > |14.3% {2653ms} ZnOAuth1Service>>httpGet:using: > | 14.3% {2653ms} ZnOAuth1Service>>executeRequest:token: > | 14.3% {2653ms} ZnOAuth1Service>>executeRequest:token:followRedirects: > | 14.2% {2646ms} ZnClient>>execute > | 14.2% {2646ms} ZnClient>>withProgressDo: > | 14.2% {2646ms} ZnSignalProgress class(DynamicVariable class)>>value:during: > | 14.2% {2646ms} ZnSignalProgress(DynamicVariable)>>value:during: > | 14.2% {2646ms} BlockClosure>>ensure: > | 14.2% {2646ms} ZnSignalProgress(DynamicVariable)>>value:during: > | 14.2% {2646ms} ZnClient>>withProgressDo: > | 14.2% {2646ms} ZnClient>>execute > | 14.2% {2646ms} ZnClient>>executeWithTimeout > | 14.2% {2646ms} ZnClient>>withTimeoutDo: > | 14.2% {2646ms} ZnConnectionTimeout class(DynamicVariable class)>>value:during: > | 14.2% {2646ms} ZnConnectionTimeout(DynamicVariable)>>value:during: > | 14.2% {2646ms} BlockClosure>>ensure: > | 14.2% {2646ms} ZnConnectionTimeout(DynamicVariable)>>value:during: > | 14.2% {2646ms} ZnClient>>withTimeoutDo: > | 14.2% {2646ms} ZnClient>>executeWithTimeout > | 14.2% {2646ms} BlockClosure>>on:do: > | 14.2% {2646ms} ZnClient>>executeWithTimeout > | 14.2% {2646ms} ZnClient>>executeWithRetriesRemaining: > | 14.2% {2644ms} BlockClosure>>on:do: > | 14.2% {2644ms} ZnClient>>executeWithRetriesRemaining: > | 14.2% {2644ms} ZnClient>>executeWithRedirectsRemaining: > | 14.2% {2641ms} ZnClient>>getConnectionAndExecute > | 13.8% {2569ms} BlockClosure>>ensure: > | 13.8% {2569ms} ZnClient>>getConnectionAndExecute > | 13.8% {2569ms} ZnClient>>executeRequestResponse > | 13.8% {2569ms} ZnClient>>readResponse > | 13.8% {2569ms} ZnResponse class(ZnMessage class)>>readFrom: > | 13.8% {2569ms} ZnResponse(ZnMessage)>>readFrom: > | 13.8% {2559ms} ZnResponse>>readEntityFrom: > | 13.8% {2559ms} ZnResponse(ZnMessage)>>readEntityFrom: > | 13.8% {2559ms} ZnEntityReader>>readEntity > | 13.8% {2559ms} ZnEntityReader>>readEntityFromStream > | 13.7% {2555ms} ZnEntityReader>>readFrom:usingType:andLength: > | 13.7% {2555ms} ZnEntity class>>readFrom:usingType:andLength: > | 13.7% {2555ms} ZnStringEntity>>readFrom: > | 13.7% {2550ms} BlockClosure>>on:do: > | 13.7% {2550ms} ZnStringEntity>>readFrom: > | 13.7% {2550ms} ZnUTF8Encoder>>readInto:startingAt:count:fromStream: > | 13.7% {2550ms} ZnUTF8Encoder>>optimizedReadInto:startingAt:count:fromStream: > | 13.7% {2550ms} ZnLimitedReadStream>>readInto:startingAt:count: > | 13.7% {2547ms} ZdcSecureSocketStream(ZdcOptimizedSocketStream)>>readInto:startingAt:count: > | 13.7% {2547ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer > | 9.0% {1669ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer > | |5.8% {1076ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer > | | |3.6% {671ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer > | | | |1.8% {337ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer > | | | | |1.2% {225ms} BlockClosure>>on:do: > | | | | | 1.2% {225ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer > | | | | | 1.2% {225ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData > | | | | | 1.2% {225ms} Socket>>waitForDataFor: > | | | | | 1.2% {225ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: > | | | | | 1.2% {225ms} Semaphore>>waitTimeoutMSecs: > | | | | | 1.2% {225ms} DelayWaitTimeout>>wait > | | | | | 1.2% {225ms} BlockClosure>>ensure: > | | | | | 1.2% {225ms} DelayWaitTimeout>>wait > | | | | | 1.1% {196ms} DelayWaitTimeout(Delay)>>unschedule > | | | | | 1.1% {196ms} DelayExperimentalSpinScheduler>>unschedule: > | | | |1.8% {335ms} BlockClosure>>on:do: > | | | | 1.8% {335ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer > | | | | 1.8% {335ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData > | | | | 1.8% {335ms} Socket>>waitForDataFor: > | | | | 1.8% {335ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: > | | | | 1.8% {335ms} Semaphore>>waitTimeoutMSecs: > | | | | 1.8% {335ms} DelayWaitTimeout>>wait > | | | | 1.8% {335ms} BlockClosure>>ensure: > | | | | 1.8% {335ms} DelayWaitTimeout>>wait > | | | | 1.5% {273ms} DelayWaitTimeout(Delay)>>unschedule > | | | | 1.5% {273ms} DelayExperimentalSpinScheduler>>unschedule: > | | |2.2% {405ms} BlockClosure>>on:do: > | | | 2.2% {405ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer > | | | 2.2% {405ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData > | | | 2.2% {405ms} Socket>>waitForDataFor: > | | | 2.2% {405ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: > | | | 2.2% {405ms} Semaphore>>waitTimeoutMSecs: > | | | 2.2% {405ms} DelayWaitTimeout>>wait > | | | 2.2% {405ms} BlockClosure>>ensure: > | | | 2.2% {405ms} DelayWaitTimeout>>wait > | | | 1.7% {314ms} DelayWaitTimeout(Delay)>>unschedule > | | | 1.7% {314ms} DelayExperimentalSpinScheduler>>unschedule: > | |3.2% {592ms} BlockClosure>>on:do: > | | 3.2% {592ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer > | | 3.2% {592ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData > | | 3.2% {592ms} Socket>>waitForDataFor: > | | 3.2% {592ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: > | | 3.2% {592ms} Semaphore>>waitTimeoutMSecs: > | | 3.2% {592ms} DelayWaitTimeout>>wait > | | 3.2% {592ms} BlockClosure>>ensure: > | | 3.2% {592ms} DelayWaitTimeout>>wait > | | 2.3% {429ms} DelayWaitTimeout(Delay)>>unschedule > | | 2.3% {429ms} DelayExperimentalSpinScheduler>>unschedule: > | 4.7% {876ms} BlockClosure>>on:do: > | 4.7% {876ms} ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer > | 4.7% {876ms} ZdcSecureSocketStream(ZdcAbstractSocketStream)>>socketWaitForData > | 4.7% {876ms} Socket>>waitForDataFor: > | 4.7% {876ms} Socket>>waitForDataFor:ifClosed:ifTimedOut: > | 4.7% {876ms} Semaphore>>waitTimeoutMSecs: > | 4.7% {876ms} DelayWaitTimeout>>wait > | 4.7% {876ms} BlockClosure>>ensure: > | 4.7% {876ms} DelayWaitTimeout>>wait > | 2.9% {532ms} DelayWaitTimeout(Delay)>>unschedule > | |2.9% {532ms} DelayExperimentalSpinScheduler>>unschedule: > | 1.4% {268ms} primitives > 10.8% {2002ms} NeoJSONObject class>>fromString: > 10.8% {2002ms} NeoJSONReader>>next > 10.8% {2002ms} NeoJSONReader>>parseValue > 10.8% {2002ms} NeoJSONReader>>parseList > 10.8% {2002ms} Array class(SequenceableCollection class)>>streamContents: > 10.8% {2002ms} Array class(SequenceableCollection class)>>new:streamContents: > 10.8% {2002ms} NeoJSONReader>>parseList > 10.8% {2002ms} NeoJSONReader>>parseListElementsDo: > 10.8% {2002ms} NeoJSONReader>>parseListDo: > 10.8% {2002ms} NeoJSONReader>>parseListElementsDo: > 10.8% {2002ms} NeoJSONReader>>parseValue > 10.8% {2002ms} NeoJSONReader>>parseMap > 10.8% {2002ms} NeoJSONReader>>parseMapKeysAndValuesDo: > 10.8% {2002ms} NeoJSONReader>>parseMapKeysDo: > 10.8% {2002ms} NeoJSONReader>>parseMapDo: > 10.7% {1994ms} NeoJSONReader>>parseMapKeysDo: > 9.6% {1785ms} NeoJSONReader>>parseMapKeysAndValuesDo: > |9.2% {1717ms} NeoJSONReader>>parseValue > | 8.6% {1600ms} NeoJSONReader>>parseMap > | 8.6% {1600ms} NeoJSONReader>>parseMapKeysAndValuesDo: > | 8.6% {1600ms} NeoJSONReader>>parseMapKeysDo: > | 8.6% {1600ms} NeoJSONReader>>parseMapDo: > | 8.5% {1577ms} NeoJSONReader>>parseMapKeysDo: > | 6.4% {1187ms} NeoJSONReader>>parseMapKeysAndValuesDo: > | |5.6% {1041ms} NeoJSONReader>>parseValue > | | 3.8% {708ms} NeoJSONReader>>parseList > | | 3.8% {706ms} Array class(SequenceableCollection class)>>streamContents: > | | 3.8% {706ms} Array class(SequenceableCollection class)>>new:streamContents: > | | 3.7% {693ms} NeoJSONReader>>parseList > | | 3.7% {693ms} NeoJSONReader>>parseListElementsDo: > | | 3.7% {693ms} NeoJSONReader>>parseListDo: > | | 3.7% {689ms} NeoJSONReader>>parseListElementsDo: > | | 3.7% {689ms} NeoJSONReader>>parseValue > | | 3.7% {687ms} NeoJSONReader>>parseMap > | | 3.7% {687ms} NeoJSONReader>>parseMapKeysAndValuesDo: > | | 3.7% {687ms} NeoJSONReader>>parseMapKeysDo: > | | 3.7% {687ms} NeoJSONReader>>parseMapDo: > | | 3.6% {672ms} NeoJSONReader>>parseMapKeysDo: > | | 3.0% {550ms} NeoJSONReader>>parseMapKeysAndValuesDo: > | | 2.6% {486ms} NeoJSONReader>>parseValue > | | 1.5% {285ms} NeoJSONReader>>parseMap > | | 1.5% {285ms} NeoJSONReader>>parseMapKeysAndValuesDo: > | | 1.5% {285ms} NeoJSONReader>>parseMapKeysDo: > | | 1.5% {285ms} NeoJSONReader>>parseMapDo: > | | 1.5% {285ms} NeoJSONReader>>parseMapKeysDo: > | | 1.4% {252ms} NeoJSONReader>>parseMapKeysAndValuesDo: > | | 1.3% {236ms} NeoJSONReader>>parseValue > | | 1.0% {193ms} NeoJSONReader>>parseMap > | | 1.0% {193ms} NeoJSONReader>>parseMapKeysAndValuesDo: > | | 1.0% {193ms} NeoJSONReader>>parseMapKeysDo: > | | 1.0% {188ms} NeoJSONReader>>parseMapDo: > | 1.9% {347ms} NeoJSONReader>>parsePropertyName > | 1.1% {196ms} NeoJSONReader>>parseValue > | 1.0% {189ms} NeoJSONReader>>parseString > 1.0% {189ms} NeoJSONReader>>parsePropertyName > -------------------------------- > Process: other processes > -------------------------------- > 73.2% {13628ms} ProcessorScheduler class>>startUp > |73.2% {13628ms} ProcessorScheduler class>>idleProcess > 1.4% {259ms} WeakArray class>>restartFinalizationProcess > 1.4% {259ms} WeakArray class>>finalizationProcess > 1.4% {257ms} primitives > **Leaves** > 73.3% {13631ms} ProcessorScheduler class>>idleProcess > 10.0% {1861ms} DelayExperimentalSpinScheduler>>unschedule: > 3.1% {581ms} DelayWaitTimeout>>wait > 1.4% {257ms} WeakArray class>>finalizationProcess > 1.0% {191ms} WeakSet>>scanFor: > > **Memory** > old +16,777,216 bytes > young -17,303,480 bytes > used -526,264 bytes > free +17,303,480 bytes > > **GCs** > full 1 totalling 247ms (1.0% uptime), avg 247.0ms > incr 127 totalling 199ms (1.0% uptime), avg 2.0ms > tenures 480,033 (avg 0 GCs/tenure) > root table 0 overflows > > > Thanks in advance, > Vitor > >