16.5: Illustrative Analysis

Understanding the result obtained when profiling is the very first step when one wants to optimize an application. However, as you probably started to feel, understanding why a computation is costly is not trivial. Based on a number of examples, we will see how comparing different profiling results greatly helps to identify costly message calls.

The method "," is known to be slow since it creates a new character string and copy both the receiver and the argument into it. Using a Stream is a significant faster approach to concatenate character strings. However, nextPut: and nextPutAll: must be carefully employed!

Using a Stream for string concatenation. At the first glance, one could think that creating a stream is costly since it is frequently used with relatively slow inputs and outputs (e.g., network socket, disk accesses, Transcript). But replacing the string concatenation employed in the previous example by a stream operation is almost 10 times faster! This is easily understandable since concatenating 9000 times a character strings creates 8999 intermediately objects, each being filled with the content of another. Using a stream, we simply have to append a character at each iteration.

MessageTally spyOn:
    [ 500 timesRepeat: [
            | str |
            str := WriteStream on: (String new).
            9000 timesRepeat: [ str nextPut: $A ]]].

- 807 tallies, 807 msec. **Tree**
--------------------------------
Process: (40s) 535298048: nil
--------------------------------

**Leaves**
33.0% {266ms} SmallInteger(Integer)>>timesRepeat:
21.2% {171ms} UndefinedObject>>DoIt

**Memory**
    old        +0 bytes
    young      -18,272 bytes
    used       -18,272 bytes
    free       +18,272 bytes

**GCs**
    full       0 totalling 0ms (0.0% uptime)
    incr       5 totalling 7ms (3.0% uptime), avg 1.0ms
    tenures    0
    root table 0 overflows

String preallocation. Using OrderedCollection without a preallocation of the collection is well known for being costly. Each time the collection is full, its content has to be copied into a larger collection. Carefully choosing a preallocation has an impact of using ordered collections. The message new: aNumber could be used instead of new.

MessageTally spyOn:
    [ 500 timesRepeat: [
            | str |
            str := WriteStream on: (String new: 9000).
            9000 timesRepeat: [ str nextPut: $A ]]].

For this example, it is possible to improve the script by using the method atAllPut:. The script below takes only a couple of milliseconds.

MessageTally spyOn:
    [ 500 timesRepeat: [
            | str |
            str :=String new: 9000.
            str atAllPut: $A ]].

An experiment. Doing benchmarks shines when different executions are compared. In the previous piece of code, replacing the value 9000 by 500 is valuable. The time taken with 9000 iterations is 2.7 times slower than with 500. Using the string concatenation (i.e., using the , method) instead of a stream widens the gap with a factor 10. This experiment clearly illustrates the importance of using appropriate tools to concatenate strings.

The time of the profiled execution is also an important quality factor for the result. MessageTally employs a sampling technique to profile code. Per default, MessageTally samples the current executing thread each millisecond per default. It is therefore necessary that all the methods involved in the computation are executed a “fair” amount of time to appear in the result report. If the application to profile is very short (few milliseconds only), then executing it a number of times help improving the accuracy of the report.