On Thu, Sep 8, 2016 at 3:44 AM, Vitor Medina Cruz <[email protected]>
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
>
