- Pharo-users - lists.pharo.org

Re: [Pharo-users] Problem cleaning up image

by Petr Fischer

Hello, when I remember correctly when I tested cleaning last time, the problem was in the method ImageCleaner>>cleanUpForRelease (called form cleanUpForProduction). Try to comment "self cleanUpMethods." in ImageCleaner>>cleanUpForRelease - "cleanUpMethods" method never finish. Have you tried "minimal image" or "kernel image" (instead of cleaning full image)? pf > Hello, > > Isn't cleanup the headless image working right now? I know it has some > problems, but I tried to: > > curl get.pharo.org | bash > ./pharo Pharo.image clean --production > > It runs for hours and don't complete. Last time I leave it for about 5 > hours before I cancelled. > > Regards, > Vitor

Sept. 11, 2016

Re: [Pharo-users] Cryptography packages

by Paul DeBruicker

Years ago when Squeaksource was "going away" I made a copy of its Cryptography repo here: http://smalltalkhub.com/#!/~Cryptography/Cryptography Esteban A. Maringolo wrote > Hi there, > > What are the most maintaned/popular cryptography package for Pharo? > > Regards! > > Esteban A. Maringolo -- View this message in context: http://forum.world.st/Cryptography-packages-tp4915041p4915127.html Sent from the Pharo Smalltalk Users mailing list archive at Nabble.com.

Sept. 11, 2016

Re: [Pharo-users] Profiling

by stepharo

Hi vitor can you open a bug entry about the clean up process because it should work? if I remember well every image we produce gets the clean for production code run. Stef Le 10/9/16 Ã 17:32, Vitor Medina Cruz a Ã©crit : > 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(a)gmail.com <mailto: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(a)gmail.com <mailto: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(a)stfx.eu <mailto:sven@stfx.eu>> wrote: > > > > On 08 Sep 2016, at 14:01, Vitor Medina Cruz > <vitormcruz(a)gmail.com <mailto: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 <http://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(a)gmail.com <mailto:bera.clement@gmail.com>> > wrote: > > > > > > On Thu, Sep 8, 2016 at 3:44 AM, Vitor Medina Cruz > <vitormcruz(a)gmail.com <mailto: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 > > > > > > > > >

Sept. 10, 2016

Re: [Pharo-users] Cryptography packages

by Esteban A. Maringolo

Thanks tocayo, I see the latest metacello config was done by you, but I can't load it because I get a MNU exception in the initialization of VintageFrame class, becasue ASN1Module is not in my image. initializeAsn1Der ((ASN1Module name: #secureSession) sequence: #VintageFrame mapping: VintageFrame) add: #header type: #VintagePayloadHeader; add: #payload type: #ASN1AnyType; yourself. Any pointers? Esteban A. Maringolo 2016-09-10 3:14 GMT-03:00 Esteban Lorenzano <estebanlm(a)gmail.com>: > http://www.squeaksource.com/Cryptography.html > > some of the algorithms present there are already in the image, but others > donât :) > > Esteban > > On 10 Sep 2016, at 04:03, Esteban A. Maringolo <emaringolo(a)gmail.com> > wrote: > > Hi there, > > What are the most maintaned/popular cryptography package for Pharo? > > Regards! > > Esteban A. Maringolo > > >

Sept. 10, 2016

Re: [Pharo-users] Porting TalkFFI / LibClang to Pharo 5 UFFI

by Ben Coman

On Sat, Sep 10, 2016 at 3:14 PM, Ben Coman <btc(a)openinworld.com> wrote: > Looks like I've been reinventing the wheel making an FFI interface to > libclang. I just bumped into Ciprian's TalkFFI which provides a > NativeBoost interface to libclang (and was used to create libgit2 bindings) > > * https://rochiamaya.wordpress.com/2013/07/30/create- > bindings-with-talkffi/ > * http://smalltalkhub.com/#!/~CipT/TalkFFI > * http://smalltalkhub.com/#!/~CipT/LibClang > > But it is NativeBoost based and the Configuration loads AsmJit and > NativeBoost packages, which seems to lock up while "Initializing > Nativeboost." What is involved in porting TalkFFI to Pharo 5.0 UFFI? > > For a start, these can be manually load no problem... > LibClang-FFI-Types-CiprianTeodorov.2 > LibClang-Tests-CiprianTeodorov.5 > LibClang-Examples-CiprianTeodorov.2 > > but loading LibClang-FFI-Binding-CiprianTeodorov.1 > reports "This package depends on the following classes: > CLLibraryMap > CLExternalLibraryWrapper > You must resolve these dependencies before you will be able to load these > definitions: > CXIndexH" > > which I found these in TalkFFI-Runtime-CiprianTeodorov.7, but loading this > reports "This package depends on the following classes: > NBExternalLibraryWrapper > You must resolve these dependencies before you will be able to load these > definitions: > CLExternalLibraryWrapper > > which I see is in Pharo 4.0 and not Pharo 5.0. So what is the replacement > for NBExternalLibraryWrapper? > What are the other general patterns for porting NativeBoost apps to UFFI? > > For discussion I've compiled a rough comparison of classes of NativeBoost and UFFI. Quite a bit of guesswork though. Feel free to edit. Probably could be slimmed by removing less significant classes like tests and OS specific classes. https://docs.google.com/spreadsheets/d/1ZN6GUtzerh7KejODXNtze3njiGAryUUdSvk… cheers -ben

