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.
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(ZdcSimpl
>> eSocketStream)>>fillReadBuffer
>> |
>> | |3.6% {671ms} ZdcSecureSocketStream(ZdcSimpl
>> eSocketStream)>>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(ZdcSimpl
>> eSocketStream)>>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(ZdcAbstr
>> actSocketStream)>>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
>>
>
>
