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 <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 ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
-- _,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;: Alexandre Bergel http://www.bergel.eu ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.