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