[Pharo-project] 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
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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list Pharo-project@lists.gforge.inria.fr 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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list Pharo-project@lists.gforge.inria.fr 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 ---
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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list Pharo-project@lists.gforge.inria.fr 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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list Pharo-project@lists.gforge.inria.fr 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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list Pharo-project@lists.gforge.inria.fr 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 ---
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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list Pharo-project@lists.gforge.inria.fr 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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list Pharo-project@lists.gforge.inria.fr 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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
Thanks Henry. I push in pharoInbox a new method. MessageTally>>spyOn:cutoff: which allows us to specify an appropriate filter. I will see the TimeProfileBrowser. Cheers, Jannik On Oct 26, 2009, at 00:26 , Henrik Sperre Johansen wrote:
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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list Pharo-project@lists.gforge.inria.fr 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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list Pharo-project@lists.gforge.inria.fr 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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list Pharo-project@lists.gforge.inria.fr 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 ---
please resurrect that and do simple increment :) Now we can use Momo tree widget for ast and this is cool stef On Oct 26, 2009, at 12:26 AM, Henrik Sperre Johansen wrote:
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
Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list
Pharo-project@lists.gforge.inria.fr 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
Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list
Pharo-project@lists.gforge.inria.fr 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
Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
_______________________________________________ Pharo-project mailing list Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
Jannik, A good starting point is wiki.squeak.org/squeak/4210 I am not an expert on this, but the profiler works by sampling from a high priority process that looks at what the "slow ones" happen to be doing at the time - it's random, but done enough times, a picture will emerge from it. In this case, you have not profiled creating a dictionary, you have profiled adding elements to a dictionary. If you want to see creating the dictionary, something like MessageTally spyOn:[ 1000 timesRepeat:[ Dictionary new. ]. ]. would be a better choice. If you want to see the effects of adding the elements, you might create the dictionary outside the block to remove it from the profile. Bill -----Original Message----- From: pharo-project-bounces@lists.gforge.inria.fr [mailto:pharo-project-bounces@lists.gforge.inria.fr] On Behalf Of Laval Jannik Sent: Saturday, October 24, 2009 12:21 AM To: Pharo-project@lists.gforge.inria.fr Subject: [Pharo-project] 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 Pharo-project@lists.gforge.inria.fr http://lists.gforge.inria.fr/cgi-bin/mailman/listinfo/pharo-project
participants (5)
-
Adrian Lienhard -
Henrik Sperre Johansen -
Laval Jannik -
Schwab,Wilhelm K -
Stéphane Ducasse