<!DOCTYPE html>
<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
</head>
<body>
<p>Ooh, that is interesting. Alas, I have no good suggestions.</p>
<div class="moz-cite-prefix">On 5/12/26 2:15 PM, Nicolás Papagna
Maldonado via Cuis-dev wrote:<br>
</div>
<blockquote type="cite"
cite="mid:CADGn7BMune6c000BTEVpxvKKqDW81f6bFgCKWF+NKoM2XvkZSg@mail.gmail.com">
<meta http-equiv="content-type" content="text/html; charset=UTF-8">
<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" moz-do-not-send="true"
class="moz-txt-link-freetext">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">
<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:part1.v3wWFvMW.McW6ubsA@hand2mouse.com"
alt="image.png" width="535" height="423"
class=""><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:part2.fIAF3pwU.RL4Q0ovH@hand2mouse.com"
alt="image.png" width="535" height="422"
class=""><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" moz-do-not-send="true"
class="moz-txt-link-freetext">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" moz-do-not-send="true"
class="moz-txt-link-freetext">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" moz-do-not-send="true"
class="moz-txt-link-freetext">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>
<br>
<fieldset class="moz-mime-attachment-header"></fieldset>
</blockquote>
</body>
</html>