fun :)
I did not pay attention to that either.
Stef
On Oct 24, 2009, at 12:08 PM, 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
>> [email protected]
>> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
>
>
> _______________________________________________
> Pharo-project mailing list
> [email protected]
> http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________
Pharo-project mailing list
[email protected]
http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
