links to this page:    
View this PageEdit this PageUploads to this PageHistory of this PageTop of the SwikiRecent ChangesSearch the SwikiHelp Guide
Last updated at 9:25 pm UTC on 13 January 2024
(culled from https://lists.wisc.edu/read/messages?id=1411189 written by Andreas Raab)


The primary tool to measure performance, both for Squeak in general as
well as for Croquet, is MessageTally. MessageTally acts on a particular
expression (MessageTally spyOn:["your expression here"]) and provides
the following information:

MessageTally uses a technique known as pc-sampling. What that means is that a high-priority process is started which (based on a timer) samples the call stack of the process and allocates a time value (typically whatever it's using for sampling).

It is important to notice that this is a statistical measure - given a large enough number of samples, the reported result will be statistically valid. On the other hand, small numbers of samples are typically statistically invalid - a single garbage collection can lead to a major change in an otherwise insignificant part of the computation.

Here is an example:
MessageTally spyOn:[100 raisedTo: 1000].

resulted in the following output:
100.0% {3ms} SmallInteger(Number)>>raisedTo:
100.0% {3ms} SmallInteger(Number)>>raisedToInteger:
50.0% {2ms} LargePositiveInteger>>*
50.0% {2ms} primitives

These results claim that we're spending 50% of the overall time in Multiplying large integers. Which is completely bogus since we have only two samples (the default sampling rate is 1ms). If we run this for a longer period of time, like here:
MessageTally spyOn:[1000 timesRepeat:[100 raisedTo: 1000]]

100.0% {1007ms} SmallInteger(Number)>>raisedTo:
99.9% {1006ms} SmallInteger(Number)>>raisedToInteger:
96.8% {975ms} primitives
3.0% {30ms} LargePositiveInteger>>*

We see that indeed, we only spend roughly 3% in multiplying large integers. The other 97% are spent in primitives which, unfortunately, are not broken out separately in the measures (however, if such a measure is critical, then the primitives can to be factored into separate methods which then call the primitives themselves - this allows message tally to "see" the method frames and report the usage accordingly).

In a more complex situation, the percentage tree is typically useful to figure out roughly the areas in which time is spent which can then be measured individually.


The Leaves reported by MessageTally is the amount of time spent in a method without the time spent in the methods called from that method. In our above example the leaves are reported as:
96.8% {975ms} SmallInteger(Number)>>raisedToInteger:

which is the overall time spent in Number>>raisedToInteger: (1006ms) minus the time spent in LargePositiveInteger>>* (30ms). If a method shows up in the leaves it typically means that this method is computationally expensive or just gets called a large number of times.


The Memory statistics shown in MessageTally provide information about how various memory regions have changed:


The GCs statistics provide information about the garbage collector:

Multiple processes

Historically, MessageTally measured and reported only the call stack of the current process. This had the disadvantage that if time was spent in a different process, it would be attributed to a bogus frame in current thread. For Croquet, I have changed this such that all processes are reported in order to be able to see "what else" is going on.

For example, if we measure an expression like here:
MessageTally spyOn:[(Delay forSeconds: 5) wait]

we will find that all of the time is reported here:
99.5% {4975ms} ProcessorScheduler class>>startUp
99.5% {4975ms} ProcessorScheduler class>>idleProcess

The idle process is the process that is being activated when no other activity occurs (the implementation of the idle process requests the VM to sleep for a millisecond so that the VM isn't running a busy). Generally, time reported in idleProcess is time spent "doing nothing" (e.g., waiting for some activity).

The other relevant system process that may show up is the finalization process. If the finalization process shows up, it means we're having a problem with too many weak references being finalized. This has been a big problem in the past, so keep an eye on it.

stephane ducasse wrote:
> may be you want to send the changes you did to get other processes
> analyzed. We could merge that in Squeak

In MessageTally>>spyEvery:on: where it says:

Timer :=
[[true] whileTrue:
[startTime := Time millisecondClockValue.
myDelay wait.
self tally: ObservedProcess
"tally can be > 1 if ran a long primitive"
by: (Time millisecondClockValue - startTime) // millisecs].

Simply replace:

self tally: ObservedProcess


self tally: Processor preemptedProcess suspendedContext

- Andreas

Other ways to invoke the MessageTally