On Thu, Sep 8, 2016 at 11:37 AM, Ben Coman <b...@openinworld.com> wrote:
> - 9989 tallies, 10003 msec.
>
> **Tree**
> --------------------------------
> Process: other processes
> --------------------------------
> 99.2% {9928ms} ProcessorScheduler class>>startUp
> 99.2% {9928ms} ProcessorScheduler class>>idleProcess
> **Leaves**
> 99.2% {9928ms} ProcessorScheduler class>>idleProcess
>
> **Memory**
> old +0 bytes
> young -223,912 bytes
> used -223,912 bytes
> free +223,912 bytes
>
> **GCs**
> full 0 totalling 0ms (0.0% uptime)
> incr 2 totalling 6ms (0.0% uptime), avg 3.0ms
> tenures 0
> root table 0 overflows
>
> On Thu, Sep 8, 2016 at 9:44 AM, Vitor Medina Cruz <vitormc...@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?
>
> I don't have an exact answer for you, but a comparative example...
>
> Tools > Time Profiler...
> 10 seconds wait
> Full report...
> ==========================================
> - 9989 tallies, 10003 msec.
>
> **Tree**
> --------------------------------
> Process: other processes
> --------------------------------
> 99.2% {9928ms} ProcessorScheduler class>>startUp
> 99.2% {9928ms} ProcessorScheduler class>>idleProcess
> **Leaves**
> 99.2% {9928ms} ProcessorScheduler class>>idleProcess
>
> **Memory**
> old +0 bytes
> young -223,912 bytes
> used -223,912 bytes
> free +223,912 bytes
>
> **GCs**
> full 0 totalling 0ms (0.0% uptime)
> incr 2 totalling 6ms (0.0% uptime), avg 3.0ms
> tenures 0
> root table 0 overflows
> ==========================================
>
> Now over that time, Windows 7 Task Manager showed Pharo process CPU load of
> 0%,
> indicating the 9.9 seconds spent in idleProcess has no impact on performance.
> Or put another way, for 99.2% of that 10 seconds Pharo was *not* busy.
>
> Applying that to your results, I would guess that for 73.3% of that 20
> seconds you were waiting on I/O.
>
> To find your performance issues, follow down the percentages for where
> there are big jumps without splits.
> That is, ignore jumps where the splits add up to the parent.
> For example 14.3 + 10.8 ==> 25.1 - so no lost performance here...
> 25.0% {4656ms} TweetsServiceRestConsumer>>fetchLastTweetsUpTo:fromHandler:
> 14.3% {2653ms} OAuthProvider>>httpGet:
> |
> 10.8% {2002ms} NeoJSONObject class>>fromString:
>
> Your biggest loss in a linear line seems to be...
> 5.6% {1041ms} NeoJSONReader>>parseValue
> to
> 1.5% {285ms} NeoJSONReader>>parseMap
>
>
> I am curious about the recursive calls to
> ZdcSecureSocketStream(ZdcSimpleSocketStream)>>fillReadBuffer
> and multiple accumulations from DelayExperimentalSpinScheduler>>unschedule:
> but that method doesn't really do a lot. I wouldn't expect the
> whileTrue loop to be spinning much, but you could examine that by
>
>
> You might try another scheduler...
> World>System>Settings>System>Delay Scheduler
Another experiment might try could be divide-and-conquer by examining
a sample of what is returned by...
10.8% {2002ms} NeoJSONObject class>>fromString:
and return a similar constant.
cheers -ben
