--- a/MessageTally.st Thu Mar 20 21:14:11 1997 +0100
+++ b/MessageTally.st Thu Mar 20 21:46:46 1997 +0100
@@ -11,7 +11,7 @@
"
Object subclass:#MessageTally
- instanceVariableNames:'tree probes ntally theBlock spyInterval'
+ instanceVariableNames:'tree probes ntally theBlock spyInterval executing'
classVariableNames:''
poolDictionaries:''
category:'System-Debugging-Support'
@@ -67,7 +67,14 @@
Here, method invocations for different receiver types are
summed up separately.
- The last list (leaf methods) is propably the most interresting.
+ The last list (leaf methods) is propably the most interresting;
+ if you are only interrested in that (or the calling hierarchy is too
+ deep for the list to be useful or the amount of data to be handled
+ correctly), use a leaf-spy with:
+ MessageTally spyLeafOn:aBlock
+ This only accumulates statistics about methods where the cpu time
+ is actually spent (not collecing hierarchy information).
+
[author:]
Claus Gittinger
@@ -80,11 +87,17 @@
examples
"
+ the block must execute for a while;
+ otherwise, no probes (and therefore no statistics) can
+ be gathered:
[exBegin]
MessageTally spyOn:[ #(6 5 4 3 2 1) sort ]
[exEnd]
+ if required, execute the block in a loop;
+ however, for the example below, a larger repeat count
+ is required, for a reasonable measurement:
[exBegin]
MessageTally spyOn:[
10000 timesRepeat:[ #(6 5 4 3 2 1) sort]
@@ -92,6 +105,7 @@
[exEnd]
+ thats better:
[exBegin]
MessageTally spyOn:[
100000 timesRepeat:[ #(6 5 4 3 2 1) sort]
@@ -99,6 +113,7 @@
[exEnd]
+ thats much better
[exBegin]
MessageTally spyOn:[
500000 timesRepeat:[#(6 5 4 3 2 1) sort]
@@ -106,6 +121,7 @@
[exEnd]
+ a smaller probing tick also helps:
[exBegin]
MessageTally spyDetailedOn:[
500000 timesRepeat:[#(6 5 4 3 2 1) sort]
@@ -113,13 +129,26 @@
[exEnd]
+ as usual, measurements add some extra overhead;
+ compare the above time to the time given by:
[exBegin]
- Time millisecondsToRun:[
+ Transcript showCR:(
+ Time millisecondsToRun:[
+ 500000 timesRepeat:[#(6 5 4 3 2 1) sort]
+ ]
+ )
+ [exEnd]
+ probing the leafs only may help to reduce the overhead
+ a bit:
+ [exBegin]
+ MessageTally spyLeafDetailedOn:[
500000 timesRepeat:[#(6 5 4 3 2 1) sort]
]
[exEnd]
+
+
[exBegin]
MessageTally spyOn:[SystemBrowser open ]
[exEnd]
@@ -346,9 +375,10 @@
execute
"evaluate the target block"
+ executing := true.
theBlock value
- "Modified: 18.5.1996 / 18:48:10 / cg"
+ "Modified: 20.3.1997 / 21:36:27 / cg"
! !
!MessageTally methodsFor:'probing'!
@@ -364,9 +394,6 @@
con := aContext.
con isNil ifTrue:[^ self].
- ntally := ntally + 1.
- "walk up above the interrupt context"
-
[con receiver == Processor] whileTrue:[
con := con sender
].
@@ -428,9 +455,12 @@
chain isNil ifTrue:[^ self].
+ ntally := ntally + 1.
+ "walk up above the interrupt context"
+
tree addChain:chain
- "Modified: 20.3.1997 / 21:05:20 / cg"
+ "Modified: 20.3.1997 / 21:33:54 / cg"
!
countLeaf:aContext
@@ -444,8 +474,6 @@
con := aContext.
con isNil ifTrue:[^ self].
- ntally := ntally + 1.
-
"walk up above the interrupt context"
[con receiver == Processor] whileTrue:[
@@ -482,6 +510,8 @@
"add info to the probes collection"
+ ntally := ntally + 1.
+
entry := ProfileTree new.
entry
receiver:recClass
@@ -496,14 +526,14 @@
existingEntry incrementLeafTally.
].
- "Modified: 20.3.1997 / 21:05:26 / cg"
+ "Modified: 20.3.1997 / 21:34:05 / cg"
!
spyLeafOn:aBlock interval:ms
"spy on execution time; generate information on leaf nodes only"
|startTime endTime probing
- executing delay probingProcess probedProcess|
+ delay probingProcess probedProcess|
theBlock := aBlock.
@@ -521,7 +551,7 @@
].
] newProcess.
- probingProcess priority:24.
+ probingProcess priority:25.
delay := (Delay forMilliseconds:ms).
ntally := 0.
@@ -535,7 +565,6 @@
[
startTime := OperatingSystem getMillisecondTime.
- probing := executing := true.
self execute.
] valueNowOrOnUnwindDo:[
probing := executing := false.
@@ -551,14 +580,14 @@
^ endTime - startTime
"Created: 20.3.1997 / 20:15:07 / cg"
- "Modified: 20.3.1997 / 21:10:51 / cg"
+ "Modified: 20.3.1997 / 21:45:11 / cg"
!
spyOn:aBlock interval:ms
"spy on execution time, generate a hierarchical call information"
|startTime endTime probing
- executing delay probingProcess probedProcess|
+ delay probingProcess probedProcess|
theBlock := aBlock.
@@ -576,7 +605,7 @@
].
] newProcess.
- probingProcess priority:24.
+ probingProcess priority:25.
delay := (Delay forMilliseconds:ms).
ntally := 0.
@@ -595,7 +624,6 @@
[
startTime := OperatingSystem getMillisecondTime.
- probing := executing := true.
self execute.
] valueNowOrOnUnwindDo:[
probing := executing := false.
@@ -605,15 +633,15 @@
endTime := OperatingSystem getMillisecondTime.
].
- tree notNil ifTrue:[tree computePercentage:ntally].
+ ntally ~~ 0 ifTrue:[tree computePercentage:ntally].
^ endTime - startTime
"Created: 20.3.1997 / 20:14:44 / cg"
- "Modified: 20.3.1997 / 20:47:48 / cg"
+ "Modified: 20.3.1997 / 21:45:02 / cg"
! !
!MessageTally class methodsFor:'documentation'!
version
- ^ '$Header: /cvs/stx/stx/libbasic3/MessageTally.st,v 1.29 1997-03-20 20:14:11 cg Exp $'
+ ^ '$Header: /cvs/stx/stx/libbasic3/MessageTally.st,v 1.30 1997-03-20 20:46:46 cg Exp $'
! !