question about results of MessageTally

> Hi,
>
> when I use MassageTally>>spyOn: on the creation of a Dictionary,
> results have not the same details according to the size of Dictionary.
>
> For example:
> ===
> |n|
> MessageTally spyOn:[
> n := Dictionary new.
> 1 to: 400000 do:[:each | n at: each put:each].
> ]
> ===
>
> returns this results:
>
> ====
>  - 1745 tallies, 1751 msec.
>
> **Tree**
> --------------------------------
> Process: (40s)  1964: nil
> --------------------------------
> 45.8% {802ms} Dictionary(Set)>>atNewIndex:put:
>   |43.6% {763ms} Dictionary(Set)>>fullCheck
>   |  |39.4% {690ms} Dictionary(Set)>>grow
>   |  |  |27.2% {476ms} Dictionary>>noCheckAdd:
>   |  |  |  |25.2% {441ms} Dictionary(Set)>>findElementOrNil:
>   |  |  |  |  |23.6% {413ms} Dictionary>>scanFor:
>   |  |  |  |  |1.6% {28ms} primitives
>   |  |  |  |2.0% {35ms} primitives
>   |  |  |9.2% {161ms} primitives
>   |  |  |3.0% {53ms} Array(SequenceableCollection)>>do:
>   |  |2.4% {42ms} primitives
>   |  |1.8% {32ms} SmallInteger(Magnitude)>>max:
>   |2.2% {39ms} primitives
> 22.4% {392ms} Association class>>key:value:
>   |18.9% {331ms} Association class(LookupKey class)>>key:
>   |  |16.3% {285ms} Association(LookupKey)>>key:
>   |  |2.6% {46ms} primitives
>   |1.9% {33ms} Association>>value:
>   |1.6% {28ms} primitives
> 4.4% {77ms} Dictionary(Set)>>findElementOrNil:
>   |2.3% {40ms} primitives
>   |2.1% {37ms} Dictionary>>scanFor:
> 1.9% {33ms} primitives
> ====
>
> But, if I do:
> ===
> |n|
> MessageTally spyOn:[
> n := Dictionary new.
> 1 to: 4000000 do:[:each | n at: each put:each].
> ]
> ===
>
> results are:
> ====
>  - 179772 tallies, 180312 msec.
>
> **Tree**
> --------------------------------
> Process: (40s)  1964: nil
> --------------------------------
> 3.1% {5590ms} Dictionary(Set)>>atNewIndex:put:
>   |2.8% {5049ms} Dictionary(Set)>>fullCheck
>   |  2.3% {4147ms} Dictionary(Set)>>grow
>   |    1.3% {2344ms} Dictionary>>noCheckAdd:
> 1.0% {1803ms} Association class>>key:value:
> ====
>
> Where are the rest of the process ?
> Does anybody understand this behavior ? can you explain ?
>
>
> Cheers,
> Jannik
>
>
> _______________________________________________
> Pharo-project mailing list
> [hidden email]
> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project

