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