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
> ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
>
>
>
>
>
>