> Hi Jannik,
>
> Interesting question!
>
> You left out an important part oft the tally: the part about GC
> activity.
>
> For the large dictionary I get:
>
> **GCs**
> full 9 totalling 1,696ms (1.0% uptime), avg 188.0ms
> incr 3776 totalling 186,310ms (94.0% uptime), avg 49.0ms
>
> That is, 95% of time is spent in GC! A lot of incremental GC cycles
> are triggered because for each at:put: a new association instance is
> created. The larger the dictionary, the larger is the new memory space
> and hence the incremental GC takes longer to complete. In the above
> tally the average was 49ms compared to
>
> incr 275 totalling 1,113ms (58.0% uptime), avg 4.0ms
>
> for the smaller dictionary. Therefore, the ratio between actual method
> execution time and GC time differs significantly between the two runs.
> As a result, a lot of branches of the tally are below a total of 1%
> runtime in the second case. Message tally has a threshold that cuts
> off branches with less than 1% runtime. Therefore you see less  
> details.
>
> Cheers,
> Adrian
>
>
> On Oct 24, 2009, at 07:21 , Laval Jannik wrote:
>
>> Hi,
>>
>> when I use MassageTally>>spyOn: on the creation of a Dictionary,
>> results have not the same details according to the size of  
>> Dictionary.
>>
>> For example:
>> ===
>> |n|
>> MessageTally spyOn:[
>> n := Dictionary new.
>> 1 to: 400000 do:[:each | n at: each put:each].
>> ]
>> ===
>>
>> returns this results:
>>
>> ====
>> - 1745 tallies, 1751 msec.
>>
>> **Tree**
>> --------------------------------
>> Process: (40s)  1964: nil
>> --------------------------------
>> 45.8% {802ms} Dictionary(Set)>>atNewIndex:put:
>>  |43.6% {763ms} Dictionary(Set)>>fullCheck
>>  |  |39.4% {690ms} Dictionary(Set)>>grow
>>  |  |  |27.2% {476ms} Dictionary>>noCheckAdd:
>>  |  |  |  |25.2% {441ms} Dictionary(Set)>>findElementOrNil:
>>  |  |  |  |  |23.6% {413ms} Dictionary>>scanFor:
>>  |  |  |  |  |1.6% {28ms} primitives
>>  |  |  |  |2.0% {35ms} primitives
>>  |  |  |9.2% {161ms} primitives
>>  |  |  |3.0% {53ms} Array(SequenceableCollection)>>do:
>>  |  |2.4% {42ms} primitives
>>  |  |1.8% {32ms} SmallInteger(Magnitude)>>max:
>>  |2.2% {39ms} primitives
>> 22.4% {392ms} Association class>>key:value:
>>  |18.9% {331ms} Association class(LookupKey class)>>key:
>>  |  |16.3% {285ms} Association(LookupKey)>>key:
>>  |  |2.6% {46ms} primitives
>>  |1.9% {33ms} Association>>value:
>>  |1.6% {28ms} primitives
>> 4.4% {77ms} Dictionary(Set)>>findElementOrNil:
>>  |2.3% {40ms} primitives
>>  |2.1% {37ms} Dictionary>>scanFor:
>> 1.9% {33ms} primitives
>> ====
>>
>> But, if I do:
>> ===
>> |n|
>> MessageTally spyOn:[
>> n := Dictionary new.
>> 1 to: 4000000 do:[:each | n at: each put:each].
>> ]
>> ===
>>
>> results are:
>> ====
>> - 179772 tallies, 180312 msec.
>>
>> **Tree**
>> --------------------------------
>> Process: (40s)  1964: nil
>> --------------------------------
>> 3.1% {5590ms} Dictionary(Set)>>atNewIndex:put:
>>  |2.8% {5049ms} Dictionary(Set)>>fullCheck
>>  |  2.3% {4147ms} Dictionary(Set)>>grow
>>  |    1.3% {2344ms} Dictionary>>noCheckAdd:
>> 1.0% {1803ms} Association class>>key:value:
>> ====
>>
>> Where are the rest of the process ?
>> Does anybody understand this behavior ? can you explain ?
>>
>>
>> Cheers,
>> Jannik
>>
>>
>> _______________________________________________
>> Pharo-project mailing list
>> [hidden email]
>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
>
>
> _______________________________________________
> Pharo-project mailing list
> [hidden email]
> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project

