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
