0
|
1 |
"
|
21
|
2 |
COPYRIGHT (c) 1995 by Claus Gittinger
|
|
3 |
All Rights Reserved
|
0
|
4 |
|
|
5 |
This software is furnished under a license and may be used
|
|
6 |
only in accordance with the terms of that license and with the
|
|
7 |
inclusion of the above copyright notice. This software may not
|
|
8 |
be provided or otherwise made available to, or used by, any
|
|
9 |
other person. No title to or ownership of the software is
|
|
10 |
hereby transferred.
|
|
11 |
"
|
|
12 |
|
120
|
13 |
Object subclass:#MessageTally
|
236
|
14 |
instanceVariableNames:'process tree ntally theBlock spyInterval'
|
|
15 |
classVariableNames:''
|
|
16 |
poolDictionaries:''
|
|
17 |
category:'System-Debugging-Support'
|
0
|
18 |
!
|
|
19 |
|
9
|
20 |
!MessageTally class methodsFor:'documentation'!
|
|
21 |
|
88
|
22 |
copyright
|
|
23 |
"
|
|
24 |
COPYRIGHT (c) 1995 by Claus Gittinger
|
|
25 |
All Rights Reserved
|
|
26 |
|
|
27 |
This software is furnished under a license and may be used
|
|
28 |
only in accordance with the terms of that license and with the
|
|
29 |
inclusion of the above copyright notice. This software may not
|
|
30 |
be provided or otherwise made available to, or used by, any
|
|
31 |
other person. No title to or ownership of the software is
|
|
32 |
hereby transferred.
|
|
33 |
"
|
9
|
34 |
!
|
|
35 |
|
|
36 |
documentation
|
|
37 |
"
|
|
38 |
MessageTally allows profiling excution of a block;
|
|
39 |
statistic of method evaluation is output on Transcript.
|
|
40 |
To get statistic, use 'MessageTally spyOn:aBlock'.
|
|
41 |
|
21
|
42 |
By default, probing is done every 10ms (i.e. the execution of the block is
|
|
43 |
interrupted every 10ms, and the context chain analyzed).
|
260
|
44 |
|
21
|
45 |
For better resolution, use smaller clock ticks (if your OperatingSystem
|
260
|
46 |
supports it). Try 'spyDetailedOn:aBlock', which tries to measure things
|
|
47 |
every 1ms.
|
|
48 |
(Notice, that some OS's do not provide this timer resolution,
|
|
49 |
so measuring may be less accurate.)
|
|
50 |
|
|
51 |
For good results, make certain that the measured block runs for some
|
|
52 |
time (say 5 seconds) - add a timesRepeat-loop around it if required.
|
236
|
53 |
|
|
54 |
[author:]
|
|
55 |
Claus Gittinger
|
260
|
56 |
|
|
57 |
[see also:]
|
261
|
58 |
CallChain ProfileTree
|
|
59 |
MessageTracer
|
21
|
60 |
"
|
|
61 |
!
|
|
62 |
|
|
63 |
examples
|
9
|
64 |
"
|
244
|
65 |
[exBegin]
|
264
|
66 |
MessageTally spyOn:[ #(6 5 4 3 2 1) sort ]
|
244
|
67 |
[exEnd]
|
|
68 |
|
|
69 |
|
|
70 |
[exBegin]
|
259
|
71 |
MessageTally spyOn:[
|
264
|
72 |
10000 timesRepeat:[ #(6 5 4 3 2 1) sort]
|
259
|
73 |
]
|
244
|
74 |
[exEnd]
|
|
75 |
|
|
76 |
|
|
77 |
[exBegin]
|
259
|
78 |
MessageTally spyOn:[
|
264
|
79 |
100000 timesRepeat:[ #(6 5 4 3 2 1) sort]
|
259
|
80 |
]
|
244
|
81 |
[exEnd]
|
|
82 |
|
|
83 |
|
|
84 |
[exBegin]
|
259
|
85 |
MessageTally spyOn:[
|
264
|
86 |
500000 timesRepeat:[#(6 5 4 3 2 1) sort]
|
259
|
87 |
]
|
244
|
88 |
[exEnd]
|
|
89 |
|
|
90 |
|
|
91 |
[exBegin]
|
259
|
92 |
MessageTally spyDetailedOn:[
|
264
|
93 |
500000 timesRepeat:[#(6 5 4 3 2 1) sort]
|
259
|
94 |
]
|
244
|
95 |
[exEnd]
|
|
96 |
|
21
|
97 |
|
244
|
98 |
[exBegin]
|
259
|
99 |
Time millisecondsToRun:[
|
264
|
100 |
500000 timesRepeat:[#(6 5 4 3 2 1) sort]
|
259
|
101 |
]
|
244
|
102 |
[exEnd]
|
|
103 |
|
|
104 |
|
|
105 |
[exBegin]
|
21
|
106 |
MessageTally spyOn:[SystemBrowser open ]
|
244
|
107 |
[exEnd]
|
|
108 |
|
|
109 |
|
|
110 |
[exBegin]
|
21
|
111 |
MessageTally spyDetailedOn:[SystemBrowser open ]
|
244
|
112 |
[exEnd]
|
21
|
113 |
"
|
9
|
114 |
! !
|
0
|
115 |
|
|
116 |
!MessageTally class methodsFor:'instance creation'!
|
|
117 |
|
88
|
118 |
spyDetailedOn:aBlock
|
|
119 |
"evaluate aBlock and output time statistic on the Transcript.
|
|
120 |
Tick is 1ms."
|
|
121 |
|
|
122 |
^ self spyOn:aBlock interval:1
|
|
123 |
!
|
|
124 |
|
|
125 |
spyOn:aBlock
|
|
126 |
"evaluate aBlock and output time statistic on the Transcript.
|
|
127 |
Tick is 10ms."
|
|
128 |
|
|
129 |
^ self spyOn:aBlock interval:10
|
|
130 |
!
|
|
131 |
|
21
|
132 |
spyOn:aBlock interval:ms
|
0
|
133 |
"evaluate aBlock and output time statistic on Transcript"
|
|
134 |
|
21
|
135 |
|runTime aTally nTally|
|
0
|
136 |
|
|
137 |
aTally := self new.
|
21
|
138 |
runTime := aTally spyOn:aBlock interval:ms.
|
|
139 |
|
|
140 |
aTally tree isNil ifTrue:[
|
256
|
141 |
Transcript cr.
|
|
142 |
Transcript showCR:'TALLY: No probes - execution time too short;'.
|
|
143 |
Transcript showCR:'TALLY: retry using: spyOn:[n timesRepeat:[...]]'.
|
21
|
144 |
] ifFalse:[
|
256
|
145 |
"/ aTally tree inspect.
|
|
146 |
nTally := aTally nTally.
|
|
147 |
Transcript cr.
|
|
148 |
Transcript showCR:('total execution time: '
|
|
149 |
, runTime printString , ' ms '
|
|
150 |
, '(' , nTally printString , ' probes ;'
|
|
151 |
, ' error >= '
|
|
152 |
, (1000 // nTally / 10.0) printString
|
|
153 |
, '%)').
|
|
154 |
Transcript cr.
|
|
155 |
aTally tree printOn:Transcript.
|
|
156 |
Transcript cr.
|
|
157 |
Transcript cr.
|
0
|
158 |
|
256
|
159 |
Transcript showCR:'leafs of calling tree:'.
|
|
160 |
Transcript cr.
|
|
161 |
aTally tree printLeafsOn:Transcript.
|
|
162 |
Transcript cr.
|
21
|
163 |
|
256
|
164 |
"
|
|
165 |
aTally statistics.
|
|
166 |
"
|
21
|
167 |
].
|
|
168 |
|
|
169 |
"
|
|
170 |
MessageTally spyOn:[ #(6 5 4 3 2 1) sort ]
|
|
171 |
MessageTally spyOn:[100 timesRepeat:[#(6 5 4 3 2 1) sort] ]
|
|
172 |
MessageTally spyOn:[1000 timesRepeat:[#(6 5 4 3 2 1) sort] ]
|
|
173 |
MessageTally spyOn:[10000 timesRepeat:[#(6 5 4 3 2 1) sort] ]
|
|
174 |
MessageTally spyOn:[100000 timesRepeat:[#(6 5 4 3 2 1) sort] ]
|
|
175 |
MessageTally spyOn:[500000 timesRepeat:[#(6 5 4 3 2 1) sort] ]
|
|
176 |
MessageTally spyOn:[SystemBrowser open ]
|
|
177 |
MessageTally spyDetailedOn:[SystemBrowser open ]
|
|
178 |
Time millisecondsToRun:[500000 timesRepeat:[#(6 5 4 3 2 1) sort] ]
|
|
179 |
"
|
256
|
180 |
|
|
181 |
"Modified: 18.5.1996 / 15:42:44 / cg"
|
88
|
182 |
! !
|
|
183 |
|
|
184 |
!MessageTally methodsFor:'accessing'!
|
|
185 |
|
|
186 |
nTally
|
260
|
187 |
"return the number of accumulated probes"
|
|
188 |
|
|
189 |
^ ntally
|
|
190 |
|
|
191 |
"Modified: 18.5.1996 / 18:47:47 / cg"
|
0
|
192 |
!
|
|
193 |
|
88
|
194 |
tree
|
260
|
195 |
"return the accumulated calling tree"
|
|
196 |
|
88
|
197 |
^ tree
|
260
|
198 |
|
|
199 |
"Modified: 18.5.1996 / 18:47:57 / cg"
|
0
|
200 |
! !
|
|
201 |
|
|
202 |
!MessageTally methodsFor:'private'!
|
|
203 |
|
21
|
204 |
execute
|
260
|
205 |
"evaluate the target block"
|
|
206 |
|
21
|
207 |
theBlock value
|
260
|
208 |
|
|
209 |
"Modified: 18.5.1996 / 18:48:10 / cg"
|
21
|
210 |
! !
|
0
|
211 |
|
21
|
212 |
!MessageTally methodsFor:'probes'!
|
|
213 |
|
|
214 |
count:aContext
|
260
|
215 |
"entered whenever the probed block gets interrupted;
|
|
216 |
look where it is, and remember in the calling tree"
|
|
217 |
|
263
|
218 |
"{ Pragma: +optSpeed }"
|
|
219 |
|
21
|
220 |
|con chain info atEnd sender home|
|
0
|
221 |
|
21
|
222 |
con := aContext.
|
|
223 |
con isNil ifTrue:[^ self].
|
0
|
224 |
|
21
|
225 |
ntally := ntally + 1.
|
|
226 |
"walk up above the interrupt context"
|
|
227 |
|
|
228 |
[con receiver == Processor] whileTrue:[
|
260
|
229 |
con := con sender
|
0
|
230 |
].
|
|
231 |
|
21
|
232 |
"got it - collect info from contexts"
|
|
233 |
|
|
234 |
"walk up"
|
|
235 |
|
|
236 |
con isNil ifTrue:[^ self].
|
|
237 |
|
|
238 |
atEnd := false.
|
0
|
239 |
|
21
|
240 |
[atEnd] whileFalse:[
|
260
|
241 |
con isNil ifTrue:[
|
|
242 |
atEnd := true
|
|
243 |
] ifFalse:[
|
|
244 |
sender := con sender.
|
|
245 |
sender isNil ifTrue:[
|
|
246 |
atEnd := true
|
|
247 |
] ifFalse:[
|
|
248 |
((sender receiver == self) and:[sender selector == #execute]) ifTrue:[
|
|
249 |
atEnd := true
|
36
|
250 |
"/ ] ifFalse:[
|
|
251 |
"/ (sender isMemberOf:BlockContext) ifTrue:[
|
|
252 |
"/ sender sender selector == #execute ifTrue:[
|
|
253 |
"/ atEnd := true
|
|
254 |
"/ ]
|
|
255 |
"/ ]
|
260
|
256 |
]
|
|
257 |
]
|
|
258 |
].
|
|
259 |
atEnd ifFalse:[
|
263
|
260 |
info := CallChain basicNew.
|
260
|
261 |
(con isMemberOf:BlockContext) ifTrue:[
|
|
262 |
home := con methodHome.
|
|
263 |
home isNil ifTrue:[
|
|
264 |
info receiver:UndefinedObject
|
|
265 |
selector:'optimized'
|
261
|
266 |
class:UndefinedObject
|
|
267 |
isBlock:true.
|
260
|
268 |
] ifFalse:[
|
|
269 |
info receiver:home receiver class
|
|
270 |
selector:home selector
|
261
|
271 |
class:con methodClass
|
|
272 |
isBlock:true.
|
260
|
273 |
].
|
|
274 |
] ifFalse:[
|
|
275 |
info receiver:con receiver class
|
|
276 |
selector:con selector
|
|
277 |
class:con methodClass.
|
|
278 |
].
|
|
279 |
info rest:chain.
|
|
280 |
chain := info.
|
|
281 |
con := sender
|
|
282 |
]
|
21
|
283 |
].
|
|
284 |
"add chain to the tree"
|
|
285 |
|
|
286 |
chain isNil ifTrue:[^ self].
|
|
287 |
|
|
288 |
tree isNil ifTrue:[
|
260
|
289 |
tree := ProfileTree new.
|
|
290 |
tree receiver:MessageTally
|
|
291 |
selector:#execute
|
|
292 |
class:MessageTally .
|
0
|
293 |
].
|
|
294 |
|
21
|
295 |
tree addChain:chain
|
260
|
296 |
|
261
|
297 |
"Modified: 18.5.1996 / 18:53:31 / cg"
|
21
|
298 |
! !
|
0
|
299 |
|
88
|
300 |
!MessageTally methodsFor:'setup'!
|
|
301 |
|
263
|
302 |
spyOn:aBlock interval:ms
|
|
303 |
"spy on execution time"
|
88
|
304 |
|
|
305 |
|startTime endTime running delay|
|
|
306 |
|
|
307 |
theBlock := aBlock.
|
|
308 |
|
|
309 |
Processor activeProcess withPriority:23 do:[
|
263
|
310 |
process := [
|
|
311 |
[
|
|
312 |
self execute
|
|
313 |
] valueNowOrOnUnwindDo:[
|
|
314 |
running := false.
|
|
315 |
theBlock := nil.
|
|
316 |
]
|
|
317 |
] newProcess.
|
88
|
318 |
|
263
|
319 |
Processor activeProcess withPriority:24 do:[
|
|
320 |
startTime := OperatingSystem getMillisecondTime.
|
|
321 |
delay := (Delay forMilliseconds:ms).
|
88
|
322 |
|
263
|
323 |
ntally := 0.
|
|
324 |
running := true.
|
|
325 |
process resume.
|
88
|
326 |
|
263
|
327 |
[running] whileTrue:[
|
|
328 |
delay wait.
|
|
329 |
self count:process suspendedContext
|
|
330 |
].
|
88
|
331 |
|
263
|
332 |
endTime := OperatingSystem getMillisecondTime.
|
|
333 |
].
|
88
|
334 |
].
|
|
335 |
|
|
336 |
tree notNil ifTrue:[tree computePercentage:ntally].
|
|
337 |
^ endTime - startTime
|
263
|
338 |
|
|
339 |
"Modified: 18.5.1996 / 19:10:27 / cg"
|
88
|
340 |
! !
|
|
341 |
|
98
|
342 |
!MessageTally class methodsFor:'documentation'!
|
|
343 |
|
261
|
344 |
version
|
264
|
345 |
^ '$Header: /cvs/stx/stx/libbasic3/MessageTally.st,v 1.26 1996-05-18 17:21:20 cg Exp $'
|
98
|
346 |
! !
|