> Hi Jannik,
>
> Interesting question!
>
> You left out an important part oft the tally: the part about GC
> activity.
>
> For the large dictionary I get:
>
> **GCs**
> full 9 totalling 1,696ms (1.0% uptime), avg 188.0ms
> incr 3776 totalling 186,310ms (94.0% uptime), avg 49.0ms
>
> That is, 95% of time is spent in GC! A lot of incremental GC cycles
> are triggered because for each at:put: a new association instance is
> created. The larger the dictionary, the larger is the new memory space
> and hence the incremental GC takes longer to complete. In the above
> tally the average was 49ms compared to
>
> incr 275 totalling 1,113ms (58.0% uptime), avg 4.0ms
>
> for the smaller dictionary. Therefore, the ratio between actual method
> execution time and GC time differs significantly between the two runs.
> As a result, a lot of branches of the tally are below a total of 1%
> runtime in the second case. Message tally has a threshold that cuts
> off branches with less than 1% runtime. Therefore you see less  
> details.
>
> Cheers,
> Adrian
>
>
> On Oct 24, 2009, at 07:21 , Laval Jannik wrote:
>
>> Hi,
>>
>> when I use MassageTally>>spyOn: on the creation of a Dictionary,
>> results have not the same details according to the size of  
>> Dictionary.
>>
>> For example:
>> ===
>> |n|
>> MessageTally spyOn:[
>> n := Dictionary new.
>> 1 to: 400000 do:[:each | n at: each put:each].
>> ]
>> ===
>>
>> returns this results:
>>
>> ====
>> - 1745 tallies, 1751 msec.
>>
>> **Tree**
>> --------------------------------
>> Process: (40s)  1964: nil
>> --------------------------------
>> 45.8% {802ms} Dictionary(Set)>>atNewIndex:put:
>>  |43.6% {763ms} Dictionary(Set)>>fullCheck
>>  |  |39.4% {690ms} Dictionary(Set)>>grow
>>  |  |  |27.2% {476ms} Dictionary>>noCheckAdd:
>>  |  |  |  |25.2% {441ms} Dictionary(Set)>>findElementOrNil:
>>  |  |  |  |  |23.6% {413ms} Dictionary>>scanFor:
>>  |  |  |  |  |1.6% {28ms} primitives
>>  |  |  |  |2.0% {35ms} primitives
>>  |  |  |9.2% {161ms} primitives
>>  |  |  |3.0% {53ms} Array(SequenceableCollection)>>do:
>>  |  |2.4% {42ms} primitives
>>  |  |1.8% {32ms} SmallInteger(Magnitude)>>max:
>>  |2.2% {39ms} primitives
>> 22.4% {392ms} Association class>>key:value:
>>  |18.9% {331ms} Association class(LookupKey class)>>key:
>>  |  |16.3% {285ms} Association(LookupKey)>>key:
>>  |  |2.6% {46ms} primitives
>>  |1.9% {33ms} Association>>value:
>>  |1.6% {28ms} primitives
>> 4.4% {77ms} Dictionary(Set)>>findElementOrNil:
>>  |2.3% {40ms} primitives
>>  |2.1% {37ms} Dictionary>>scanFor:
>> 1.9% {33ms} primitives
>> ====
>>
>> But, if I do:
>> ===
>> |n|
>> MessageTally spyOn:[
>> n := Dictionary new.
>> 1 to: 4000000 do:[:each | n at: each put:each].
>> ]
>> ===
>>
>> results are:
>> ====
>> - 179772 tallies, 180312 msec.
>>
>> **Tree**
>> --------------------------------
>> Process: (40s)  1964: nil
>> --------------------------------
>> 3.1% {5590ms} Dictionary(Set)>>atNewIndex:put:
>>  |2.8% {5049ms} Dictionary(Set)>>fullCheck
>>  |  2.3% {4147ms} Dictionary(Set)>>grow
>>  |    1.3% {2344ms} Dictionary>>noCheckAdd:
>> 1.0% {1803ms} Association class>>key:value:
>> ====
>>
>> Where are the rest of the process ?
>> Does anybody understand this behavior ? can you explain ?
>>
>>
>> Cheers,
>> Jannik
>>
>>
>> _______________________________________________
>> Pharo-project mailing list
>> [hidden email]
>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
>
>
> _______________________________________________
> Pharo-project mailing list
> [hidden email]
> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project