Sept. 10, 2016

Re: [Pharo-users] Profiling

by Vitor Medina Cruz

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(a)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(a)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(a)stfx.eu> >> wrote: >> >>> >>> > On 08 Sep 2016, at 14:01, Vitor Medina Cruz <vitormcruz(a)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(a)gmail.com> >>> wrote: >>> > >>> > >>> > On Thu, Sep 8, 2016 at 3:44 AM, Vitor Medina Cruz < >>> vitormcruz(a)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 >>> > >>> > >>> >>> >>> >> >

Sept. 10, 2016

Re: [Pharo-users] Profiling

by Vitor Medina Cruz

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(a)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(a)stfx.eu> > wrote: > >> >> > On 08 Sep 2016, at 14:01, Vitor Medina Cruz <vitormcruz(a)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(a)gmail.com> >> wrote: >> > >> > >> > On Thu, Sep 8, 2016 at 3:44 AM, Vitor Medina Cruz <vitormcruz(a)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>>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 >> > >> > >> >> >> >

Sept. 10, 2016

[ANN] Dr. Geo release 16.10a

by Hilaire

Dear Pharo fellows, I am proud to announce release 16.10a of Dr. Geo. It comes with the usual bug fixes and a new French programming API for French speaking kids: programmed sketch can be written in French Smalltalk! Read more at http://www.drgeo.eu/news/drgeo1610release Hilaire -- Dr. Geo http://drgeo.eu

Sept. 10, 2016

Porting TalkFFI / LibClang to Pharo 5 UFFI

by Ben Coman

Looks like I've been reinventing the wheel making an FFI interface to libclang. I just bumped into Ciprian's TalkFFI which provides a NativeBoost interface to libclang (and was used to create libgit2 bindings) * https://rochiamaya.wordpress.com/2013/07/30/create-bindings-with-talkffi/ * http://smalltalkhub.com/#!/~CipT/TalkFFI * http://smalltalkhub.com/#!/~CipT/LibClang But it is NativeBoost based and the Configuration loads AsmJit and NativeBoost packages, which seems to lock up while "Initializing Nativeboost." What is involved in porting TalkFFI to Pharo 5.0 UFFI? For a start, these can be manually load no problem... LibClang-FFI-Types-CiprianTeodorov.2 LibClang-Tests-CiprianTeodorov.5 LibClang-Examples-CiprianTeodorov.2 but loading LibClang-FFI-Binding-CiprianTeodorov.1 reports "This package depends on the following classes: CLLibraryMap CLExternalLibraryWrapper You must resolve these dependencies before you will be able to load these definitions: CXIndexH" which I found these in TalkFFI-Runtime-CiprianTeodorov.7, but loading this reports "This package depends on the following classes: NBExternalLibraryWrapper You must resolve these dependencies before you will be able to load these definitions: CLExternalLibraryWrapper which I see is in Pharo 4.0 and not Pharo 5.0. So what is the replacement for NBExternalLibraryWrapper? What are the other general patterns for porting NativeBoost apps to UFFI? cheers -ben

Sept. 10, 2016

Re: [Pharo-users] Adopting someone else's image

by Siemen Baader

Thanks. I found out that I had two unrelated problems. Spotter was one and not critical, and the reason I had errors with Monticello was that I had made the mistake to rename the .image file, so it didn't match the changes file anymore. Siemen -- View this message in context: http://forum.world.st/Adopting-someone-else-s-image-tp4914933p4915049.html Sent from the Pharo Smalltalk Users mailing list archive at Nabble.com.

Sept. 10, 2016