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 <alexandre.bergel@me.com>:
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 ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.