Good point!
It actually makes sense. But how comes that 36% is spent in the eventLoop
method?
In some situation, the InputEventPollingFetcher>>eventLoop can take up to 90%
of the execution time.
I guess this is essentially to answer to Cmd-. right?
Cheers,
Alexandre
On 24 Dec 2011, at 13:18, Nicolas Cellier wrote:
> I did not check code, but to me, the symptoms look like the other
> processes are not reported but their are still counted in the
> percentage.
> You can compare the results of these two invocations:
>
> MessageTally spyOn: [1 to: 10000 do: [:i | Float pi storeString]].
>
> - 386 tallies, 389 msec.
>
> **Tree**
> --------------------------------
> Process: (40s) 328990720: nil
> --------------------------------
> 61.4% {239ms} Float>>storeOn:
> 61.4% {239ms} Float>>storeOn:base:
> 61.4% {239ms} Float>>absPrintExactlyOn:base:
> snip...
>
> MessageTally spyAllOn: [1 to: 10000 do: [:i | Float pi storeString]].
>
> - 386 tallies, 388 msec.
>
> **Tree**
> --------------------------------
> Process: other processes
> --------------------------------
> --------------------------------
> Process: (40s) 328990720: nil
> --------------------------------
> 58.5% {227ms} Float>>storeOn:
> 58.5% {227ms} Float>>storeOn:base:
> 57.5% {223ms} Float>>absPrintExactlyOn:base:
> snip...
> --------------------------------
> Process: (50) 240123904: WeakArray class>>finalizationProcess
> --------------------------------
> 2.6% {10ms} WeakArray class>>finalizationProcess
> --------------------------------
> Process: (60) Input events fetching process: [delaySemaphore wait] in
> Delay>>wait
> --------------------------------
> 36.3% {141ms} InputEventPollingFetcher(InputEventFetcher)>>eventLoop
> 36.3% {141ms} InputEventPollingFetcher>>waitForInput
> 36.3% {141ms} Delay>>wait
>
>
> Strangely in Squeak, spyOn: often reports about the finalizationProcess
>
> - 381 tallies, 381 msec.
>
> **Tree**
> --------------------------------
> Process: other processes
> --------------------------------
> 7.6% {29ms} WeakArray class>>finalizationProcess
> --------------------------------
> Process: (40s) 93165: nil
> --------------------------------
> 86.4% {329ms} Float>>storeOn:
> |86.4% {329ms} Float>>storeOn:base:
> | 85.8% {327ms} Float>>absPrintExactlyOn:base:
> | 41.5% {158ms} False>>|
> snip...
>
> Nicolas
>
> 2011/12/24 Alexandre Bergel <[email protected]>:
>> I am not familiar with CUIS. But MessageTally is implemented in just one
>> class. I commented it and some added tests a few months ago.
>>
>> In Visualworks, the root of the callgraph is always reported at 100%.
>>
>> I will continue to work on the Pharo version.
>>
>> Alexandre
>>
>>
>> On 24 Dec 2011, at 11:52, Stéphane Ducasse wrote:
>>
>>> Alex
>>>
>>> normally I integrated the fixes of juan long time ago. Now could you have a
>>> look at CUIS to see if you get the same effect.
>>>
>>> Stef
>>>
>>> On Dec 24, 2011, at 3:29 PM, Alexandre Bergel wrote:
>>>
>>>>> This means that some other process (probably the finalization process,
>>>>> since #factorial creates a lot of garbage) was running and/or gc happened
>>>>> during the "missing" 34.2%. The gc times are listed below.
>>>>
>>>> I also thought about that. But I doubt this is the only reason. I tried:
>>>>
>>>> MessageTally spyOn: [ 100 timesRepeat: [XMLDOMParser parse: (FileStream
>>>> fileNamed: 'path to an xml file') contents ]].
>>>>
>>>> and I obtain
>>>> -=-=-=-=-=-=-=-=-=-=-=-=
>>>> - 168 tallies, 168 msec.
>>>>
>>>> **Tree**
>>>> --------------------------------
>>>> Process: (40s) 754188288: nil
>>>> --------------------------------
>>>> 18.5% {31ms} XMLDOMParser>>parseDocument
>>>> 18.5% {31ms} XMLDOMParser(SAXHandler)>>parseDocument
>>>> 18.5% {31ms} XMLParser>>parseDocument
>>>> 18.5% {31ms} XMLParser>>parseToken
>>>> 18.5% {31ms} XMLTokenizer>>nextToken
>>>> 16.1% {27ms} XMLTokenizer>>nextMarkupToken
>>>> -=-=-=-=-=-=-=-=-=-=-=-=
>>>>
>>>> The memory stat are
>>>> -=-=-=-=-=-=-=-=-=-=-=-=
>>>>
>>>> **Memory**
>>>> old +120,524 bytes
>>>> young -442,960 bytes
>>>> used -322,436 bytes
>>>> free +322,436 bytes
>>>>
>>>> **GCs**
>>>> full 0 totalling 0ms (0.0% uptime)
>>>> incr 12 totalling 5ms (3.0% uptime), avg 0.0ms
>>>> tenures 2 (avg 6 GCs/tenure)
>>>> root table 0 overflows
>>>> -=-=-=-=-=-=-=-=-=-=-=-=
>>>>
>>>>
>>>> The factorial example consumes more memory, and it is reported to consume
>>>> 72%
>>>>
>>>> Something is weird. I will look into it.
>>>>
>>>> Cheers,
>>>> Alexandre
>>>> --
>>>> _,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:
>>>> Alexandre Bergel http://www.bergel.eu
>>>> ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
>>>>
>>>>
>>>>
>>>>
>>>>
>>>>
>>>
>>>
>>
>> --
>> _,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:
>> Alexandre Bergel http://www.bergel.eu
>> ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
>>
>>
>>
>>
>>
>>
>
--
_,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:
Alexandre Bergel http://www.bergel.eu
^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