> Hi Adrian,
>
> Now I understand the "problem".
> So we can use "report:cutoff:" which allows us to give a specific
> value for the threshold.
>
> I will create a new method, spyOn:cutoff:.
>
> I think the method "spyOn:" must have the threshold equals to 0.
> No ?
>
> Cheers,
> Jannik
>
>
> On Oct 24, 2009, at 12:08 , Adrian Lienhard wrote:
>
>> Hi Jannik,
>>
>> Interesting question!
>>
>> You left out an important part oft the tally: the part about GC
>> activity.
>>
>> For the large dictionary I get:
>>
>> **GCs**
>> full 9 totalling 1,696ms (1.0% uptime), avg 188.0ms
>> incr 3776 totalling 186,310ms (94.0% uptime), avg 49.0ms
>>
>> That is, 95% of time is spent in GC! A lot of incremental GC cycles
>> are triggered because for each at:put: a new association instance is
>> created. The larger the dictionary, the larger is the new memory  
>> space
>> and hence the incremental GC takes longer to complete. In the above
>> tally the average was 49ms compared to
>>
>> incr 275 totalling 1,113ms (58.0% uptime), avg 4.0ms
>>
>> for the smaller dictionary. Therefore, the ratio between actual  
>> method
>> execution time and GC time differs significantly between the two  
>> runs.
>> As a result, a lot of branches of the tally are below a total of 1%
>> runtime in the second case. Message tally has a threshold that cuts
>> off branches with less than 1% runtime. Therefore you see less
>> details.
>>
>> Cheers,
>> Adrian
>>
>>
>> On Oct 24, 2009, at 07:21 , Laval Jannik wrote:
>>
>>> Hi,
>>>
>>> when I use MassageTally>>spyOn: on the creation of a Dictionary,
>>> results have not the same details according to the size of
>>> Dictionary.
>>>
>>> For example:
>>> ===
>>> |n|
>>> MessageTally spyOn:[
>>> n := Dictionary new.
>>> 1 to: 400000 do:[:each | n at: each put:each].
>>> ]
>>> ===
>>>
>>> returns this results:
>>>
>>> ====
>>> - 1745 tallies, 1751 msec.
>>>
>>> **Tree**
>>> --------------------------------
>>> Process: (40s)  1964: nil
>>> --------------------------------
>>> 45.8% {802ms} Dictionary(Set)>>atNewIndex:put:
>>> |43.6% {763ms} Dictionary(Set)>>fullCheck
>>> |  |39.4% {690ms} Dictionary(Set)>>grow
>>> |  |  |27.2% {476ms} Dictionary>>noCheckAdd:
>>> |  |  |  |25.2% {441ms} Dictionary(Set)>>findElementOrNil:
>>> |  |  |  |  |23.6% {413ms} Dictionary>>scanFor:
>>> |  |  |  |  |1.6% {28ms} primitives
>>> |  |  |  |2.0% {35ms} primitives
>>> |  |  |9.2% {161ms} primitives
>>> |  |  |3.0% {53ms} Array(SequenceableCollection)>>do:
>>> |  |2.4% {42ms} primitives
>>> |  |1.8% {32ms} SmallInteger(Magnitude)>>max:
>>> |2.2% {39ms} primitives
>>> 22.4% {392ms} Association class>>key:value:
>>> |18.9% {331ms} Association class(LookupKey class)>>key:
>>> |  |16.3% {285ms} Association(LookupKey)>>key:
>>> |  |2.6% {46ms} primitives
>>> |1.9% {33ms} Association>>value:
>>> |1.6% {28ms} primitives
>>> 4.4% {77ms} Dictionary(Set)>>findElementOrNil:
>>> |2.3% {40ms} primitives
>>> |2.1% {37ms} Dictionary>>scanFor:
>>> 1.9% {33ms} primitives
>>> ====
>>>
>>> But, if I do:
>>> ===
>>> |n|
>>> MessageTally spyOn:[
>>> n := Dictionary new.
>>> 1 to: 4000000 do:[:each | n at: each put:each].
>>> ]
>>> ===
>>>
>>> results are:
>>> ====
>>> - 179772 tallies, 180312 msec.
>>>
>>> **Tree**
>>> --------------------------------
>>> Process: (40s)  1964: nil
>>> --------------------------------
>>> 3.1% {5590ms} Dictionary(Set)>>atNewIndex:put:
>>> |2.8% {5049ms} Dictionary(Set)>>fullCheck
>>> |  2.3% {4147ms} Dictionary(Set)>>grow
>>> |    1.3% {2344ms} Dictionary>>noCheckAdd:
>>> 1.0% {1803ms} Association class>>key:value:
>>> ====
>>>
>>> Where are the rest of the process ?
>>> Does anybody understand this behavior ? can you explain ?
>>>
>>>
>>> Cheers,
>>> Jannik
>>>
>>>
>>> _______________________________________________
>>> Pharo-project mailing list
>>> [hidden email]
>>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
>>
>>
>> _______________________________________________
>> Pharo-project mailing list
>> [hidden email]
>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
>
> ---
> Jannik Laval
> PhD Student - Rmod Team - INRIA
> Certified Project Management Associate (IPMA)
> http://www.jannik-laval.eu
> http://rmod.lille.inria.fr
> ---
>
>
> _______________________________________________
> Pharo-project mailing list
> [hidden email]
> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project

