[Vm-dev] Code Compilation | Performance regression in recent VMs

[Marcel Taeumel]

One more piece of information about "Morph compileAll" in my image:

CommitHash: 118a02c69 Plugins: 202107232247 (Jul 23)

44.4% {572ms} Morph class(Behavior)>>sourceCodeAt:
10.6% {136ms} Compiler>>compile:in:notifying:ifFail:
9.1% {117ms} Morph class(Behavior)>>basicAddSelector:withMethod:
8.2% {106ms} MethodNode>>generate:

CommitHash: 534349675 Plugins: 202108200036 (Aug 20)

93.0% {48312ms} Morph class(Behavior)>>basicAddSelector:withMethod:
   93.0% {48310ms} CompiledMethod>>methodClass:

Note that #methodClass: ends up in:

CompiledCode >> #literalAt:put:
CompiledCode >> #objectAt:put: (primitive 69)

Maybe the slow down in primitive 69 in this particular situation can give somebody a clue? Hmmm...

***

I captured the VM parameters but could not find anything suspicious:

report := [
FileStream forceNewFileNamed: (Time highResClock // Time highResClockTicksPerMillisecond) asString, '.txt'
do: [:stream | SystemReporter new reportVMParameters: stream]].

report value.
Morph compileAll.
report value.

See the attached logs to do a diff.

Best,
Marcel
Am 20.08.2021 12:21:53 schrieb Marcel Taeumel <marcel.taeumel at hpi.de>:
Hi all --

I found the culprit. The regression started with the introduction of FastCPrimitiveFlag in VMMaker.oscog-eem.2995. That new feature needs more adjustments, I suppose. :-)

My previous numbers were kind of wrong. I compared cog.spur against stack.spur. The latter being, in comparison, blazingly fast in #compileAll. Something is wrong with current cog.spur, at least on Windows (64-bit).

CommitHash: d8576b0 Plugins: 202108200011 


stack.pur
Morph methodDict size. " 1493 "
[Morph compileAll] timeToRun " 1293 "

cog.spur
Morph methodDict size. " 1493 "
[Morph compileAll] timeToRun " 23018 "

Here are more tests with cog.spur:

CommitHash: 128d14994 Plugins: 202105050056
cog.spur -- [Morph compileAll] timeToRun " 1294 "

CommitHash: 9d4e82529 Plugins: 202107121800

cog.spur -- [Morph compileAll] timeToRun " 910 "

CommitHash: c0d1a5574 Plugins: 202107211710 -- VMMaker.oscog-eem.2991

cog.spur -- [Morph compileAll] timeToRun " 901 "


CommitHash: 118a02c69 Plugins: 202107232247

cog.spur -- [Morph compileAll] timeToRun " 984 "

(BUILD BROKEN  -- VMMaker.oscog-eem.2995)
(VM CRASHES between VMMaker.oscog-eem.2996 and VMMaker.oscog-eem.3009)


CommitHash: 03c4ef31b Plugins: 202108010511 -- VMMaker.oscog-eem.3009

cog.spur -- [Morph compileAll] timeToRun " 20787 "


***

Note that #compileAll does not write into the .changes file.


Note that the last "good" commit hash is 118a02c69f3e4c8c29e8ba867a78bd39f9a53cb4 (still using VMMaker.oscog-eem.2991). I added the tag "last-before-FastCPrimitiveFlag" to this commit.

Now let's review and fix this. ^__^

Best,
Marcel

Am 19.08.2021 15:55:34 schrieb Marcel Taeumel <marcel.taeumel at hpi.de>:
[Morph compileAll] timeToRunWithoutGC

VM 202108160631 : 24607 milliseconds
VM 202108010511 : 1078 milliseconds

Best,
Marcel
Am 19.08.2021 15:40:03 schrieb Marcel Taeumel <marcel.taeumel at hpi.de>:
Hi all!

There is a serious performance regression in recent VM (202108160631) regarding code compilation. I could only narrow it down to CompiledMethod >> #methodClass:. Still investigating. The start-up is also very slow. Maybe GC-related?

This regression was not there in 202108010511.

Best,
Marcel
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.squeakfoundation.org/pipermail/vm-dev/attachments/20210820/fc5fc604/attachment-0001.html>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: FAST_373527935.txt
URL: <http://lists.squeakfoundation.org/pipermail/vm-dev/attachments/20210820/fc5fc604/attachment-0004.txt>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: FAST_373528923.txt
URL: <http://lists.squeakfoundation.org/pipermail/vm-dev/attachments/20210820/fc5fc604/attachment-0005.txt>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: SLOW_373304652.txt
URL: <http://lists.squeakfoundation.org/pipermail/vm-dev/attachments/20210820/fc5fc604/attachment-0006.txt>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: SLOW_373346954.txt
URL: <http://lists.squeakfoundation.org/pipermail/vm-dev/attachments/20210820/fc5fc604/attachment-0007.txt>