Smalltalk performance measurement

The application I'm working on uses VisualWorks and GemStone. As we've built out our application and loaded more test data we find ourselves spending more time turning performance. If there is one thing I've learned over the years that is performance problems are never what they seem: always measure before you change the code. Premature optimization makes your code ugly and, more likely than not, adds no value.

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.