> Have you tried with 0? I guess you get way too much in the tree
> (especially when you trace a larger part of your application and not
> only adding elements to a dictionary). It seems that 1% is a sensible
> default as usually it does not make sense to look into these branches
> more closely as you cannot optimize them much.
>
> Adrian
>
> On Oct 25, 2009, at 19:42 , Laval Jannik wrote:
>
>> Hi Adrian,
>>
>> Now I understand the "problem".
>> So we can use "report:cutoff:" which allows us to give a specific
>> value for the threshold.
>>
>> I will create a new method, spyOn:cutoff:.
>>
>> I think the method "spyOn:" must have the threshold equals to 0.
>> No ?
>>
>> Cheers,
>> Jannik
>>
>>
>> On Oct 24, 2009, at 12:08 , Adrian Lienhard wrote:
>>
>>> Hi Jannik,
>>>
>>> Interesting question!
>>>
>>> You left out an important part oft the tally: the part about GC
>>> activity.
>>>
>>> For the large dictionary I get:
>>>
>>> **GCs**
>>> full 9 totalling 1,696ms (1.0% uptime), avg 188.0ms
>>> incr 3776 totalling 186,310ms (94.0% uptime), avg 49.0ms
>>>
>>> That is, 95% of time is spent in GC! A lot of incremental GC cycles
>>> are triggered because for each at:put: a new association instance is
>>> created. The larger the dictionary, the larger is the new memory
>>> space
>>> and hence the incremental GC takes longer to complete. In the above
>>> tally the average was 49ms compared to
>>>
>>> incr 275 totalling 1,113ms (58.0% uptime), avg 4.0ms
>>>
>>> for the smaller dictionary. Therefore, the ratio between actual
>>> method
>>> execution time and GC time differs significantly between the two
>>> runs.
>>> As a result, a lot of branches of the tally are below a total of 1%
>>> runtime in the second case. Message tally has a threshold that cuts
>>> off branches with less than 1% runtime. Therefore you see less
>>> details.
>>>
>>> Cheers,
>>> Adrian
>>>
>>>
>>> On Oct 24, 2009, at 07:21 , Laval Jannik wrote:
>>>
>>>> Hi,
>>>>
>>>> when I use MassageTally>>spyOn: on the creation of a Dictionary,
>>>> results have not the same details according to the size of
>>>> Dictionary.
>>>>
>>>> For example:
>>>> ===
>>>> |n|
>>>> MessageTally spyOn:[
>>>> n := Dictionary new.
>>>> 1 to: 400000 do:[:each | n at: each put:each].
>>>> ]
>>>> ===
>>>>
>>>> returns this results:
>>>>
>>>> ====
>>>> - 1745 tallies, 1751 msec.
>>>>
>>>> **Tree**
>>>> --------------------------------
>>>> Process: (40s)  1964: nil
>>>> --------------------------------
>>>> 45.8% {802ms} Dictionary(Set)>>atNewIndex:put:
>>>> |43.6% {763ms} Dictionary(Set)>>fullCheck
>>>> |  |39.4% {690ms} Dictionary(Set)>>grow
>>>> |  |  |27.2% {476ms} Dictionary>>noCheckAdd:
>>>> |  |  |  |25.2% {441ms} Dictionary(Set)>>findElementOrNil:
>>>> |  |  |  |  |23.6% {413ms} Dictionary>>scanFor:
>>>> |  |  |  |  |1.6% {28ms} primitives
>>>> |  |  |  |2.0% {35ms} primitives
>>>> |  |  |9.2% {161ms} primitives
>>>> |  |  |3.0% {53ms} Array(SequenceableCollection)>>do:
>>>> |  |2.4% {42ms} primitives
>>>> |  |1.8% {32ms} SmallInteger(Magnitude)>>max:
>>>> |2.2% {39ms} primitives
>>>> 22.4% {392ms} Association class>>key:value:
>>>> |18.9% {331ms} Association class(LookupKey class)>>key:
>>>> |  |16.3% {285ms} Association(LookupKey)>>key:
>>>> |  |2.6% {46ms} primitives
>>>> |1.9% {33ms} Association>>value:
>>>> |1.6% {28ms} primitives
>>>> 4.4% {77ms} Dictionary(Set)>>findElementOrNil:
>>>> |2.3% {40ms} primitives
>>>> |2.1% {37ms} Dictionary>>scanFor:
>>>> 1.9% {33ms} primitives
>>>> ====
>>>>
>>>> But, if I do:
>>>> ===
>>>> |n|
>>>> MessageTally spyOn:[
>>>> n := Dictionary new.
>>>> 1 to: 4000000 do:[:each | n at: each put:each].
>>>> ]
>>>> ===
>>>>
>>>> results are:
>>>> ====
>>>> - 179772 tallies, 180312 msec.
>>>>
>>>> **Tree**
>>>> --------------------------------
>>>> Process: (40s)  1964: nil
>>>> --------------------------------
>>>> 3.1% {5590ms} Dictionary(Set)>>atNewIndex:put:
>>>> |2.8% {5049ms} Dictionary(Set)>>fullCheck
>>>> |  2.3% {4147ms} Dictionary(Set)>>grow
>>>> |    1.3% {2344ms} Dictionary>>noCheckAdd:
>>>> 1.0% {1803ms} Association class>>key:value:
>>>> ====
>>>>
>>>> Where are the rest of the process ?
>>>> Does anybody understand this behavior ? can you explain ?
>>>>
>>>>
>>>> Cheers,
>>>> Jannik
>>>>
>>>>
>>>> _______________________________________________
>>>> Pharo-project mailing list
>>>> [hidden email]
>>>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
>>>
>>>
>>> _______________________________________________
>>> Pharo-project mailing list
>>> [hidden email]
>>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
>>
>> ---
>> Jannik Laval
>> PhD Student - Rmod Team - INRIA
>> Certified Project Management Associate (IPMA)
>> http://www.jannik-laval.eu
>> http://rmod.lille.inria.fr
>> ---
>>
>>
>> _______________________________________________
>> Pharo-project mailing list
>> [hidden email]
>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
>
>
> _______________________________________________
> Pharo-project mailing list
> [hidden email]
> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project

