On VW we use TimeProfiler & KaiProfiler, and on GS we use ProfMonitor. All are useful for getting a sense of where to look, after which we switch to more basic tools, like...
Time>>millisecondsToRun:, along with some convenience methods.
In VW you can use the Transcript to show performance measurements.
You could write something like...
Transcript cr; show: 'tag for this code'; show: (Time millisecondsToRun: [some code]) printString.
...but that's a pain. And you'd need the 'tag for this code' if you have several measurements spread throughout the code. To make that easier, we use...
'tag for this code' echoTime: [some code]
...which is implemented as...
echoTime: aBlock
| result microseconds |
microseconds := Time microsecondsToRun: [result := aBlock value].
self echo: microseconds displayMicroseconds.
^result
...the #echo: method is commented on in a previous post and #displayMicroseconds is just...
Integer>>displayMicroseconds
self > 1000 ifTrue: [^(self // 1000) displayTime].
^self printString, 'µs'
...and displayTime shows hh:mm:ss.mmm with hh and mm displayed if needed.
In GS you could use the VW transcript with a client forwarder, but our application uses a simplified GS interface model with only one forwarder and no replication (an XML string is the only returned value from GS), so adding a client forwarder was something I did not want to do. I also wanted to run some tests from a Topaz script.
Instead of a Transcript I use a String WriteStream held in a GS session variable and use Time class methods to add measurements and show the results. To measure a block of code, we add nested time measurements with...
Time log: 'tag for this code' run: [some code]
...and we wrap the top method send with...
Time showLog: [top method]
...some methods get called a lot, so we'd like a total time. For that we use...
Time sum: 'tag for this method' run: [some code]
...because each Time method answers the block result we can insert the code easily...
someValue := self bigMethod
...vs...
someValue := Time log: 'bigMethod' run: [self bigMethod]
These are the methods...
Time>>showLog: aBlock
self timeSumDictionary: Dictionary new.
self timeLogStream: String new writeStream.
self timeLogStream nextPutAll: 'Time...'.
self log: 'time' run: aBlock.
^self timeLogStream contents , self displayTimeSums
...each time* variable is stored in the GS session array, like...
timeLogStream
^System __sessionStateAt: 77
timeLogStream: anObject
System __sessionStateAt: 77 put: anObject
log: aMessage run: aBlock
"Time showLog: [Time log: 'test' run: [(Delay forSeconds: 1) wait] ]"
| result microseconds |
microseconds := self millisecondsToRun: [result := aBlock value].
self timeLogStreamAt: aMessage put: microseconds.
^result
timeLogStreamAt: aMessage put: anInteger
| stream |
stream := self timeLogStream.
stream isNil ifTrue: [
stream := String new writeStream.
self timeLogStream: stream].
stream
cr; nextPutAll: aMessage; tab;
nextPutAll: anInteger displayTime.
self timeSumDictionaryAt: aMessage add: anInteger.
sum: aMessage run: aBlock
"Time showLog: [
Time sum: 'test' run: [(Delay forSeconds: 1) wait].
Time sum: 'test' run: [(Delay forSeconds: 1) wait]]"
| result milliseconds |
milliseconds := self millisecondsToRun: [result := aBlock value].
self timeSumDictionaryAt: aMessage add: milliseconds.
^result
timeSumDictionaryAt: aKey add: aValue
| dictionary total |
dictionary := self timeSumDictionary.
dictionary isNil ifTrue: [
dictionary := Dictionary new.
self timeSumDictionary: dictionary].
total := dictionary at: aKey ifAbsent: [0].
total := total + aValue.
dictionary at: aKey put: total.
Simple things should be simple. Complex things should be possible.
