<div dir="ltr"><div dir="ltr">Hi Martin!</div><br><div class="gmail_quote gmail_quote_container"><div dir="ltr" class="gmail_attr">On Tue, May 12, 2026 at 6:05 PM Martin McClure <<a href="mailto:martin@hand2mouse.com">martin@hand2mouse.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><u></u>
<div>
<p>Hi Nico,</p>
<p>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.</p>
<p>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.</p></div></blockquote><div>Sorry I was not clear enough, my bad.</div><div>That's what I did. Before I run each test suite I run a full GC:</div><div><br></div><div><font face="monospace">testSuites collect: [ :testSuite | self profile: [ testSuite run ] ].</font></div></div><div class="gmail_quote gmail_quote_container"><div><br></div><div>I implemented #profile: as follows:</div><div><br></div><div><font face="monospace">profile: aBlock</font></div><div><font face="monospace"><br> Smalltalk garbageCollect.<br> startVMStats := Smalltalk getVMParameters.<br> ticksPerMs := Time highResTimerTicksPerMillisecond.<br> startTicks := Time primHighResClock.<br><br> aBlock value.<br><br></font></div><div><font face="monospace"> endTicks := Time primHighResClock.<br> endVMStats := Smalltalk getVMParameters.<br><br> "returned result includes </font></div><div><font face="monospace"> elapsed time based on (endTicks-startTicks)/ticksPerMs.<br> Full GC count & ms based on endVMStats - </font><span style="font-family:monospace">startVMStats</span><font face="monospace"><br> Incremental GC count & ms </font><font face="monospace">based on endVMStats - </font><span style="font-family:monospace">startVMStats</span><font face="monospace">"</font><br><br>No GC activity was observed (full or incremental) on all the 50 Aconcagua test suite runs.</div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div>
<p>Regards,</p>
<p>-Martin </p>
<div>On 5/12/26 12:17 PM, Nicolás Papagna
Maldonado via Cuis-dev wrote:<br>
</div>
<blockquote type="cite">
<div dir="ltr">
<div dir="ltr">
<div>Hi folks,</div>
<div><br>
</div>
<div>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.</div>
<div><br>
</div>
<div><b>Observation:</b><br>
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":<br>
<br>
<img src="cid:ii_19e1e038234cb971f161" alt="image.png" width="535" height="423"><br>
A Base Mode (~6.28 ms): Representing roughly 72% of the
iterations.<br>
A Spike Mode (~7.0 ms): Representing roughly 28% of the
iterations.<br>
<br>
As the next plot shows, the spikes are not random; they
seem to be kind-of deterministic (roughly every 4th
iteration).</div>
<div>I think these perturbations are visible because I'm
taking very small measurements (~6.28 ms).</div>
<div><img src="cid:ii_19e1e038234cb971f162" alt="image.png" width="535" height="422"><br>
<br>
<b>Question:</b><br>
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?)</div>
<div>Does anyone know what could be causing this?</div>
<div>Are there any known events that run at this particular
frequency?</div>
<div><br>
</div>
<div>I repeated the experiment a couple of times and the
perturbations are consistent (in terms of ms and frequency).</div>
<div><br>
</div>
<div><b>Methodology:</b></div>
<div>
<ul>
<li>Measurements were taken in batches of 50 test runs.</li>
<li>Each batch was run in a fresh image, waiting 2 minutes
for the VM to stabilize Cuis code.</li>
<li>10 warmup runs were done and discarded before
measuring test run times.</li>
<li>Measurements were taken using Time primHighResClock
and converted to ms using Time
highResTimerTicksPerMillisecond.</li>
<li>VM stats were collected before and after measurements.
A full GC was run before taking measurements.</li>
<li>No GC activity was observed while measuring the tests
run (VM stats report no full nor incremental GCs).</li>
<li>The test suite was created and run from a workspace</li>
</ul>
</div>
<div><b>Cuis environment:</b><br>
<ul>
<li>Cuis Smalltalk commit: <a href="https://github.com/Cuis-Smalltalk/Cuis-Smalltalk-Dev/commit/b221722348cc46ebb9f5d9f3a057a3f361aa3d55" target="_blank">https://github.com/Cuis-Smalltalk/Cuis-Smalltalk-Dev/commit/b221722348cc46ebb9f5d9f3a057a3f361aa3d55</a></li>
<li>Code Coverage commit: <a href="https://github.com/npapagna/cuis-code-coverage/commit/db19de02250a3fd50dfc4e0b4d0893b656e31e9b" target="_blank">https://github.com/npapagna/cuis-code-coverage/commit/db19de02250a3fd50dfc4e0b4d0893b656e31e9b</a></li>
<li>Aconcagua commit: <a href="https://github.com/Cuis-Smalltalk/Measures/commit/05aa02aada64f7b64898a5e1452ae8fb76f79427" target="_blank">https://github.com/Cuis-Smalltalk/Measures/commit/05aa02aada64f7b64898a5e1452ae8fb76f79427</a></li>
</ul>
<b>Machine environment:</b><br>
<ul>
<li>Model Name: MacBook Pro</li>
<li>Model Identifier: MacBookPro18,3</li>
<li>Model Number: MKGR3LL/A</li>
<li>Chip: Apple M1 Pro</li>
<li>Total Number of Cores: 8 (6 Performance and 2
Efficiency)</li>
<li>Memory: 16 GB</li>
<li>System Firmware Version: 13822.81.10</li>
<li>OS Loader Version: 13822.81.102</li>
<li>APPLE SSD AP0512R (NVMe, avg read 5671 MB/s, avg
write 5670 MB/s)</li>
<li>macOs 26.3 (25D125)</li>
<li>A dedicated fresh profile was created for the
benchmarks (indexing, time machine, screen lock/saver,
display shutdown, bluetooth and wifi disabled).</li>
</ul>
</div>
</div>
<div dir="ltr">
<div>Thanks in advance,</div>
<div>Nico PM</div>
<div><br>
</div>
</div>
</div>
<br>
<fieldset></fieldset>
</blockquote>
</div>
</blockquote></div><div><br clear="all"></div><div><br></div><span class="gmail_signature_prefix">-- </span><br><div dir="ltr" class="gmail_signature"><br>Nicolás Papagna</div></div>