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
[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
---
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
[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
---
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
[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
