<div dir="ltr">Hi Philippe,<br><div class="gmail_extra"><br><br><div class="gmail_quote">On Tue, Jun 17, 2014 at 1:03 AM, Philippe Marschall <span dir="ltr"><<a href="mailto:philippe.marschall@netcetera.ch" target="_blank">philippe.marschall@netcetera.ch</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="">On 13.06.14 01:41, Eliot Miranda wrote:<br>
</div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="">
<br>
<br>
<br>
<br>
Hi All,<br>
<br>
it gives me great pleasure to let you know that a spur-format trunk<br>
Squeak image is finally available at<br>
<a href="http://www.mirandabanda.org/files/Cog/SpurImages/" target="_blank">http://www.mirandabanda.org/<u></u>files/Cog/SpurImages/</a>. Spur VMs are<br>
available at <a href="http://www.mirandabanda.org/files/Cog/VM/VM.r2987/" target="_blank">http://www.mirandabanda.org/<u></u>files/Cog/VM/VM.r2987/</a>.<br>
<br></div>
…<br>
</blockquote>
<br>
I'm seeing a Seaside request handling benchmark going from 10k req/s to 11k req/s.<br>
Don't be too quick to dismiss this as being IO-bound (being IO-bound is actually quite hard on Squeak/Pharo). During the benchmark Squeak fully saturates one core. It is hard to tell what the limiting factor for this benchmark actually is. But removing one or two String allocations from the request handling loop usually yields about 100 to 200 additional req/s.<br>
</blockquote><div><br></div><div>That's good news at least. One thing you can try is the VMProfiler. It's an interactive Morphic application so it will try and open and may crash Load the VMProfiler and use it via</div>
<div><br></div><div> VMProfiler openInstance</div><div> spyOn: [...];</div><div> report: aStream.</div><div><br></div><div>e.g. </div><div><div>VMProfiler openInstance</div><div><span class="Apple-tab-span" style="white-space:pre"> </span>spyOn: [1 tinyBenchmarks];</div>
<div><span class="Apple-tab-span" style="white-space:pre"> </span>report: (Transcript cr; yourself).</div><div>Transcript flush.</div><div><br></div><div>produces:</div><div><br></div><div><div>/Users/eliot/Cog/oscogvm/build.macos32x86/squeak.cog.spur/Fast.app/Contents/MacOS/Squeak 6/17/2014 </div>
<div>eden size: 2,603,344 stack pages: 160 code size: 1,048,576</div><div><br></div><div>1 tinyBenchmarks</div><div><br></div><div>gc prior. clear prior. </div><div>6.298 seconds; sampling frequency 1473 hz</div><div>
9231 samples in the VM<span class="Apple-tab-span" style="white-space:pre"> </span>(9275 samples in the entire program) 99.53% of total</div><div><br></div><div>8798 samples in generated vm code 95.31% of entire vm (94.86% of total)</div>
<div>433 samples in vanilla vm code 4.69% of entire vm ( 4.67% of total)</div><div><br></div><div>% of generated vm code (% of total)<span class="Apple-tab-span" style="white-space:pre"> </span>(samples) (cumulative)</div>
<div>61.29% (58.13%)<span class="Apple-tab-span" style="white-space:pre"> </span>Integer>>benchFib<span class="Apple-tab-span" style="white-space:pre"> </span>(5392)<span class="Apple-tab-span" style="white-space:pre"> </span>(61.29%)</div>
<div>13.47% (12.78%)<span class="Apple-tab-span" style="white-space:pre"> </span>Integer>>benchmark<span class="Apple-tab-span" style="white-space:pre"> </span>(1185)<span class="Apple-tab-span" style="white-space:pre"> </span>(74.76%)</div>
<div>11.48% (10.89%)<span class="Apple-tab-span" style="white-space:pre"> </span>Object>>at:put:<span class="Apple-tab-span" style="white-space:pre"> </span>(1010)<span class="Apple-tab-span" style="white-space:pre"> </span>(86.24%)</div>
<div> 9.60% ( 9.11%)<span class="Apple-tab-span" style="white-space:pre"> </span>SmallInteger>>+<span class="Apple-tab-span" style="white-space:pre"> </span>(845)<span class="Apple-tab-span" style="white-space:pre"> </span>(95.84%)</div>
<div> 3.99% ( 3.78%)<span class="Apple-tab-span" style="white-space:pre"> </span>Object>>at:<span class="Apple-tab-span" style="white-space:pre"> </span>(351)<span class="Apple-tab-span" style="white-space:pre"> </span>(99.83%)</div>
<div> 0.07% ( 0.06%)<span class="Apple-tab-span" style="white-space:pre"> </span>ceBaseFram...Trampoline(6)<span class="Apple-tab-span" style="white-space:pre"> </span>(99.90%)</div><div> 0.03% ( 0.03%)<span class="Apple-tab-span" style="white-space:pre"> </span>ceMethodAbort0Args<span class="Apple-tab-span" style="white-space:pre"> </span>(3)<span class="Apple-tab-span" style="white-space:pre"> </span>(99.93%)</div>
<div> 0.03% ( 0.03%)<span class="Apple-tab-span" style="white-space:pre"> </span>Sequenceabl...om:to:put:<span class="Apple-tab-span" style="white-space:pre"> </span>(3)<span class="Apple-tab-span" style="white-space:pre"> </span>(99.97%)</div>
<div> 0.02% ( 0.02%)<span class="Apple-tab-span" style="white-space:pre"> </span>Magnitude>>min:<span class="Apple-tab-span" style="white-space:pre"> </span>(2)<span class="Apple-tab-span" style="white-space:pre"> </span>(99.99%)</div>
<div> 0.01% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>ceEnterCog...ceiverReg<span class="Apple-tab-span" style="white-space:pre"> </span>(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(100.0%)</div>
<div><br></div><div><br></div><div>% of vanilla vm code (% of total)<span class="Apple-tab-span" style="white-space:pre"> </span>(samples) (cumulative)</div><div>32.33% ( 1.51%)<span class="Apple-tab-span" style="white-space:pre"> </span>primitiveStringReplace<span class="Apple-tab-span" style="white-space:pre"> </span>(140)<span class="Apple-tab-span" style="white-space:pre"> </span>(32.33%)</div>
<div>24.25% ( 1.13%)<span class="Apple-tab-span" style="white-space:pre"> </span>copyAndForward<span class="Apple-tab-span" style="white-space:pre"> </span>(105)<span class="Apple-tab-span" style="white-space:pre"> </span>(56.58%)</div>
<div>13.63% ( 0.64%)<span class="Apple-tab-span" style="white-space:pre"> </span>marryFrameSP<span class="Apple-tab-span" style="white-space:pre"> </span>(59)<span class="Apple-tab-span" style="white-space:pre"> </span>(70.21%)</div>
<div>10.85% ( 0.51%)<span class="Apple-tab-span" style="white-space:pre"> </span>instantiateClassindexableSize<span class="Apple-tab-span" style="white-space:pre"> </span>(47)<span class="Apple-tab-span" style="white-space:pre"> </span>(81.06%)</div>
<div> 3.46% ( 0.16%)<span class="Apple-tab-span" style="white-space:pre"> </span>ceBaseFrameReturn<span class="Apple-tab-span" style="white-space:pre"> </span>(15)<span class="Apple-tab-span" style="white-space:pre"> </span>(84.53%)</div>
<div> 2.08% ( 0.10%)<span class="Apple-tab-span" style="white-space:pre"> </span>scavengeLoop<span class="Apple-tab-span" style="white-space:pre"> </span>(9)<span class="Apple-tab-span" style="white-space:pre"> </span>(86.61%)</div>
<div> 1.62% ( 0.08%)<span class="Apple-tab-span" style="white-space:pre"> </span>checkForEvent...ontextSwitch<span class="Apple-tab-span" style="white-space:pre"> </span>(7)<span class="Apple-tab-span" style="white-space:pre"> </span>(88.22%)</div>
<div> 1.39% ( 0.06%)<span class="Apple-tab-span" style="white-space:pre"> </span>externalEnsureIsBaseFrame<span class="Apple-tab-span" style="white-space:pre"> </span>(6)<span class="Apple-tab-span" style="white-space:pre"> </span>(89.61%)</div>
<div> 1.39% ( 0.06%)<span class="Apple-tab-span" style="white-space:pre"> </span>voidVMStateForSn...nalPrimitivesIf(6)<span class="Apple-tab-span" style="white-space:pre"> </span>(90.99%)</div><div> 1.15% ( 0.05%)<span class="Apple-tab-span" style="white-space:pre"> </span>mapInterpreterOops<span class="Apple-tab-span" style="white-space:pre"> </span>(5)<span class="Apple-tab-span" style="white-space:pre"> </span>(92.15%)</div>
<div> 1.15% ( 0.05%)<span class="Apple-tab-span" style="white-space:pre"> </span>returnToExecuti...tContextSwitch(5)<span class="Apple-tab-span" style="white-space:pre"> </span>(93.30%)</div><div> 1.15% ( 0.05%)<span class="Apple-tab-span" style="white-space:pre"> </span>scavengeReferentsOf<span class="Apple-tab-span" style="white-space:pre"> </span>(5)<span class="Apple-tab-span" style="white-space:pre"> </span>(94.46%)</div>
<div> 0.92% ( 0.04%)<span class="Apple-tab-span" style="white-space:pre"> </span>handleStackOverflow<span class="Apple-tab-span" style="white-space:pre"> </span>(4)<span class="Apple-tab-span" style="white-space:pre"> </span>(95.38%)</div>
<div> 0.92% ( 0.04%)<span class="Apple-tab-span" style="white-space:pre"> </span>signed64BitIntegerFor<span class="Apple-tab-span" style="white-space:pre"> </span>(4)<span class="Apple-tab-span" style="white-space:pre"> </span>(96.30%)</div>
<div> 0.46% ( 0.02%)<span class="Apple-tab-span" style="white-space:pre"> </span>primitiveShortAt<span class="Apple-tab-span" style="white-space:pre"> </span>(2)<span class="Apple-tab-span" style="white-space:pre"> </span>(96.77%)</div>
<div> 0.46% ( 0.02%)<span class="Apple-tab-span" style="white-space:pre"> </span>ceNonLocalReturn<span class="Apple-tab-span" style="white-space:pre"> </span>(2)<span class="Apple-tab-span" style="white-space:pre"> </span>(97.23%)</div>
<div> 0.23% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>gMoveCwR<span class="Apple-tab-span" style="white-space:pre"> </span>(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(97.46%)</div>
<div> 0.23% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>genInnerPrimit...CharacterinReg<span class="Apple-tab-span" style="white-space:pre"> </span>(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(97.69%)</div>
<div> 0.23% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>genPrimitiveMultiply<span class="Apple-tab-span" style="white-space:pre"> </span>(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(97.92%)</div>
<div> 0.23% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>primitiveInflateDecompressBlock(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(98.15%)</div><div> 0.23% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>primitiveNewWithArg<span class="Apple-tab-span" style="white-space:pre"> </span>(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(98.38%)</div>
<div> 0.23% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>primitiveTestAnd...fCriticalSection(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(98.61%)</div><div> 0.23% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>processWeaklings<span class="Apple-tab-span" style="white-space:pre"> </span>(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(98.85%)</div>
<div> 0.23% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>scavengingGCTenuringIf<span class="Apple-tab-span" style="white-space:pre"> </span>(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(99.08%)</div>
<div> 0.23% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>updateMaybeObjRefAt<span class="Apple-tab-span" style="white-space:pre"> </span>(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(99.31%)</div>
<div> 0.23% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>wakeHighestPriority<span class="Apple-tab-span" style="white-space:pre"> </span>(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(99.54%)</div>
<div> 0.23% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>ceCannotResume<span class="Apple-tab-span" style="white-space:pre"> </span>(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(99.77%)</div>
<div> 0.23% ( 0.01%)<span class="Apple-tab-span" style="white-space:pre"> </span>ioPositionOfWindowSetxy<span class="Apple-tab-span" style="white-space:pre"> </span>(1)<span class="Apple-tab-span" style="white-space:pre"> </span>(100.0%)</div>
<div><br></div><div><br></div><div><br></div><div>**Memory**</div><div><span class="Apple-tab-span" style="white-space:pre"> </span>old<span class="Apple-tab-span" style="white-space:pre"> </span>+574,744 bytes</div><div>
<br></div><div>**GCs**</div><div><span class="Apple-tab-span" style="white-space:pre"> </span>full<span class="Apple-tab-span" style="white-space:pre"> </span>0 totalling 0ms (0% elapsed time)</div><div><span class="Apple-tab-span" style="white-space:pre"> </span>scavenges<span class="Apple-tab-span" style="white-space:pre"> </span>330 totalling 93ms (1.477% elapsed time), avg 0.282ms</div>
<div><span class="Apple-tab-span" style="white-space:pre"> </span>tenures<span class="Apple-tab-span" style="white-space:pre"> </span>0</div><div><span class="Apple-tab-span" style="white-space:pre"> </span>root table<span class="Apple-tab-span" style="white-space:pre"> </span>0 overflows</div>
<div><br></div><div>**Compiled Code Compactions**</div><div><span class="Apple-tab-span" style="white-space:pre"> </span>0 totalling 0ms (0% elapsed time)</div><div><br></div><div>**Events**</div><div>Process switches<span class="Apple-tab-span" style="white-space:pre"> </span>66 (10 per second)</div>
<div>ioProcessEvents calls<span class="Apple-tab-span" style="white-space:pre"> </span>314 (50 per second)</div><div>Interrupt checks<span class="Apple-tab-span" style="white-space:pre"> </span>3462 (550 per second)</div>
<div>Event checks<span class="Apple-tab-span" style="white-space:pre"> </span>3585 (569 per second)</div><div>Stack overflows<span class="Apple-tab-span" style="white-space:pre"> </span>421897 (66989 per second)</div><div>
Stack page divorces<span class="Apple-tab-span" style="white-space:pre"> </span>0 (0 per second)</div></div></div><div><br></div><div> </div><div><br></div><div>While this profile is flat, it does show where the VM is spending its time, and since the VM is not something with deep call chains, this view is the most useful I have.</div>
<div>The VMProfiler is part of the CogTools package at <a href="http://source.squeak.org/VMMaker">http://source.squeak.org/VMMaker</a>.</div><div><br></div><div>P.S. Extending the size of the DefaultTabsArray will result in a less cramped report.</div>
<div><br></div><div>HTH</div><div>Eliot</div></div>
</div></div>