Re: [Pharo-users] Profiling

Sept. 8, 2016


      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

Re: [Pharo-users] Profiling

ClÃ©ment Bera