[Pharo-project] Wrong number with message tally?
Hi! MessageTally seems to give wrong values regarding the relative time spent. Consider: MessageTally spyOn: [ 100 timesRepeat: [ 1000 factorial ] ] It gives something like: -=-=-=-=-=-=-=-=-=-=-=-= - 377 tallies, 379 msec. **Tree** -------------------------------- Process: (40s) 464519168: nil -------------------------------- 65.8% {249ms} SmallInteger(Integer)>>factorial 65.8% {249ms} SmallInteger(Integer)>>factorial 65.8% {249ms} SmallInteger(Integer)>>factorial 65.8% {249ms} SmallInteger(Integer)>>factorial ... -=-=-=-=-=-=-=-=-=-=-=-= I would expect to have 100% at the root of the call graph since other threads are not reported. Is there something I am missing? If no, then I will dive into MessageTally. This is annoying. Cheers, Alexandre -- _,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;: Alexandre Bergel http://www.bergel.eu ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
Doesn't it tally several processes ? (finalization etc...) Nicolas 2011/12/23 Alexandre Bergel <alexandre.bergel@me.com>:
Hi!
MessageTally seems to give wrong values regarding the relative time spent. Consider: Â Â Â Â MessageTally spyOn: [ Â 100 timesRepeat: [ 1000 factorial ] ]
It gives something like: -=-=-=-=-=-=-=-=-=-=-=-= Â - 377 tallies, 379 msec.
**Tree** -------------------------------- Process: (40s)  464519168: nil -------------------------------- 65.8% {249ms} SmallInteger(Integer)>>factorial  65.8% {249ms} SmallInteger(Integer)>>factorial   65.8% {249ms} SmallInteger(Integer)>>factorial    65.8% {249ms} SmallInteger(Integer)>>factorial ... -=-=-=-=-=-=-=-=-=-=-=-=
I would expect to have 100% at the root of the call graph since other threads are not reported.
Is there something I am missing? If no, then I will dive into MessageTally. This is annoying.
Cheers, Alexandre
-- _,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;: Alexandre Bergel  http://www.bergel.eu ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
On Fri, 23 Dec 2011, Nicolas Cellier wrote:
Doesn't it tally several processes ? (finalization etc...)
No, that would be MessageTally spyAllOn: [ ... ]. Levente
Nicolas
2011/12/23 Alexandre Bergel <alexandre.bergel@me.com>:
Hi!
MessageTally seems to give wrong values regarding the relative time spent. Consider: Â Â Â Â MessageTally spyOn: [ Â 100 timesRepeat: [ 1000 factorial ] ]
It gives something like: -=-=-=-=-=-=-=-=-=-=-=-= Â - 377 tallies, 379 msec.
**Tree** -------------------------------- Process: (40s)  464519168: nil -------------------------------- 65.8% {249ms} SmallInteger(Integer)>>factorial  65.8% {249ms} SmallInteger(Integer)>>factorial   65.8% {249ms} SmallInteger(Integer)>>factorial    65.8% {249ms} SmallInteger(Integer)>>factorial ... -=-=-=-=-=-=-=-=-=-=-=-=
I would expect to have 100% at the root of the call graph since other threads are not reported.
Is there something I am missing? If no, then I will dive into MessageTally. This is annoying.
Cheers, Alexandre
-- _,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;: Alexandre Bergel  http://www.bergel.eu ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
It is not supposed to do: -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= MessageTally class>>spyOn: aBlock " Spy on aBlock, in the current process. Can include or not statistics on other processes in the report. [1000 timesRepeat: [ 100 timesRepeat: [120 factorial]. (Delay forMilliseconds: 10) wait ]] forkAt: 45 named: '45'. MessageTally spyOn: [10000 timesRepeat: [1.23 printString]] " ^self spyOn: aBlock reportOtherProcesses: false -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-= I am not very familiar with the threading mechanism in Pharo, but since factorial does not explicitly give the hand to other threads, how can other threads be activated while the factoring is being computed? Cheers, Alexandre On 23 Dec 2011, at 14:12, Nicolas Cellier wrote:
Doesn't it tally several processes ? (finalization etc...)
Nicolas
2011/12/23 Alexandre Bergel <alexandre.bergel@me.com>:
Hi!
MessageTally seems to give wrong values regarding the relative time spent. Consider: MessageTally spyOn: [ 100 timesRepeat: [ 1000 factorial ] ]
It gives something like: -=-=-=-=-=-=-=-=-=-=-=-= - 377 tallies, 379 msec.
**Tree** -------------------------------- Process: (40s) 464519168: nil -------------------------------- 65.8% {249ms} SmallInteger(Integer)>>factorial 65.8% {249ms} SmallInteger(Integer)>>factorial 65.8% {249ms} SmallInteger(Integer)>>factorial 65.8% {249ms} SmallInteger(Integer)>>factorial ... -=-=-=-=-=-=-=-=-=-=-=-=
I would expect to have 100% at the root of the call graph since other threads are not reported.
Is there something I am missing? If no, then I will dive into MessageTally. This is annoying.
Cheers, Alexandre
-- _,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;: Alexandre Bergel http://www.bergel.eu ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
-- _,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;: Alexandre Bergel http://www.bergel.eu ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
On Fri, 23 Dec 2011, Alexandre Bergel wrote:
Hi!
MessageTally seems to give wrong values regarding the relative time spent. Consider: MessageTally spyOn: [ 100 timesRepeat: [ 1000 factorial ] ]
It gives something like: -=-=-=-=-=-=-=-=-=-=-=-= - 377 tallies, 379 msec.
**Tree** -------------------------------- Process: (40s) 464519168: nil -------------------------------- 65.8% {249ms} SmallInteger(Integer)>>factorial 65.8% {249ms} SmallInteger(Integer)>>factorial 65.8% {249ms} SmallInteger(Integer)>>factorial 65.8% {249ms} SmallInteger(Integer)>>factorial ... -=-=-=-=-=-=-=-=-=-=-=-=
I would expect to have 100% at the root of the call graph since other threads are not reported.
Is there something I am missing? If no, then I will dive into MessageTally. This is annoying.
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. Levente
Cheers, Alexandre
-- _,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;: Alexandre Bergel http://www.bergel.eu ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
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 ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
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 ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
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 ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
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 ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
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 ^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;._,.;:~^~:;.
participants (4)
-
Alexandre Bergel -
Levente Uzonyi -
Nicolas Cellier -
Stéphane Ducasse