> Personally, I always change to 0.1 in spyOn: (my experience in VW  
> was that doing 0.0 makes the tree building take a long time).
> You'd probably also want to try out
> TimeProfileBrowser onBlock:
> instead of MessageTally spyOn:,
> while not a huge improvement, it's nice to have the method source  
> accessible directly.
> I had a dream of making a new one, with a proper treeview of the  
> tally (and a button for auto-expand to certain %, no need to worry  
> if you'd set the cutoff correctly before starting the tally), color-
> coding of the hotspots in the method view, and store/compare of  
> tallies, but never seem to get around to it.
> Well, I did start once, but my head started hurting too soon from  
> the total lack of separation between result production/storage/
> presentation responsibilities in MT.
>
> Cheers,
> Henry
>
>
> On 25.10.2009 21:00, Laval Jannik wrote:
>> yes, with 0 it works.
>>
>> But, in some cases, we would like to have all branches.
>> So, I will do the method spyOn:cutoff:, and keep the 1% threshold for
>> spyOn:.
>>
>> Cheers,
>> Jannik
>>
>>
>> On Oct 25, 2009, at 20:54 , Adrian Lienhard wrote:
>>
>>
>>
>>> Have you tried with 0? I guess you get way too much in the tree
>>> (especially when you trace a larger part of your application and not
>>> only adding elements to a dictionary). It seems that 1% is a  
>>> sensible
>>> default as usually it does not make sense to look into these  
>>> branches
>>> more closely as you cannot optimize them much.
>>>
>>> Adrian
>>>
>>> On Oct 25, 2009, at 19:42 , Laval Jannik wrote:
>>>
>>>
>>>
>>>> Hi Adrian,
>>>>
>>>> Now I understand the "problem".
>>>> So we can use "report:cutoff:" which allows us to give a specific
>>>> value for the threshold.
>>>>
>>>> I will create a new method, spyOn:cutoff:.
>>>>
>>>> I think the method "spyOn:" must have the threshold equals to 0.
>>>> No ?
>>>>
>>>> Cheers,
>>>> Jannik
>>>>
>>>>
>>>> On Oct 24, 2009, at 12:08 , Adrian Lienhard wrote:
>>>>
>>>>
>>>>
>>>>> Hi Jannik,
>>>>>
>>>>> Interesting question!
>>>>>
>>>>> You left out an important part oft the tally: the part about GC
>>>>> activity.
>>>>>
>>>>> For the large dictionary I get:
>>>>>
>>>>> **GCs**
>>>>> full 9 totalling 1,696ms (1.0% uptime), avg 188.0ms
>>>>> incr 3776 totalling 186,310ms (94.0% uptime), avg 49.0ms
>>>>>
>>>>> That is, 95% of time is spent in GC! A lot of incremental GC  
>>>>> cycles
>>>>> are triggered because for each at:put: a new association  
>>>>> instance is
>>>>> created. The larger the dictionary, the larger is the new memory
>>>>> space
>>>>> and hence the incremental GC takes longer to complete. In the  
>>>>> above
>>>>> tally the average was 49ms compared to
>>>>>
>>>>> incr 275 totalling 1,113ms (58.0% uptime), avg 4.0ms
>>>>>
>>>>> for the smaller dictionary. Therefore, the ratio between actual
>>>>> method
>>>>> execution time and GC time differs significantly between the two
>>>>> runs.
>>>>> As a result, a lot of branches of the tally are below a total of  
>>>>> 1%
>>>>> runtime in the second case. Message tally has a threshold that  
>>>>> cuts
>>>>> off branches with less than 1% runtime. Therefore you see less
>>>>> details.
>>>>>
>>>>> Cheers,
>>>>> Adrian
>>>>>
>>>>>
>>>>> On Oct 24, 2009, at 07:21 , Laval Jannik wrote:
>>>>>
>>>>>
>>>>>
>>>>>> Hi,
>>>>>>
>>>>>> when I use MassageTally>>spyOn: on the creation of a Dictionary,
>>>>>> results have not the same details according to the size of
>>>>>> Dictionary.
>>>>>>
>>>>>> For example:
>>>>>> ===
>>>>>> |n|
>>>>>> MessageTally spyOn:[
>>>>>> n := Dictionary new.
>>>>>> 1 to: 400000 do:[:each | n at: each put:each].
>>>>>> ]
>>>>>> ===
>>>>>>
>>>>>> returns this results:
>>>>>>
>>>>>> ====
>>>>>> - 1745 tallies, 1751 msec.
>>>>>>
>>>>>> **Tree**
>>>>>> --------------------------------
>>>>>> Process: (40s)  1964: nil
>>>>>> --------------------------------
>>>>>> 45.8% {802ms} Dictionary(Set)>>atNewIndex:put:
>>>>>> |43.6% {763ms} Dictionary(Set)>>fullCheck
>>>>>> |  |39.4% {690ms} Dictionary(Set)>>grow
>>>>>> |  |  |27.2% {476ms} Dictionary>>noCheckAdd:
>>>>>> |  |  |  |25.2% {441ms} Dictionary(Set)>>findElementOrNil:
>>>>>> |  |  |  |  |23.6% {413ms} Dictionary>>scanFor:
>>>>>> |  |  |  |  |1.6% {28ms} primitives
>>>>>> |  |  |  |2.0% {35ms} primitives
>>>>>> |  |  |9.2% {161ms} primitives
>>>>>> |  |  |3.0% {53ms} Array(SequenceableCollection)>>do:
>>>>>> |  |2.4% {42ms} primitives
>>>>>> |  |1.8% {32ms} SmallInteger(Magnitude)>>max:
>>>>>> |2.2% {39ms} primitives
>>>>>> 22.4% {392ms} Association class>>key:value:
>>>>>> |18.9% {331ms} Association class(LookupKey class)>>key:
>>>>>> |  |16.3% {285ms} Association(LookupKey)>>key:
>>>>>> |  |2.6% {46ms} primitives
>>>>>> |1.9% {33ms} Association>>value:
>>>>>> |1.6% {28ms} primitives
>>>>>> 4.4% {77ms} Dictionary(Set)>>findElementOrNil:
>>>>>> |2.3% {40ms} primitives
>>>>>> |2.1% {37ms} Dictionary>>scanFor:
>>>>>> 1.9% {33ms} primitives
>>>>>> ====
>>>>>>
>>>>>> But, if I do:
>>>>>> ===
>>>>>> |n|
>>>>>> MessageTally spyOn:[
>>>>>> n := Dictionary new.
>>>>>> 1 to: 4000000 do:[:each | n at: each put:each].
>>>>>> ]
>>>>>> ===
>>>>>>
>>>>>> results are:
>>>>>> ====
>>>>>> - 179772 tallies, 180312 msec.
>>>>>>
>>>>>> **Tree**
>>>>>> --------------------------------
>>>>>> Process: (40s)  1964: nil
>>>>>> --------------------------------
>>>>>> 3.1% {5590ms} Dictionary(Set)>>atNewIndex:put:
>>>>>> |2.8% {5049ms} Dictionary(Set)>>fullCheck
>>>>>> |  2.3% {4147ms} Dictionary(Set)>>grow
>>>>>> |    1.3% {2344ms} Dictionary>>noCheckAdd:
>>>>>> 1.0% {1803ms} Association class>>key:value:
>>>>>> ====
>>>>>>
>>>>>> Where are the rest of the process ?
>>>>>> Does anybody understand this behavior ? can you explain ?
>>>>>>
>>>>>>
>>>>>> Cheers,
>>>>>> Jannik
>>>>>>
>>>>>>
>>>>>> _______________________________________________
>>>>>> Pharo-project mailing list
>>>>>>
>>>>>> [hidden email]
>>>>>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>> _______________________________________________
>>>>> Pharo-project mailing list
>>>>>
>>>>> [hidden email]
>>>>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo- 
>>>>> project
>>>>>
>>>>>
>>>>>
>>>> ---
>>>> Jannik Laval
>>>> PhD Student - Rmod Team - INRIA
>>>> Certified Project Management Associate (IPMA)
>>>>
>>>> http://www.jannik-laval.eu
>>>> http://rmod.lille.inria.fr
>>>>
>>>> ---
>>>>
>>>>
>>>> _______________________________________________
>>>> Pharo-project mailing list
>>>>
>>>> [hidden email]
>>>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
>>>>
>>>>
>>>>
>>>
>>> _______________________________________________
>>> Pharo-project mailing list
>>>
>>> [hidden email]
>>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
>>>
>>>
>>>
>> ---
>> Jannik Laval
>> PhD Student - Rmod Team - INRIA
>> Certified Project Management Associate (IPMA)
>>
>> http://www.jannik-laval.eu
>> http://rmod.lille.inria.fr
>>
>> ---
>>
>>
>> _______________________________________________
>> Pharo-project mailing list
>>
>> [hidden email]
>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
>>
>>
>>
>>
>>
>
> _______________________________________________
> Pharo-project mailing list
> [hidden email]
> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project