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 <vitormc...@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 <vitormc...@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 <s...@stfx.eu>
>> wrote:
>>
>>>
>>> > On 08 Sep 2016, at 14:01, Vitor Medina Cruz <vitormc...@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.clem...@gmail.com>
>>> wrote:
>>> >
>>> >
>>> > On Thu, Sep 8, 2016 at 3:44 AM, Vitor Medina Cruz <
>>> vitormc...@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>>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
>>> >
>>> >
>>>
>>>
>>>
>>
>
