[Cuis-dev] Jitter source during benchmarks

[Martin McClure]

Ooh, that is interesting. Alas, I have no good suggestions.

On 5/12/26 2:15 PM, Nicolás Papagna Maldonado via Cuis-dev wrote:
> Hi Martin!
>
> On Tue, May 12, 2026 at 6:05 PM Martin McClure <martin at hand2mouse.com> 
> wrote:
>
>     Hi Nico,
>
>     I would definitely suspect GC. You've already eliminated
>     full/incremental GC. Does Cuis keep statistics on when scavenges
>     are done? It's a sub-millisecond difference between the peaks.
>     ~700 microseconds seems like maybe a bit long for a scavenge, but
>     not unbelievable.
>
>     To eliminate memory allocation or GC effects, you could try
>     running a full GC between each repetition of the test and see
>     whether there is still a bimodal distribution.
>
> Sorry I was not clear enough, my bad.
> That's what I did. Before I run each test suite I run a full GC:
>
> testSuites collect: [ :testSuite | self profile: [ testSuite run ] ].
>
> I implemented #profile: as follows:
>
> profile: aBlock
>
>     Smalltalk garbageCollect.
>     startVMStats := Smalltalk getVMParameters.
>     ticksPerMs := Time highResTimerTicksPerMillisecond.
>     startTicks := Time primHighResClock.
>
>     aBlock value.
>
>     endTicks := Time primHighResClock.
>     endVMStats := Smalltalk getVMParameters.
>
>     "returned result includes
>         elapsed time based on (endTicks-startTicks)/ticksPerMs.
>         Full GC count & ms based on endVMStats - startVMStats
>         Incremental GC count & ms based on endVMStats - startVMStats"
>
> No GC activity was observed (full or incremental) on all the 50 
> Aconcagua test suite runs.
>
>     Regards,
>
>     -Martin
>
>     On 5/12/26 12:17 PM, Nicolás Papagna Maldonado via Cuis-dev wrote:
>>     Hi folks,
>>
>>     I'm in the process of doing performance benchmarks of my Code
>>     Coverage tool for my thesis, and I've encountered something
>>     interesting while measuring the test execution times of the
>>     Aconcagua package.
>>
>>     *Observation:*
>>     When running the Aconcagua test suite 150 times in a clean image,
>>     the execution times are not normally distributed. Instead, they
>>     fall into two distinct "modes":
>>
>>     image.png
>>     A Base Mode (~6.28 ms): Representing roughly 72% of the iterations.
>>     A Spike Mode (~7.0 ms): Representing roughly 28% of the iterations.
>>
>>     As the next plot shows, the spikes are not random; they seem to
>>     be kind-of deterministic (roughly every 4th iteration).
>>     I think these perturbations are visible because I'm taking very
>>     small measurements (~6.28 ms).
>>     image.png
>>
>>     *Question:*
>>     I am trying to isolate whether this "heartbeat" is originating
>>     from within the Cuis image or the VM/OS layer (I'm thinking of VM
>>     timer/events, maybe UI timers?)
>>     Does anyone know what could be causing this?
>>     Are there any known events that run at this particular frequency?
>>
>>     I repeated the experiment a couple of times and the perturbations
>>     are consistent (in terms of ms and frequency).
>>
>>     *Methodology:*
>>
>>       * Measurements were taken in batches of 50 test runs.
>>       * Each batch was run in a fresh image, waiting 2 minutes for
>>         the VM to stabilize Cuis code.
>>       * 10 warmup runs were done and discarded before measuring test
>>         run times.
>>       * Measurements were taken using Time primHighResClock and
>>         converted to ms using Time highResTimerTicksPerMillisecond.
>>       * VM stats were collected before and after measurements. A full
>>         GC was run before taking measurements.
>>       * No GC activity was observed while measuring the tests run (VM
>>         stats report no full nor incremental GCs).
>>       * The test suite was created and run from a workspace
>>
>>     *Cuis environment:*
>>
>>       * Cuis Smalltalk commit:
>>         https://github.com/Cuis-Smalltalk/Cuis-Smalltalk-Dev/commit/b221722348cc46ebb9f5d9f3a057a3f361aa3d55
>>       * Code Coverage commit:
>>         https://github.com/npapagna/cuis-code-coverage/commit/db19de02250a3fd50dfc4e0b4d0893b656e31e9b
>>       * Aconcagua commit:
>>         https://github.com/Cuis-Smalltalk/Measures/commit/05aa02aada64f7b64898a5e1452ae8fb76f79427
>>
>>     *Machine environment:*
>>
>>       * Model Name: MacBook Pro
>>       * Model Identifier: MacBookPro18,3
>>       * Model Number: MKGR3LL/A
>>       * Chip: Apple M1 Pro
>>       * Total Number of Cores: 8 (6 Performance and 2 Efficiency)
>>       * Memory: 16 GB
>>       * System Firmware Version: 13822.81.10
>>       * OS Loader Version: 13822.81.102
>>       * APPLE SSD AP0512R (NVMe, avg read 5671 MB/s, avg write 5670 MB/s)
>>       * macOs 26.3 (25D125)
>>       * A dedicated fresh profile was created for the benchmarks
>>         (indexing, time machine, screen lock/saver, display shutdown,
>>         bluetooth and wifi disabled).
>>
>>     Thanks in advance,
>>     Nico PM
>>
>>
>
>
> -- 
>
> Nicolás Papagna
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.cuis.st/mailman/archives/cuis-dev/attachments/20260512/61a6fb8f/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image.png
Type: image/png
Size: 48058 bytes
Desc: not available
URL: <http://lists.cuis.st/mailman/archives/cuis-dev/attachments/20260512/61a6fb8f/attachment-0002.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image.png
Type: image/png
Size: 175232 bytes
Desc: not available
URL: <http://lists.cuis.st/mailman/archives/cuis-dev/attachments/20260512/61a6fb8f/attachment-0003.png>