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 <vitormcruz@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 <vitormcruz@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 <sven@stfx.eu> wrote:
On 08 Sep 2016, at 14:01, Vitor Medina Cruz <vitormcruz@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.clement@gmail.com> wrote:
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(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