Skip to content

Instantly share code, notes, and snippets.

@TruffleSqueak-Bot

TruffleSqueak-Bot/c452863-1-summary.md

Created May 3, 2022 07:33
Show Gist options
  • Save TruffleSqueak-Bot/242814dc9fa8cffd210016209a61c4d0 to your computer and use it in GitHub Desktop.
Save TruffleSqueak-Bot/242814dc9fa8cffd210016209a61c4d0 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
c452863-1-summary.md

Steady (after 50 iterations)

Benchmark Name Min Geomean Median Mean Max Total (ms) Total (min)
Bounce 180 186 180.86 180 180.85 36171 0.6
DeltaBlue 298 618 416.28 420 413.91 83256 1.39
Havlak 1565 1654 1589.95 1589 1589.87 317989 5.3
Json 729 738 734 734 734 146800 2.45
List 901 1041 905.57 902 905.39 181113 3.02
Mandelbrot 145 153 145.34 145 145.34 29068 0.48
NBody 275 374 278.25 277 278.17 55649 0.93
Permute 231 247 238.16 239 238.13 47631 0.79
Queens 255 263 256.88 257 256.88 51376 0.86
Richards 1074 1085 1078.08 1078 1078.07 215615 3.59
Sieve 210 220 211.27 211 211.27 42254 0.7
Storage 272 286 275.2 275 275.18 55039 0.92
Towers 392 405 394.12 393 394.12 78824 1.31
6527 7270 6703.93 6700 6701.17 1340785 22.35
Benchmarks ran on graalvm-ce-java17-22.1.0. 
Runtime:   graalvm-ce-java17-22.1.0
System:    Host: swaarena Kernel: 4.9.0-18-amd64 x86_64 (64 bit) Console: tty
         Distro: Debian GNU/Linux 9 (stretch)
Machine:   Device: server System: Dell product: PowerEdge 2950
         Mobo: Dell model: 0H603H v: A05 BIOS: Dell v: 2.5.0 date: 09/12/2008
CPU(s):    2 Quad core Intel Xeon E5410s (-HT-MCP-SMP-) cache: 12288 KB 
         clock speeds: max: 2333 MHz 1: 2333 MHz 2: 2333 MHz 3: 2333 MHz 4: 2333 MHz 5: 2333 MHz
         6: 2333 MHz 7: 2333 MHz 8: 2333 MHz
Memory:    Used/Total: 464.0/32174.2MB
         Array-1 capacity: 63.75 GB devices: 8 EC: Multi-bit ECC
         Device-1: DIMM1 size: 4 GB speed: 667 MHz type: DDR2 FB-DIMM
         Device-2: DIMM2 size: 4 GB speed: 667 MHz type: DDR2 FB-DIMM
         Device-3: DIMM3 size: 4 GB speed: 667 MHz type: DDR2 FB-DIMM
         Device-4: DIMM4 size: 4 GB speed: 667 MHz type: DDR2 FB-DIMM
         Device-5: DIMM5 size: 4 GB speed: 667 MHz type: DDR2 FB-DIMM
         Device-6: DIMM6 size: 4 GB speed: 667 MHz type: DDR2 FB-DIMM
         Device-7: DIMM7 size: 4 GB speed: 667 MHz type: DDR2 FB-DIMM
         Device-8: DIMM8 size: 4 GB speed: 667 MHz type: DDR2 FB-DIMM
================================================================================
IMPLEMENTOR="GraalVM Community"
JAVA_VERSION="17.0.3"
JAVA_VERSION_DATE="2022-04-19"
LIBC="gnu"
MODULES="java.base java.compiler java.instrument java.logging java.management jdk.internal.vm.ci jdk.jfr jdk.unsupported org.graalvm.sdk java.datatransfer java.xml java.prefs java.desktop java.transaction.xa java.sql jdk.management org.graalvm.truffle jdk.internal.vm.compiler com.oracle.graal.graal_enterprise com.oracle.svm.svm_enterprise com.oracle.truffle.regex com.oracle.truffle.truffle_nfi com.oracle.truffle.truffle_nfi_libffi java.security.sasl java.naming java.rmi java.management.rmi java.net.http java.scripting java.security.jgss java.sql.rowset java.xml.crypto java.se java.smartcardio jdk.accessibility jdk.internal.jvmstat jdk.attach jdk.charsets jdk.compiler jdk.crypto.ec jdk.crypto.cryptoki jdk.dynalink jdk.internal.ed jdk.editpad jdk.hotspot.agent jdk.httpserver jdk.incubator.foreign jdk.incubator.vector jdk.internal.le jdk.internal.opt jdk.internal.vm.compiler.management jdk.internal.vm.compiler.truffle.jfr jdk.jartool jdk.javadoc jdk.jcmd jdk.management.agent jdk.jconsole jdk.jdeps jdk.jdwp.agent jdk.jdi jdk.jlink jdk.jpackage jdk.jshell jdk.jsobject jdk.jstatd jdk.localedata jdk.management.jfr jdk.naming.dns jdk.naming.rmi jdk.net jdk.nio.mapmode jdk.random jdk.sctp jdk.security.auth jdk.security.jgss jdk.unsupported.desktop jdk.xml.dom jdk.zipfs org.graalvm.js.scriptengine org.graalvm.locator org.graalvm.nativeimage.junitsupport"
OS_ARCH="x86_64"
OS_NAME="Linux"
SOURCE=".:git:05e32d91e144+ labsjdk-builder:2b1266064e5d9e0d42f93f35bf7064378ffe38e2 compiler:da6a62d607552fc958ccb63f4ca1d81e1817cadc graal-js:3489418d0408bfa1cc3fd5d77d9593b0eac6d3c8 java-benchmarks:da6a62d607552fc958ccb63f4ca1d81e1817cadc regex:da6a62d607552fc958ccb63f4ca1d81e1817cadc sdk:da6a62d607552fc958ccb63f4ca1d81e1817cadc substratevm:da6a62d607552fc958ccb63f4ca1d81e1817cadc sulong:da6a62d607552fc958ccb63f4ca1d81e1817cadc tools:da6a62d607552fc958ccb63f4ca1d81e1817cadc truffle:da6a62d607552fc958ccb63f4ca1d81e1817cadc vm:da6a62d607552fc958ccb63f4ca1d81e1817cadc"
GRAALVM_VERSION="22.1.0"
COMMIT_INFO={"compiler": {"commit.committer": "Gilles Duboscq <[email protected]>", "commit.committer-ts": 1650629140, "commit.rev": "da6a62d607552fc958ccb63f4ca1d81e1817cadc"}, "graal-js": {"commit.committer": "Gilles Duboscq <[email protected]>", "commit.committer-ts": 1649795667, "commit.rev": "3489418d0408bfa1cc3fd5d77d9593b0eac6d3c8"}, "java-benchmarks": {"commit.committer": "Gilles Duboscq <[email protected]>", "commit.committer-ts": 1650629140, "commit.rev": "da6a62d607552fc958ccb63f4ca1d81e1817cadc"}, "regex": {"commit.committer": "Gilles Duboscq <[email protected]>", "commit.committer-ts": 1650629140, "commit.rev": "da6a62d607552fc958ccb63f4ca1d81e1817cadc"}, "sdk": {"commit.committer": "Gilles Duboscq <[email protected]>", "commit.committer-ts": 1650629140, "commit.rev": "da6a62d607552fc958ccb63f4ca1d81e1817cadc"}, "substratevm": {"commit.committer": "Gilles Duboscq <[email protected]>", "commit.committer-ts": 1650629140, "commit.rev": "da6a62d607552fc958ccb63f4ca1d81e1817cadc"}, "sulong": {"commit.committer": "Gilles Duboscq <[email protected]>", "commit.committer-ts": 1650629140, "commit.rev": "da6a62d607552fc958ccb63f4ca1d81e1817cadc"}, "tools": {"commit.committer": "Gilles Duboscq <[email protected]>", "commit.committer-ts": 1650629140, "commit.rev": "da6a62d607552fc958ccb63f4ca1d81e1817cadc"}, "truffle": {"commit.committer": "Gilles Duboscq <[email protected]>", "commit.committer-ts": 1650629140, "commit.rev": "da6a62d607552fc958ccb63f4ca1d81e1817cadc"}, "vm": {"commit.committer": "Gilles Duboscq <[email protected]>", "commit.committer-ts": 1650629140, "commit.rev": "da6a62d607552fc958ccb63f4ca1d81e1817cadc"}}
component_catalog="https://www.graalvm.org/component-catalog/v2/graal-updater-component-catalog-java17.properties|{ee=GraalVM Enterprise Edition}rest://gds.oracle.com/api/20220101/|gds://oca.opensource.oracle.com/gds/meta-data.json"
GDS_PRODUCT_ID="D53FAE8052773FFAE0530F15000AA6C6"
Display the source blob
Display the rendered blob
Raw
c452863-2-steady.svg
Loading
Sorry, something went wrong. Reload?
Sorry, we cannot display this file.
Sorry, this file is invalid so it cannot be displayed.
Display the source blob
Display the rendered blob
Raw
c452863-3-warmup.svg
Loading
Sorry, something went wrong. Reload?
Sorry, we cannot display this file.
Sorry, this file is invalid so it cannot be displayed.
Raw
c4528635-Bounce.trace.log
# Bounce (iterations: 250, problem size: 1500) on Tue May 3 07:21:23 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Bounce.trace.log" --quiet --code "AWFYHarness run: #('Bounce' 250 1500)"`
[engine] opt done id=667 AWFYBall>>bounce |Tier 2|Time 552( 487+64 )ms|AST 206|Inlined 8Y 0N|IR 626/ 693|CodeSize 1995|Timestamp 2406834090312766|Src n/a
[engine] opt done id=666 [] in AWFYBounce>>benchmark |Tier 2|Time 602( 533+69 )ms|AST 35|Inlined 9Y 0N|IR 762/ 943|CodeSize 2987|Timestamp 2406834126264395|Src n/a
[engine] opt done id=183 Number>>negated |Tier 2|Time 70( 66+4 )ms|AST 13|Inlined 0Y 0N|IR 24/ 96|CodeSize 363|Timestamp 2406834199540871|Src n/a
[engine] opt done id=668 Number>>abs |Tier 2|Time 111( 105+6 )ms|AST 28|Inlined 1Y 0N|IR 65/ 177|CodeSize 545|Timestamp 2406834210906854|Src n/a
[engine] opt done id=665 AWFYSomRandom>>next |Tier 2|Time 92( 84+8 )ms|AST 33|Inlined 0Y 0N|IR 102/ 169|CodeSize 507|Timestamp 2406834293625997|Src n/a
[engine] opt done id=669 SequenceableCollection>>do: <split-669> |Tier 2|Time 867( 610+257 )ms|AST 72|Inlined 10Y 0N|IR 939/ 3189|CodeSize 11241|Timestamp 2406834394876360|Src n/a
[engine] opt done id=663 Behavior>>new <split-663> |Tier 2|Time 112( 102+10 )ms|AST 25|Inlined 0Y 0N|IR 34/ 199|CodeSize 700|Timestamp 2406834510641379|Src n/a
[engine] opt done id=662 AWFYBall class>>new: |Tier 2|Time 379( 329+50 )ms|AST 30|Inlined 6Y 0N|IR 394/ 408|CodeSize 1175|Timestamp 2406834674552927|Src n/a
[engine] opt done id=661 AWFYSomRandom>>initialize |Tier 2|Time 40( 36+4 )ms|AST 9|Inlined 0Y 0N|IR 73/ 84|CodeSize 214|Timestamp 2406834900415759|Src n/a
[engine] opt done id=660 Behavior>>new <split-660> |Tier 2|Time 115( 110+5 )ms|AST 27|Inlined 1Y 0N|IR 34/ 110|CodeSize 414|Timestamp 2406835309076869|Src n/a
[engine] opt done id=659 AWFYSomRandom class>>new |Tier 2|Time 134( 129+5 )ms|AST 25|Inlined 3Y 0N|IR 34/ 110|CodeSize 414|Timestamp 2406835326081142|Src n/a
[engine] opt done id=670 AWFYBounce>>verifyResult: |Tier 2|Time 48( 45+3 )ms|AST 14|Inlined 0Y 0N|IR 25/ 34|CodeSize 158|Timestamp 2406835373219602|Src n/a
[engine] opt done id=658 AWFYBounce>>benchmark |Tier 2|Time 1218( 922+296 )ms|AST 162|Inlined 22Y 0N|IR 1877/ 5003|CodeSize 21545|Timestamp 2406835431321948|Src n/a
[engine] opt done id=657 AWFYBenchmark>>innerBenchmarkLoop: |Tier 2|Time 1079( 698+381 )ms|AST 58|Inlined 24Y 0N|IR 1970/ 5115|CodeSize 21369|Timestamp 2406836769499622|Src n/a
[engine] opt done id=675 SmallInteger>>printString |Tier 2|Time 286( 268+18 )ms|AST 149|Inlined 4Y 1N|IR 274/ 382|CodeSize 1166|Timestamp 2406862140401253|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 136( 126+9 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1107|Timestamp 2406877394398844|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 18
Success : 16
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 2
Invalidated : 0
Queues : 18
Dequeues : 1
Target inlined into only caller : 1
Splits : 176
Compilation Accuracy : 1.000000
Queue Accuracy : 0.944444
Compilation Utilization : 0.123689
Remaining Compilation Queue : 0
Time to queue : count= 18, sum= 128321, min= 35, average= 7128.99, max= 45612 (milliseconds), maxTarget=SmallInteger>>printString
Time waiting in queue : count= 18, sum= 2388, min= 0, average= 132.68, max= 513 (milliseconds), maxTarget=Number>>abs
Time for compilation : count= 16, sum= 5892, min= 41, average= 368.30, max= 1219 (milliseconds), maxTarget=AWFYBounce>>benchmark
Truffle Tier : count= 16, sum= 4670, min= 36, average= 291.89, max= 922 (milliseconds), maxTarget=AWFYBounce>>benchmark
Graal Tier : count= 16, sum= 787, min= 2, average= 49.20, max= 269 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Code Installation : count= 16, sum= 435, min= 1, average= 27.21, max= 113 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle node count : count= 16, sum= 7137, min= 17, average= 446.06, max= 1751, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Trivial : count= 16, sum= 2815, min= 8, average= 175.94, max= 682, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Non Trivial : count= 16, sum= 4322, min= 9, average= 270.13, max= 1069, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Monomorphic : count= 16, sum= 4318, min= 9, average= 269.88, max= 1067, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Polymorphic : count= 16, sum= 4, min= 0, average= 0.25, max= 2, maxTarget=AWFYBounce>>benchmark
Megamorphic : count= 16, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYBall>>bounce
Truffle call count : count= 16, sum= 92, min= 0, average= 5.75, max= 24, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Indirect : count= 16, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYBall>>bounce
Direct : count= 16, sum= 92, min= 0, average= 5.75, max= 24, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Dispatched : count= 16, sum= 2, min= 0, average= 0.13, max= 1, maxTarget=SmallInteger>>printString
Inlined : count= 16, sum= 90, min= 0, average= 5.63, max= 24, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
---------- :
Cloned : count= 16, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYBall>>bounce
Not Cloned : count= 16, sum= 92, min= 0, average= 5.75, max= 24, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle loops : count= 16, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYBall>>bounce
Graal node count :
After Truffle Tier : count= 16, sum= 7338, min= 24, average= 458.63, max= 1970, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
After Graal Tier : count= 16, sum= 17041, min= 34, average= 1065.06, max= 5115, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Graal compilation result :
Code size : count= 16, sum= 65900, min= 158, average= 4118.75, max= 21545, maxTarget=AWFYBounce>>benchmark
Total frame size : count= 16, sum= 1808, min= 32, average= 113.00, max= 528, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Exception handlers : count= 16, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYBall>>bounce
Infopoints : count= 16, sum= 690, min= 4, average= 43.13, max= 189, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
CALL : count= 16, sum= 563, min= 4, average= 35.19, max= 153, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
IMPLICIT_EXCEPTION : count= 16, sum= 122, min= 0, average= 7.63, max= 33, maxTarget=AWFYBounce>>benchmark
SAFEPOINT : count= 16, sum= 5, min= 0, average= 0.31, max= 3, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Marks : count= 16, sum= 101, min= 6, average= 6.31, max= 9, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Data references : count= 16, sum= 445, min= 2, average= 27.81, max= 127, maxTarget=AWFYBounce>>benchmark
Raw
c4528635-DeltaBlue.trace.log
# DeltaBlue (iterations: 250, problem size: 12000) on Tue May 3 07:09:47 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/DeltaBlue.trace.log" --quiet --code "AWFYHarness run: #('DeltaBlue' 250 12000)"`
[engine] opt done id=675 Behavior>>new <split-675> |Tier 2|Time 242( 227+15 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2406137284621929|Src n/a
[engine] opt done id=676 AWFYVector>>initialize: |Tier 2|Time 236( 205+31 )ms|AST 27|Inlined 0Y 0N|IR 148/ 337|CodeSize 914|Timestamp 2406137284621929|Src n/a
[engine] opt done id=674 AWFYVector class>>new: |Tier 2|Time 279( 270+9 )ms|AST 28|Inlined 2Y 0N|IR 53/ 292|CodeSize 956|Timestamp 2406137316401298|Src n/a
[engine] opt done id=700 AWFYStrength class>>absoluteWeakest |Tier 2|Time 68( 66+2 )ms|AST 9|Inlined 0Y 0N|IR 21/ 29|CodeSize 175|Timestamp 2406137363191216|Src n/a
[engine] opt done id=721 AWFYBinaryConstraint>>output |Tier 2|Time 77( 72+5 )ms|AST 19|Inlined 0Y 0N|IR 45/ 77|CodeSize 347|Timestamp 2406137658861790|Src n/a
[engine] opt done id=725 AWFYVector>>isEmpty |Tier 2|Time 67( 64+4 )ms|AST 17|Inlined 0Y 0N|IR 39/ 54|CodeSize 221|Timestamp 2406137663530843|Src n/a
[engine] opt done id=720 AWFYVariable>>mark: |Tier 2|Time 56( 51+5 )ms|AST 10|Inlined 0Y 0N|IR 78/ 95|CodeSize 241|Timestamp 2406137721294562|Src n/a
[engine] opt done id=714 AWFYStrength>>weaker: |Tier 2|Time 83( 79+4 )ms|AST 26|Inlined 0Y 0N|IR 47/ 70|CodeSize 256|Timestamp 2406137744074643|Src n/a
[engine] opt done id=678 AWFYVector>>append: |Tier 2|Time 217( 169+49 )ms|AST 59|Inlined 0Y 0N|IR 284/ 795|CodeSize 2295|Timestamp 2406137799613037|Src n/a
[engine] opt done id=709 AWFYVariable>>addConstraint: |Tier 2|Time 293( 236+57 )ms|AST 23|Inlined 1Y 0N|IR 294/ 872|CodeSize 2591|Timestamp 2406138016459181|Src n/a
[engine] opt done id=737 AWFYVector>>forEach: <split-737> |Tier 2|Time 309( 249+60 )ms|AST 78|Inlined 1Y 0N|IR 215/ 961|CodeSize 3316|Timestamp 2406138111087317|Src n/a
[engine] opt done id=667 AWFYSomDictionary>>bucketIdx: |Tier 2|Time 122( 112+9 )ms|AST 34|Inlined 0Y 0N|IR 109/ 246|CodeSize 797|Timestamp 2406138146080244|Src n/a
[engine] opt done id=666 Integer>>>> |Tier 2|Time 70( 66+5 )ms|AST 30|Inlined 0Y 0N|IR 40/ 120|CodeSize 435|Timestamp 2406138218614036|Src n/a
[engine] opt done id=665 AWFYSomDictionary>>hash: |Tier 2|Time 131( 126+5 )ms|AST 59|Inlined 1Y 0N|IR 33/ 111|CodeSize 396|Timestamp 2406138245489884|Src n/a
[engine] opt done id=687 AWFYDictIdEntry>>match:key: |Tier 2|Time 102( 98+4 )ms|AST 28|Inlined 0Y 0N|IR 51/ 96|CodeSize 359|Timestamp 2406138350267024|Src n/a
[engine] opt done id=686 AWFYSomDictionary>>bucket: |Tier 2|Time 149( 142+7 )ms|AST 32|Inlined 1Y 0N|IR 162/ 138|CodeSize 561|Timestamp 2406138501741119|Src n/a
[engine] opt done id=685 AWFYSomDictionary>>at: |Tier 2|Time 315( 305+10 )ms|AST 85|Inlined 5Y 0N|IR 244/ 230|CodeSize 837|Timestamp 2406138536278868|Src n/a
[engine] opt done id=701 AWFYStrength class>>SymRequired |Tier 2|Time 38( 36+3 )ms|AST 9|Inlined 0Y 0N|IR 21/ 29|CodeSize 175|Timestamp 2406138577247923|Src n/a
[engine] opt deopt id=737 AWFYVector>>forEach: <split-737> |Timestamp 2406138622459070|Src n/a
[engine] opt inval. id=737 AWFYVector>>forEach: <split-737> |Timestamp 2406138630893035|Src n/a|Reason validRootAssumption Split call node
[engine] opt done id=688 AWFYStrength class>>of: |Tier 2|Time 337( 295+41 )ms|AST 22|Inlined 6Y 0N|IR 292/ 246|CodeSize 909|Timestamp 2406138854439457|Src n/a
[engine] opt done id=721 AWFYBinaryConstraint>>output |Tier 2|Time 79( 73+6 )ms|AST 19|Inlined 0Y 0N|IR 78/ 125|CodeSize 439|Timestamp 2406138936513765|Src n/a
[engine] opt done id=737 AWFYVector>>forEach: <split-737> |Tier 2|Time 279( 234+46 )ms|AST 78|Inlined 2Y 0N|IR 260/ 1753|CodeSize 6275|Timestamp 2406138966258557|Src n/a
[engine] opt done id=722 AWFYVariable>>determinedBy: |Tier 2|Time 37( 32+4 )ms|AST 10|Inlined 0Y 0N|IR 61/ 83|CodeSize 281|Timestamp 2406138974981120|Src n/a
[engine] opt done id=730 AWFYVariable>>walkStrength: |Tier 2|Time 57( 53+5 )ms|AST 10|Inlined 0Y 0N|IR 66/ 174|CodeSize 415|Timestamp 2406139034116520|Src n/a
[engine] opt done id=715 AWFYStrength>>stronger: |Tier 2|Time 83( 79+4 )ms|AST 26|Inlined 0Y 0N|IR 47/ 70|CodeSize 256|Timestamp 2406139051802822|Src n/a
[engine] opt done id=713 AWFYBinaryConstraint>>chooseMethod: |Tier 2|Time 280( 199+81 )ms|AST 240|Inlined 3Y 0N|IR 351/ 775|CodeSize 2513|Timestamp 2406139316370194|Src n/a
[engine] opt done id=724 AWFYVector class>>with: |Tier 2|Time 289( 280+9 )ms|AST 42|Inlined 4Y 0N|IR 150/ 309|CodeSize 1022|Timestamp 2406139343157619|Src n/a
[engine] opt done id=735 AWFYPlanner>>addConstraintsConsuming:to: |Tier 2|Time 263( 214+49 )ms|AST 56|Inlined 3Y 0N|IR 349/ 618|CodeSize 2117|Timestamp 2406139581737150|Src n/a
[engine] opt done id=713 AWFYBinaryConstraint>>chooseMethod: |Tier 2|Time 276( 245+31 )ms|AST 240|Inlined 4Y 0N|IR 426/ 954|CodeSize 3088|Timestamp 2406139621183659|Src n/a
[engine] opt deopt id=737 AWFYVector>>forEach: <split-737> |Timestamp 2406139631168038|Src n/a
[engine] opt deopt id=735 AWFYPlanner>>addConstraintsConsuming:to: |Timestamp 2406139631807397|Src n/a
[engine] opt inval. id=735 AWFYPlanner>>addConstraintsConsuming:to: |Timestamp 2406139634961866|Src n/a|Reason validRootAssumption Split call node
[engine] opt inval. id=737 AWFYVector>>forEach: <split-737> |Timestamp 2406139635597873|Src n/a|Reason validRootAssumption Split call node
[engine] opt deopt id=737 AWFYVector>>forEach: <split-737> |Timestamp 2406139636254204|Src n/a
[engine] opt done id=731 AWFYVariable>>stay: |Tier 2|Time 112( 41+71 )ms|AST 10|Inlined 0Y 0N|IR 81/ 98|CodeSize 243|Timestamp 2406139736156599|Src n/a
[engine] opt done id=726 AWFYVector>>removeFirst |Tier 2|Time 214( 205+9 )ms|AST 52|Inlined 1Y 0N|IR 125/ 192|CodeSize 641|Timestamp 2406139798143621|Src n/a
[engine] opt done id=737 AWFYVector>>forEach: <split-737> |Tier 2|Time 637( 466+170 )ms|AST 78|Inlined 3Y 0N|IR 948/ 2869|CodeSize 11626|Timestamp 2406140437123792|Src n/a
[engine] opt done id=735 AWFYPlanner>>addConstraintsConsuming:to: |Tier 2|Time 709( 515+194 )ms|AST 56|Inlined 4Y 0N|IR 1018/ 2345|CodeSize 9378|Timestamp 2406140447148681|Src n/a
[engine] opt done id=734 AWFYVariable>>value: |Tier 2|Time 41( 37+4 )ms|AST 10|Inlined 0Y 0N|IR 79/ 95|CodeSize 241|Timestamp 2406140491207669|Src n/a
[engine] opt done id=702 AWFYEqualityConstraint class>>var:var:strength:addTo: |Tier 2|Time 2054(2047+7 )ms|AST 39|Inlined 57Y 4N|IR 518/ 5|CodeSize 88|Timestamp 2406140633632466|Src n/a
[engine] opt done id=732 AWFYEqualityConstraint>>execute |Tier 2|Time 171( 162+9 )ms|AST 79|Inlined 3Y 0N|IR 290/ 204|CodeSize 646|Timestamp 2406140663653424|Src n/a
[engine] opt done id=733 Symbol>>= <split-733> |Tier 2|Time 108( 104+4 )ms|AST 27|Inlined 0Y 0N|IR 64/ 91|CodeSize 267|Timestamp 2406140749408900|Src n/a
[engine] opt done id=678 AWFYVector>>append: |Tier 2|Time 333( 212+121 )ms|AST 59|Inlined 0Y 0N|IR 776/ 2132|CodeSize 8832|Timestamp 2406140773137333|Src n/a
[engine] opt done id=780 [] in AWFYPlan>>execute |Tier 2|Time 200( 185+14 )ms|AST 19|Inlined 4Y 0N|IR 373/ 324|CodeSize 982|Timestamp 2406140865664539|Src n/a
[engine] opt done id=718 Symbol>>= <split-718> |Tier 2|Time 109( 105+4 )ms|AST 27|Inlined 0Y 0N|IR 64/ 91|CodeSize 267|Timestamp 2406140976815434|Src n/a
[engine] opt done id=717 AWFYBinaryConstraint>>inputsDo: |Tier 2|Time 231( 193+38 )ms|AST 59|Inlined 5Y 0N|IR 432/ 1601|CodeSize 5172|Timestamp 2406141006675958|Src n/a
[engine] opt done id=719 [] in AWFYAbstractConstraint>>satisfy:propagate: |Tier 2|Time 79( 73+5 )ms|AST 20|Inlined 1Y 0N|IR 117/ 134|CodeSize 249|Timestamp 2406141057090121|Src n/a
[engine] opt done id=779 AWFYVector>>forEach: <split-779> |Tier 2|Time 327( 251+76 )ms|AST 78|Inlined 5Y 0N|IR 570/ 2139|CodeSize 7899|Timestamp 2406141077899951|Src n/a
[engine] opt done id=728 Symbol>>= <split-728> |Tier 2|Time 81( 77+4 )ms|AST 27|Inlined 0Y 0N|IR 64/ 91|CodeSize 267|Timestamp 2406141139917356|Src n/a
[engine] opt done id=729 AWFYStrength>>weakest: |Tier 2|Time 105( 101+4 )ms|AST 24|Inlined 1Y 0N|IR 41/ 65|CodeSize 243|Timestamp 2406141185031279|Src n/a
[engine] opt inval. id=722 AWFYVariable>>determinedBy: |Timestamp 2406141189167766|Src n/a|Reason Profiled Argument Types
[engine] opt deopt id=678 AWFYVector>>append: |Timestamp 2406141191291955|Src n/a
[engine] opt inval. id=725 AWFYVector>>isEmpty |Timestamp 2406141191700058|Src n/a|Reason Profiled Argument Types
[engine] opt inval. id=726 AWFYVector>>removeFirst |Timestamp 2406141192289198|Src n/a|Reason Profiled Argument Types
[engine] opt done id=746 AWFYBinaryConstraint>>markUnsatisfied |Tier 2|Time 40( 35+5 )ms|AST 9|Inlined 0Y 0N|IR 66/ 174|CodeSize 438|Timestamp 2406141226576484|Src n/a
[engine] opt done id=727 AWFYBinaryConstraint>>recalculate |Tier 2|Time 293( 273+21 )ms|AST 146|Inlined 9Y 0N|IR 621/ 607|CodeSize 1679|Timestamp 2406141302523240|Src n/a
[engine] opt done id=726 AWFYVector>>removeFirst |Tier 2|Time 152( 144+8 )ms|AST 52|Inlined 1Y 0N|IR 125/ 192|CodeSize 641|Timestamp 2406141457096837|Src n/a
[engine] opt done id=722 AWFYVariable>>determinedBy: |Tier 2|Time 37( 32+5 )ms|AST 10|Inlined 0Y 0N|IR 61/ 102|CodeSize 370|Timestamp 2406141495394051|Src n/a
[engine] opt done id=678 AWFYVector>>append: |Tier 2|Time 298( 222+75 )ms|AST 59|Inlined 0Y 0N|IR 776/ 2272|CodeSize 9521|Timestamp 2406141526161020|Src n/a
[engine] opt done id=725 AWFYVector>>isEmpty |Tier 2|Time 66( 63+3 )ms|AST 17|Inlined 0Y 0N|IR 39/ 54|CodeSize 221|Timestamp 2406141562697587|Src n/a
[engine] opt done id=676 AWFYVector>>initialize: |Tier 2|Time 86( 75+11 )ms|AST 27|Inlined 0Y 0N|IR 148/ 337|CodeSize 914|Timestamp 2406141649825303|Src n/a
[engine] opt done id=674 AWFYVector class>>new: |Tier 2|Time 160( 144+17 )ms|AST 28|Inlined 2Y 0N|IR 140/ 396|CodeSize 1110|Timestamp 2406141690206056|Src n/a
[engine] opt done id=675 Behavior>>new <split-675> |Tier 2|Time 120( 113+7 )ms|AST 25|Inlined 0Y 0N|IR 86/ 169|CodeSize 521|Timestamp 2406141771538054|Src n/a
[engine] opt deopt id=678 AWFYVector>>append: |Timestamp 2406141932122072|Src n/a
[engine] opt deopt id=709 AWFYVariable>>addConstraint: |Timestamp 2406141932643603|Src n/a
[engine] opt done id=790 AWFYVector>>forEach: <split-790> |Tier 2|Time 558( 371+187 )ms|AST 78|Inlined 3Y 0N|IR 1008/ 2766|CodeSize 12503|Timestamp 2406142250508262|Src n/a
[engine] opt done id=750 AWFYPlanner>>addPropagate:mark: <split-750> |Tier 2|Time 1455( 943+512 )ms|AST 128|Inlined 25Y 0N|IR 2296/ 3827|CodeSize 14561|Timestamp 2406142596472518|Src n/a
[engine] opt done id=713 AWFYBinaryConstraint>>chooseMethod: |Tier 2|Time 350( 316+34 )ms|AST 240|Inlined 4Y 0N|IR 576/ 1140|CodeSize 3935|Timestamp 2406142605032623|Src n/a
[engine] opt done id=794 AWFYVector>>forEach: <split-794> |Tier 2|Time 931( 660+271 )ms|AST 78|Inlined 15Y 0N|IR 1861/ 4373|CodeSize 17158|Timestamp 2406142704203534|Src n/a
[engine] opt done id=721 AWFYBinaryConstraint>>output |Tier 2|Time 81( 74+7 )ms|AST 19|Inlined 0Y 0N|IR 109/ 159|CodeSize 535|Timestamp 2406142788990263|Src n/a
[engine] opt done id=699 AWFYVariable>>initialize |Tier 2|Time 203( 181+22 )ms|AST 51|Inlined 4Y 0N|IR 295/ 686|CodeSize 1709|Timestamp 2406142803541932|Src n/a
[engine] opt done id=709 AWFYVariable>>addConstraint: |Tier 2|Time 327( 230+98 )ms|AST 23|Inlined 1Y 0N|IR 740/ 1896|CodeSize 7656|Timestamp 2406142934775852|Src n/a
[engine] opt done id=698 Behavior>>new <split-698> |Tier 2|Time 266( 192+74 )ms|AST 27|Inlined 5Y 0N|IR 257/ 574|CodeSize 1363|Timestamp 2406143071648758|Src n/a
[engine] opt deopt id=780 [] in AWFYPlan>>execute |Timestamp 2406143119460296|Src n/a
[engine] opt deopt id=779 AWFYVector>>forEach: <split-779> |Timestamp 2406143119998799|Src n/a
[engine] opt deopt id=790 AWFYVector>>forEach: <split-790> |Timestamp 2406143121595381|Src n/a
[engine] opt deopt id=794 AWFYVector>>forEach: <split-794> |Timestamp 2406143122352219|Src n/a
[engine] opt deopt id=713 AWFYBinaryConstraint>>chooseMethod: |Timestamp 2406143125580514|Src n/a
[engine] opt deopt id=721 AWFYBinaryConstraint>>output |Timestamp 2406143126774371|Src n/a
[engine] opt done id=711 AWFYPlanner>>newMark |Tier 2|Time 57( 50+7 )ms|AST 18|Inlined 0Y 0N|IR 87/ 161|CodeSize 476|Timestamp 2406143131257706|Src n/a
[engine] opt done id=697 AWFYVariable class>>new |Tier 2|Time 395( 318+76 )ms|AST 25|Inlined 11Y 0N|IR 534/ 1177|CodeSize 3119|Timestamp 2406143185566274|Src n/a
[engine] opt done id=815 AWFYVector>>forEach: <split-815> |Tier 2|Time 259( 196+63 )ms|AST 78|Inlined 2Y 0N|IR 260/ 1753|CodeSize 6260|Timestamp 2406143196413306|Src n/a
[engine] opt done id=721 AWFYBinaryConstraint>>output |Tier 2|Time 61( 54+7 )ms|AST 19|Inlined 0Y 0N|IR 115/ 163|CodeSize 542|Timestamp 2406143249594999|Src n/a
[engine] opt done id=713 AWFYBinaryConstraint>>chooseMethod: |Tier 2|Time 308( 267+42 )ms|AST 240|Inlined 4Y 0N|IR 702/ 1431|CodeSize 4998|Timestamp 2406143441250650|Src n/a
[engine] opt done id=746 AWFYBinaryConstraint>>markUnsatisfied |Tier 2|Time 41( 35+6 )ms|AST 9|Inlined 0Y 0N|IR 85/ 259|CodeSize 708|Timestamp 2406143483896818|Src n/a
[engine] opt done id=674 AWFYVector class>>new: |Tier 2|Time 212( 186+26 )ms|AST 28|Inlined 2Y 0N|IR 287/ 573|CodeSize 1726|Timestamp 2406143696979098|Src n/a
[engine] opt done id=790 AWFYVector>>forEach: <split-790> |Tier 2|Time 521( 351+170 )ms|AST 78|Inlined 3Y 0N|IR 1086/ 2826|CodeSize 12360|Timestamp 2406143719640373|Src n/a
[engine] opt done id=676 AWFYVector>>initialize: |Tier 2|Time 109( 93+16 )ms|AST 27|Inlined 0Y 0N|IR 214/ 528|CodeSize 1630|Timestamp 2406143808050719|Src n/a
[engine] opt done id=675 Behavior>>new <split-675> |Tier 2|Time 100( 90+10 )ms|AST 25|Inlined 0Y 0N|IR 135/ 227|CodeSize 733|Timestamp 2406143821463010|Src n/a
[engine] opt done id=839 Symbol>>= <split-839> |Tier 2|Time 63( 59+4 )ms|AST 27|Inlined 0Y 0N|IR 64/ 91|CodeSize 270|Timestamp 2406143885783337|Src n/a
[engine] opt done id=838 AWFYScaleConstraint>>execute |Tier 2|Time 197( 183+15 )ms|AST 151|Inlined 3Y 0N|IR 399/ 446|CodeSize 1485|Timestamp 2406144007069057|Src n/a
[engine] opt done id=853 [] in AWFYPlan>>execute <split-853> |Tier 2|Time 306( 284+22 )ms|AST 19|Inlined 4Y 0N|IR 484/ 565|CodeSize 1853|Timestamp 2406144193550049|Src n/a
[engine] opt done id=852 AWFYVector>>forEach: <split-852> |Tier 2|Time 471( 357+114 )ms|AST 78|Inlined 5Y 0N|IR 679/ 2581|CodeSize 10817|Timestamp 2406144479734867|Src n/a
[engine] opt done id=794 AWFYVector>>forEach: <split-794> |Tier 2|Time 1278( 875+403 )ms|AST 78|Inlined 25Y 0N|IR 2767/ 5370|CodeSize 21303|Timestamp 2406144529347631|Src n/a
[engine] opt done id=846 AWFYVector>>forEach: <split-846> |Tier 2|Time 547( 333+214 )ms|AST 78|Inlined 3Y 0N|IR 1063/ 2983|CodeSize 12156|Timestamp 2406144742931816|Src n/a
[engine] opt inval. id=702 AWFYEqualityConstraint class>>var:var:strength:addTo: |Timestamp 2406144893839052|Src n/a|Reason validRootAssumption Split call node
[engine] opt done id=836 AWFYScaleConstraint>>recalculate |Tier 2|Time 406( 375+31 )ms|AST 180|Inlined 9Y 0N|IR 773/ 1006|CodeSize 2965|Timestamp 2406144939325038|Src n/a
[engine] opt done id=795 [] in AWFYPlanner>>constraintsConsuming:do: |Tier 2|Time 1107( 855+252 )ms|AST 61|Inlined 24Y 0N|IR 2514/ 4274|CodeSize 17036|Timestamp 2406145588980496|Src n/a
[engine] opt deopt id=846 AWFYVector>>forEach: <split-846> |Timestamp 2406145722618962|Src n/a
[engine] opt done id=787 AWFYVector>>forEach: <split-787> |Tier 2|Time 343( 257+86 )ms|AST 78|Inlined 1Y 0N|IR 408/ 1980|CodeSize 7794|Timestamp 2406145935397976|Src n/a
[engine] opt done id=769 AWFYPlanner>>makePlan: |Tier 2|Time 1823(1150+673 )ms|AST 209|Inlined 24Y 0N|IR 2884/ 5600|CodeSize 26224|Timestamp 2406146568194374|Src n/a
[engine] opt done id=846 AWFYVector>>forEach: <split-846> |Tier 2|Time 638( 455+183 )ms|AST 78|Inlined 3Y 0N|IR 1140/ 3043|CodeSize 12195|Timestamp 2406146574764322|Src n/a
[engine] opt done id=943 [] in AWFYPlan>>execute <split-943> |Tier 2|Time 200( 162+38 )ms|AST 19|Inlined 4Y 0N|IR 373/ 324|CodeSize 982|Timestamp 2406146772645517|Src n/a
[engine] opt done id=942 AWFYVector>>forEach: <split-942> |Tier 2|Time 357( 246+111 )ms|AST 78|Inlined 5Y 0N|IR 570/ 2139|CodeSize 7886|Timestamp 2406146933953058|Src n/a
[engine] opt done id=847 [] in AWFYPlanner>>addConstraintsConsuming:to: <split-847> |Tier 2|Time 447( 349+98 )ms|AST 60|Inlined 2Y 0N|IR 915/ 1952|CodeSize 8152|Timestamp 2406147221167669|Src n/a
[engine] opt done id=706 AWFYAbstractConstraint>>initialize: |Tier 2|Time 359( 343+16 )ms|AST 22|Inlined 7Y 0N|IR 387/ 679|CodeSize 1932|Timestamp 2406147294716166|Src n/a
[engine] opt done id=702 AWFYEqualityConstraint class>>var:var:strength:addTo: |Tier 2|Time 3169(2007+1162)ms|AST 39|Inlined 59Y 0N|IR 4848/ 7765|CodeSize 30122|Timestamp 2406148111312286|Src n/a
[engine] opt done id=819 AWFYVariable class>>value: |Tier 2|Time 551( 478+73 )ms|AST 40|Inlined 13Y 0N|IR 640/ 1262|CodeSize 3159|Timestamp 2406148670039705|Src n/a
[engine] opt done id=793 AWFYPlanner>>constraintsConsuming:do: |Tier 2|Time 1520( 982+538 )ms|AST 56|Inlined 26Y 0N|IR 2847/ 4850|CodeSize 18354|Timestamp 2406148816544136|Src n/a
[engine] opt deopt id=846 AWFYVector>>forEach: <split-846> |Timestamp 2406149084725698|Src n/a
[engine] opt deopt id=845 AWFYPlanner>>addConstraintsConsuming:to: <split-845> |Timestamp 2406149085248277|Src n/a
[engine] opt done id=919 AWFYVector>>forEach: <split-919> |Tier 2|Time 273( 210+62 )ms|AST 78|Inlined 2Y 0N|IR 260/ 1753|CodeSize 6260|Timestamp 2406149093315138|Src n/a
[engine] opt deopt id=769 AWFYPlanner>>makePlan: |Timestamp 2406149246216023|Src n/a
[engine] opt done id=938 AWFYVector>>forEach: <split-938> |Tier 2|Time 350( 211+138 )ms|AST 78|Inlined 2Y 0N|IR 339/ 1915|CodeSize 6911|Timestamp 2406149444757950|Src n/a
[engine] opt done id=771 AWFYAbstractConstraint>>inputsKnown: |Tier 2|Time 284( 266+18 )ms|AST 36|Inlined 5Y 0N|IR 379/ 487|CodeSize 1431|Timestamp 2406149730793512|Src n/a
[engine] opt done id=960 AWFYVector>>forEach: <split-960> |Tier 2|Time 240( 194+46 )ms|AST 78|Inlined 2Y 0N|IR 260/ 1753|CodeSize 6260|Timestamp 2406149972980597|Src n/a
[engine] opt done id=789 AWFYPlanner>>removePropagateFrom: |Tier 2|Time 3324(1884+1440)ms|AST 204|Inlined 50Y 0N|IR 5831/ 12779|CodeSize 50504|Timestamp 2406150546942278|Src n/a
[engine] opt done id=769 AWFYPlanner>>makePlan: |Tier 2|Time 1939(1199+740 )ms|AST 209|Inlined 24Y 0N|IR 2958/ 5657|CodeSize 26481|Timestamp 2406152492227842|Src n/a
[engine] opt done id=841 AWFYVector>>forEach: <split-841> |Tier 2|Time 173( 151+23 )ms|AST 78|Inlined 1Y 0N|IR 215/ 961|CodeSize 3316|Timestamp 2406152591023478|Src n/a
[engine] opt done id=845 AWFYPlanner>>addConstraintsConsuming:to: <split-845> |Tier 2|Time 788( 544+244 )ms|AST 56|Inlined 4Y 0N|IR 1210/ 2519|CodeSize 9754|Timestamp 2406153381236858|Src n/a
[engine] opt done id=835 AWFYPlanner>>addPropagate:mark: <split-835> |Tier 2|Time 1100( 948+151 )ms|AST 128|Inlined 23Y 0N|IR 1564/ 1931|CodeSize 5761|Timestamp 2406153596395066|Src n/a
[engine] opt done id=994 AWFYVector>>forEach: <split-994> |Tier 2|Time 515( 350+165 )ms|AST 78|Inlined 3Y 0N|IR 949/ 2869|CodeSize 11707|Timestamp 2406153898504215|Src n/a
[engine] opt done id=1010 AWFYVector>>forEach: <split-1010> |Tier 2|Time 499( 311+188 )ms|AST 78|Inlined 3Y 0N|IR 949/ 2869|CodeSize 11707|Timestamp 2406154099605744|Src n/a
[engine] opt done id=693 AWFYPlanner class>>chainTest: |Tier 2|Time 5772(2290+3483)ms|AST 440|Inlined 51Y 20N|IR 5784/ 18574|CodeSize 72200|Timestamp 2406154445007055|Src n/a
[engine] opt done id=912 AWFYVector>>forEach: <split-912> |Tier 2|Time 283( 216+68 )ms|AST 78|Inlined 2Y 0N|IR 260/ 1753|CodeSize 6432|Timestamp 2406154736528645|Src n/a
[engine] opt done id=873 AWFYVector>>at: |Tier 2|Time 117( 111+6 )ms|AST 38|Inlined 0Y 0N|IR 95/ 132|CodeSize 520|Timestamp 2406154855240656|Src n/a
[engine] opt done id=917 AWFYPlanner>>addPropagate:mark: <split-917> |Tier 2|Time 1173( 954+219 )ms|AST 128|Inlined 24Y 0N|IR 1495/ 1724|CodeSize 4919|Timestamp 2406155274697818|Src n/a
[engine] opt done id=909 AWFYPlanner>>addPropagate:mark: <split-909> |Tier 2|Time 921( 826+95 )ms|AST 128|Inlined 15Y 0N|IR 917/ 1335|CodeSize 4125|Timestamp 2406155777963465|Src n/a
[engine] opt done id=936 AWFYPlanner>>addPropagate:mark: <split-936> |Tier 2|Time 1183( 969+214 )ms|AST 128|Inlined 24Y 0N|IR 1573/ 1986|CodeSize 6065|Timestamp 2406156461956922|Src n/a
[engine] opt done id=958 AWFYPlanner>>addPropagate:mark: <split-958> |Tier 2|Time 1233(1010+223 )ms|AST 128|Inlined 24Y 0N|IR 1495/ 1724|CodeSize 4919|Timestamp 2406157014263934|Src n/a
[engine] opt done id=705 AWFYBinaryConstraint>>initializeVar:var:strength:addTo: |Tier 2|Time 424( 368+55 )ms|AST 33|Inlined 8Y 0N|IR 520/ 1278|CodeSize 3648|Timestamp 2406157441747657|Src n/a
[engine] opt done id=744 AWFYUnaryConstraint>>chooseMethod: |Tier 2|Time 143( 131+12 )ms|AST 59|Inlined 1Y 0N|IR 230/ 325|CodeSize 969|Timestamp 2406157587081003|Src n/a
[engine] opt done id=745 AWFYUnaryConstraint>>inputsDo: |Tier 2|Time 22( 20+2 )ms|AST 5|Inlined 0Y 0N|IR 19/ 22|CodeSize 122|Timestamp 2406157610283295|Src n/a
[engine] opt done id=743 AWFYUnaryConstraint>>addToGraph |Tier 2|Time 490( 383+107 )ms|AST 26|Inlined 2Y 0N|IR 859/ 2009|CodeSize 7823|Timestamp 2406158101897438|Src n/a
[engine] opt done id=903 AWFYVector>>forEach: <split-903> |Tier 2|Time 209( 184+25 )ms|AST 78|Inlined 1Y 0N|IR 215/ 961|CodeSize 3316|Timestamp 2406158313110046|Src n/a
[engine] opt done id=833 AWFYScaleConstraint>>inputsDo: |Tier 2|Time 435( 301+134 )ms|AST 135|Inlined 13Y 0N|IR 945/ 4267|CodeSize 13056|Timestamp 2406158750192118|Src n/a
[engine] opt done id=907 AWFYPlanner>>incrementalAdd: <split-907> |Tier 2|Time 3455(2023+1432)ms|AST 71|Inlined 44Y 9N|IR 4936/ 16293|CodeSize 57290|Timestamp 2406159920766567|Src n/a
[engine] opt done id=741 Behavior>>new <split-741> |Tier 2|Time 113( 109+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2406160040599517|Src n/a
[engine] opt done id=820 AWFYStrength class>>SymDefault |Tier 2|Time 33( 31+2 )ms|AST 9|Inlined 0Y 0N|IR 21/ 29|CodeSize 175|Timestamp 2406160075372644|Src n/a
[engine] opt done id=818 AWFYPlanner class>>projectionTest: |Tier 2|Time 6276(2483+3793)ms|AST 506|Inlined 42Y 21N|IR 6364/ 19337|CodeSize 77156|Timestamp 2406160177282798|Src n/a
[engine] opt done id=826 Behavior>>new <split-826> |Tier 2|Time 182( 174+8 )ms|AST 25|Inlined 0Y 0N|IR 98/ 207|CodeSize 729|Timestamp 2406160367626418|Src n/a
[engine] opt done id=740 AWFYStayConstraint class>>var:strength:addTo: |Tier 2|Time 4895(1966+2929)ms|AST 36|Inlined 47Y 12N|IR 5611/ 16210|CodeSize 58289|Timestamp 2406163647622219|Src n/a
[engine] opt done id=926 AWFYPlanner>>incrementalAdd: <split-926> |Tier 2|Time 3287(2305+982 )ms|AST 71|Inlined 52Y 4N|IR 4745/ 9233|CodeSize 37216|Timestamp 2406163656286882|Src n/a
[engine] opt done id=993 AWFYPlanner>>addConstraintsConsuming:to: <split-993> |Tier 2|Time 672( 451+221 )ms|AST 56|Inlined 4Y 0N|IR 1019/ 2345|CodeSize 9228|Timestamp 2406164336675725|Src n/a
[engine] opt done id=825 AWFYScaleConstraint class>>var:var:var:var:strength:addTo: |Tier 2|Time 5068(2266+2801)ms|AST 45|Inlined 39Y 5N|IR 5715/ 16956|CodeSize 65139|Timestamp 2406165144588127|Src n/a
[engine] opt done id=991 AWFYPlanner>>addPropagate:mark: <split-991> |Tier 2|Time 1907(1343+564 )ms|AST 140|Inlined 28Y 0N|IR 2733/ 4648|CodeSize 18085|Timestamp 2406165562724877|Src n/a
[engine] opt done id=1007 AWFYPlanner>>addPropagate:mark: <split-1007> |Tier 2|Time 2542(1767+775 )ms|AST 140|Inlined 28Y 0N|IR 2733/ 4648|CodeSize 18085|Timestamp 2406168111791752|Src n/a
[engine] opt done id=948 AWFYPlanner>>incrementalAdd: <split-948> |Tier 2|Time 3625(2635+989 )ms|AST 71|Inlined 53Y 5N|IR 4143/ 8554|CodeSize 32395|Timestamp 2406168776340573|Src n/a
[engine] opt done id=906 AWFYAbstractConstraint>>addConstraint: <split-906> |Tier 2|Time 4762(2240+2523)ms|AST 34|Inlined 43Y 10N|IR 5603/ 17881|CodeSize 64113|Timestamp 2406169101386678|Src n/a
[engine] opt done id=910 AWFYUnaryConstraint>>recalculate <split-910> |Tier 2|Time 152( 141+11 )ms|AST 81|Inlined 2Y 0N|IR 209/ 390|CodeSize 868|Timestamp 2406169260233102|Src n/a
[engine] opt done id=918 AWFYPlanner>>addConstraintsConsuming:to: <split-918> |Tier 2|Time 293( 264+29 )ms|AST 56|Inlined 3Y 0N|IR 349/ 618|CodeSize 2117|Timestamp 2406169555238692|Src n/a
[engine] opt done id=905 AWFYUnaryConstraint>>initializeVar:strength:addTo: <split-905> |Tier 2|Time 4765(2172+2592)ms|AST 44|Inlined 49Y 11N|IR 5254/ 16617|CodeSize 59271|Timestamp 2406173548591985|Src n/a
[engine] opt done id=827 AWFYScaleConstraint>>initializeSrc:scale:offset:dst:strength:addTo: |Tier 2|Time 4714(2427+2286)ms|AST 54|Inlined 38Y 4N|IR 5707/ 16998|CodeSize 64559|Timestamp 2406174271006921|Src n/a
[engine] opt done id=828 AWFYAbstractConstraint>>addConstraint: <split-828> |Tier 2|Time 4660(2667+1993)ms|AST 34|Inlined 44Y 5N|IR 6076/ 16511|CodeSize 61521|Timestamp 2406174343698494|Src n/a
[engine] opt done id=829 AWFYScaleConstraint>>addToGraph |Tier 2|Time 1302( 626+676 )ms|AST 77|Inlined 8Y 0N|IR 2800/ 7517|CodeSize 33040|Timestamp 2406174858066185|Src n/a
[engine] opt done id=832 AWFYBinaryConstraint>>isSatisfied <split-832> |Tier 2|Time 91( 72+19 )ms|AST 16|Inlined 0Y 0N|IR 34/ 67|CodeSize 301|Timestamp 2406174952260658|Src n/a
[engine] opt done id=777 [] in AWFYAbstractConstraint>>inputsKnown: |Tier 2|Time 123( 118+5 )ms|AST 51|Inlined 0Y 0N|IR 106/ 109|CodeSize 284|Timestamp 2406175076907032|Src n/a
[engine] opt done id=775 AWFYBinaryConstraint>>inputsHasOne: |Tier 2|Time 416( 361+56 )ms|AST 58|Inlined 3Y 0N|IR 420/ 1679|CodeSize 5428|Timestamp 2406175494866171|Src n/a
[engine] opt done id=776 Symbol>>= <split-776> |Tier 2|Time 97( 93+4 )ms|AST 27|Inlined 0Y 0N|IR 64/ 91|CodeSize 270|Timestamp 2406175593871482|Src n/a
[engine] opt done id=840 AWFYPlanner>>addConstraintsConsuming:to: <split-840> |Tier 2|Time 307( 290+17 )ms|AST 56|Inlined 2Y 0N|IR 265/ 422|CodeSize 1418|Timestamp 2406175902219870|Src n/a
[engine] opt done id=904 [] in AWFYPlanner>>addConstraintsConsuming:to: <split-904> |Tier 2|Time 79( 76+3 )ms|AST 21|Inlined 0Y 0N|IR 27/ 29|CodeSize 166|Timestamp 2406175982792308|Src n/a
[engine] opt done id=831 AWFYAbstractConstraint>>satisfy:propagate: <split-831> |Tier 2|Time 2435(2039+396 )ms|AST 150|Inlined 47Y 0N|IR 3337/ 4132|CodeSize 12310|Timestamp 2406176788394532|Src n/a
[engine] opt done id=883 AWFYVector>>forEach: <split-883> |Tier 2|Time 885( 645+240 )ms|AST 78|Inlined 3Y 0N|IR 1132/ 3061|CodeSize 12549|Timestamp 2406176869000566|Src n/a
[engine] opt done id=848 AWFYBinaryConstraint>>isSatisfied <split-848> |Tier 2|Time 78( 72+6 )ms|AST 16|Inlined 0Y 0N|IR 82/ 124|CodeSize 396|Timestamp 2406176948907872|Src n/a
[engine] opt done id=830 AWFYPlanner>>incrementalAdd: <split-830> |Tier 2|Time 2707(2320+387 )ms|AST 50|Inlined 49Y 0N|IR 3401/ 4195|CodeSize 13495|Timestamp 2406176985161918|Src n/a
[engine] opt done id=861 AWFYVector>>forEach: <split-861> |Tier 2|Time 637( 428+210 )ms|AST 78|Inlined 3Y 0N|IR 1083/ 3008|CodeSize 12001|Timestamp 2406177431238815|Src n/a
[engine] opt done id=791 [] in AWFYPlanner>>removePropagateFrom: |Tier 2|Time 502( 390+112 )ms|AST 40|Inlined 2Y 0N|IR 865/ 1938|CodeSize 8433|Timestamp 2406177509798677|Src n/a
[engine] opt done id=823 AWFYVector>>forEach: <split-823> |Tier 2|Time 624( 414+210 )ms|AST 78|Inlined 3Y 0N|IR 1063/ 2806|CodeSize 12722|Timestamp 2406177574201981|Src n/a
[engine] opt done id=792 AWFYBinaryConstraint>>isSatisfied <split-792> |Tier 2|Time 83( 78+6 )ms|AST 16|Inlined 0Y 0N|IR 82/ 124|CodeSize 396|Timestamp 2406177659793115|Src n/a
[engine] opt done id=813 AWFYPlanner>>addPropagate:mark: <split-813> |Tier 2|Time 1658(1325+332 )ms|AST 132|Inlined 34Y 0N|IR 2341/ 2767|CodeSize 8638|Timestamp 2406179318796744|Src n/a
[engine] opt done id=796 AWFYBinaryConstraint>>isSatisfied <split-796> |Tier 2|Time 87( 82+6 )ms|AST 16|Inlined 0Y 0N|IR 82/ 124|CodeSize 396|Timestamp 2406179410979967|Src n/a
[engine] opt done id=758 AWFYPlanner>>addPropagate:mark: <split-758> |Tier 2|Time 2020(1303+717 )ms|AST 140|Inlined 28Y 0N|IR 3098/ 4775|CodeSize 19252|Timestamp 2406179453576477|Src n/a
[engine] opt done id=708 AWFYBinaryConstraint>>addToGraph |Tier 2|Time 887( 566+321 )ms|AST 43|Inlined 4Y 0N|IR 1468/ 3878|CodeSize 16039|Timestamp 2406180344762435|Src n/a
[engine] opt done id=797 [] in AWFYPlanner>>removePropagateFrom: |Tier 2|Time 1403(1188+216 )ms|AST 48|Inlined 22Y 0N|IR 2200/ 3476|CodeSize 12430|Timestamp 2406180815739274|Src n/a
[engine] opt done id=703 Behavior>>new <split-703> |Tier 2|Time 120( 112+7 )ms|AST 25|Inlined 0Y 0N|IR 98/ 201|CodeSize 707|Timestamp 2406180939188998|Src n/a
[engine] opt done id=761 AWFYPlanner>>addPropagate:mark: <split-761> |Tier 2|Time 1858(1369+489 )ms|AST 128|Inlined 25Y 0N|IR 2360/ 3892|CodeSize 14495|Timestamp 2406182205104864|Src n/a
[engine] opt done id=736 [] in AWFYPlanner>>addConstraintsConsuming:to: |Tier 2|Time 240( 231+9 )ms|AST 44|Inlined 1Y 0N|IR 137/ 215|CodeSize 741|Timestamp 2406182449458191|Src n/a
[engine] opt done id=756 AWFYPlanner>>incrementalAdd: <split-756> |Tier 2|Time 5087(2186+2900)ms|AST 71|Inlined 37Y 21N|IR 6132/ 20316|CodeSize 78119|Timestamp 2406182598371294|Src n/a
[engine] opt done id=880 AWFYPlanner>>addPropagate:mark: <split-880> |Tier 2|Time 1858(1292+566 )ms|AST 140|Inlined 28Y 0N|IR 2915/ 4838|CodeSize 19759|Timestamp 2406184309044763|Src n/a
[engine] opt done id=704 AWFYEqualityConstraint>>initializeVar:var:strength:addTo: |Tier 2|Time 3409(2351+1058)ms|AST 44|Inlined 57Y 0N|IR 4857/ 8009|CodeSize 30058|Timestamp 2406184349450033|Src n/a
[engine] opt done id=803 AWFYPlanner>>incrementalAdd: <split-803> |Tier 2|Time 4268(2029+2239)ms|AST 71|Inlined 51Y 12N|IR 6442/ 18480|CodeSize 69384|Timestamp 2406186873305431|Src n/a
[engine] opt done id=860 AWFYPlanner>>addConstraintsConsuming:to: <split-860> |Tier 2|Time 826( 581+245 )ms|AST 56|Inlined 4Y 0N|IR 1153/ 2484|CodeSize 9762|Timestamp 2406187706182884|Src n/a
[engine] opt done id=742 AWFYUnaryConstraint>>initializeVar:strength:addTo: |Tier 2|Time 4536(2281+2255)ms|AST 44|Inlined 34Y 9N|IR 4756/ 12012|CodeSize 47309|Timestamp 2406188849503094|Src n/a
[engine] opt done id=716 AWFYBinaryConstraint>>isSatisfied |Tier 2|Time 99( 92+7 )ms|AST 17|Inlined 0Y 0N|IR 101/ 160|CodeSize 541|Timestamp 2406188992495386|Src n/a
[engine] opt done id=749 AWFYBinaryConstraint>>isSatisfied <split-749> |Tier 2|Time 101( 96+4 )ms|AST 16|Inlined 0Y 0N|IR 34/ 67|CodeSize 301|Timestamp 2406189481545540|Src n/a
[engine] opt done id=191 SequenceableCollection>>first |Tier 2|Time 157( 153+4 )ms|AST 20|Inlined 0Y 0N|IR 40/ 86|CodeSize 356|Timestamp 2406189640363191|Src n/a
[engine] opt done id=738 SequenceableCollection>>last |Tier 2|Time 97( 93+5 )ms|AST 23|Inlined 0Y 0N|IR 57/ 75|CodeSize 344|Timestamp 2406189738980795|Src n/a
[engine] opt done id=941 AWFYPlan>>execute <split-941> |Tier 2|Time 440( 320+120 )ms|AST 22|Inlined 6Y 0N|IR 619/ 1116|CodeSize 3869|Timestamp 2406190180380751|Src n/a
[engine] opt done id=712 AWFYAbstractConstraint>>satisfy:propagate: |Tier 2|Time 2852(1939+914 )ms|AST 182|Inlined 48Y 0N|IR 4762/ 7108|CodeSize 27277|Timestamp 2406190560418305|Src n/a
[engine] opt done id=849 Integer>>timesRepeat: |Tier 2|Time 654( 506+149 )ms|AST 45|Inlined 9Y 0N|IR 943/ 1842|CodeSize 7739|Timestamp 2406190836432898|Src n/a
[engine] opt done id=748 AWFYAbstractConstraint>>satisfy:propagate: <split-748> |Tier 2|Time 2276(1605+671 )ms|AST 164|Inlined 42Y 0N|IR 3829/ 5888|CodeSize 21497|Timestamp 2406191269986144|Src n/a
[engine] opt done id=785 AWFYVector>>remove: |Tier 2|Time 424( 311+112 )ms|AST 94|Inlined 3Y 0N|IR 615/ 1319|CodeSize 5339|Timestamp 2406208672110953|Src n/a
[engine] opt done id=784 AWFYVariable>>removeConstraint: |Tier 2|Time 494( 360+135 )ms|AST 38|Inlined 4Y 0N|IR 673/ 1426|CodeSize 5583|Timestamp 2406208742277780|Src n/a
[engine] opt done id=783 AWFYUnaryConstraint>>removeFromGraph |Tier 2|Time 497( 347+150 )ms|AST 36|Inlined 5Y 0N|IR 757/ 1517|CodeSize 5830|Timestamp 2406208744557793|Src n/a
[engine] opt done id=767 AWFYVector>>forEach: <split-767> |Tier 2|Time 392( 254+138 )ms|AST 78|Inlined 2Y 0N|IR 895/ 2759|CodeSize 10380|Timestamp 2406209066210221|Src n/a
[engine] opt done id=762 AWFYUnaryConstraint>>markUnsatisfied |Tier 2|Time 45( 40+5 )ms|AST 9|Inlined 0Y 0N|IR 98/ 97|CodeSize 290|Timestamp 2406224940100135|Src n/a
[engine] opt done id=890 SmallInteger>>printString |Tier 2|Time 288( 270+18 )ms|AST 149|Inlined 4Y 1N|IR 274/ 382|CodeSize 1169|Timestamp 2406225956177590|Src n/a
[engine] opt done id=766 AWFYVector class>>new |Tier 2|Time 163( 132+32 )ms|AST 19|Inlined 3Y 0N|IR 316/ 536|CodeSize 1362|Timestamp 2406234753190645|Src n/a
[engine] opt done id=1026 AWFYVector>>forEach: <split-1026> |Tier 2|Time 448( 298+150 )ms|AST 78|Inlined 3Y 0N|IR 1063/ 2806|CodeSize 12434|Timestamp 2406236618972734|Src n/a
[engine] opt done id=752 AWFYStrength class>>SymPreferred |Tier 2|Time 36( 33+3 )ms|AST 9|Inlined 0Y 0N|IR 21/ 29|CodeSize 175|Timestamp 2406248920878212|Src n/a
[engine] opt done id=1039 AWFYVector>>forEach: <split-1039> |Tier 2|Time 535( 398+136 )ms|AST 78|Inlined 3Y 0N|IR 949/ 2692|CodeSize 11113|Timestamp 2406250641604458|Src n/a
[engine] opt done id=765 AWFYPlanner>>extractPlanFromConstraints: |Tier 2|Time 2135(1321+814 )ms|AST 56|Inlined 32Y 0N|IR 3705/ 7693|CodeSize 35014|Timestamp 2406251030052318|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 161( 149+11 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1107|Timestamp 2406261509229795|Src n/a
[engine] opt done id=696 AWFYPlanner>>initialize |Tier 2|Time 39( 35+4 )ms|AST 9|Inlined 0Y 0N|IR 73/ 84|CodeSize 214|Timestamp 2406269376527118|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 190
Success : 181
Temporary Bailouts : 5
org.graalvm.compiler.core.common.RetryableBailoutException: Assumption invalidated while compiling code: Object[Instance<org.graalvm.compiler.truffle.runtime.OptimizedAssumption>]: 4
org.graalvm.compiler.core.common.CancellationBailoutException: Compilation cancelled.: 1
Permanent Bailouts : 0
Failed : 0
Interrupted : 4
Invalidated : 7
validRootAssumption Split call node : 4
Profiled Argument Types : 3
Queues : 292
Dequeues : 107
Target inlined into only caller : 99
Split call node : 6
validRootAssumption Split call node : 2
Splits : 461
Compilation Accuracy : 0.963158
Queue Accuracy : 0.633562
Compilation Utilization : 1.226578
Remaining Compilation Queue : 0
Time to queue : count= 292, sum= 2097676, min= 2, average= 7183.82, max= 132360 (milliseconds), maxTarget=AWFYPlanner>>initialize
Time waiting in queue : count= 190, sum= 1802555, min= 0, average= 9487.13, max= 51199 (milliseconds), maxTarget=AWFYBinaryConstraint>>isSatisfied
Time for compilation : count= 186, sum= 162677, min= 22, average= 874.61, max= 6277 (milliseconds), maxTarget=AWFYPlanner class>>projectionTest:
Truffle Tier : count= 181, sum= 99700, min= 19, average= 550.83, max= 2667 (milliseconds), maxTarget=AWFYAbstractConstraint>>addConstraint: <split-828>
Graal Tier : count= 181, sum= 40102, min= 1, average= 221.56, max= 2702 (milliseconds), maxTarget=AWFYPlanner class>>projectionTest:
Code Installation : count= 181, sum= 16236, min= 1, average= 89.70, max= 1179 (milliseconds), maxTarget=AWFYPlanner class>>chainTest:
Truffle node count : count= 186, sum= 161861, min= 6, average= 870.22, max= 4537, maxTarget=AWFYEqualityConstraint class>>var:var:strength:addTo:
Trivial : count= 186, sum= 64316, min= 1, average= 345.78, max= 1801, maxTarget=AWFYEqualityConstraint class>>var:var:strength:addTo:
Non Trivial : count= 186, sum= 97545, min= 5, average= 524.44, max= 2736, maxTarget=AWFYEqualityConstraint class>>var:var:strength:addTo:
Monomorphic : count= 186, sum= 94191, min= 5, average= 506.40, max= 2652, maxTarget=AWFYEqualityConstraint class>>var:var:strength:addTo:
Polymorphic : count= 186, sum= 3354, min= 0, average= 18.03, max= 109, maxTarget=AWFYAbstractConstraint>>satisfy:propagate:
Megamorphic : count= 186, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYVector>>initialize:
Truffle call count : count= 186, sum= 2075, min= 0, average= 11.16, max= 71, maxTarget=AWFYPlanner class>>chainTest:
Indirect : count= 186, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYVector>>initialize:
Direct : count= 186, sum= 2075, min= 0, average= 11.16, max= 71, maxTarget=AWFYPlanner class>>chainTest:
Dispatched : count= 186, sum= 172, min= 0, average= 0.92, max= 21, maxTarget=AWFYPlanner class>>projectionTest:
Inlined : count= 186, sum= 1903, min= 0, average= 10.23, max= 59, maxTarget=AWFYEqualityConstraint class>>var:var:strength:addTo:
---------- :
Cloned : count= 186, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYVector>>initialize:
Not Cloned : count= 186, sum= 2035, min= 0, average= 10.94, max= 71, maxTarget=AWFYPlanner class>>chainTest:
Truffle loops : count= 186, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYVector>>initialize:
Graal node count :
After Truffle Tier : count= 186, sum= 216788, min= 5, average= 1165.53, max= 6442, maxTarget=AWFYPlanner>>incrementalAdd: <split-803>
After Graal Tier : count= 185, sum= 491478, min= 5, average= 2656.64, max= 20316, maxTarget=AWFYPlanner>>incrementalAdd: <split-756>
Graal compilation result :
Code size : count= 181, sum= 1858772, min= 88, average= 10269.46, max= 78119, maxTarget=AWFYPlanner>>incrementalAdd: <split-756>
Total frame size : count= 181, sum= 44192, min= 32, average= 244.15, max= 1232, maxTarget=AWFYPlanner>>incrementalAdd: <split-756>
Exception handlers : count= 181, sum= 301, min= 0, average= 1.66, max= 31, maxTarget=AWFYPlanner class>>projectionTest:
Infopoints : count= 181, sum= 16251, min= 4, average= 89.78, max= 810, maxTarget=AWFYPlanner>>incrementalAdd: <split-756>
CALL : count= 181, sum= 13711, min= 4, average= 75.75, max= 659, maxTarget=AWFYPlanner>>incrementalAdd: <split-756>
IMPLICIT_EXCEPTION : count= 181, sum= 2362, min= 0, average= 13.05, max= 147, maxTarget=AWFYPlanner>>incrementalAdd: <split-756>
SAFEPOINT : count= 181, sum= 178, min= 0, average= 0.98, max= 6, maxTarget=AWFYPlanner>>extractPlanFromConstraints:
Marks : count= 181, sum= 1564, min= 5, average= 8.64, max= 41, maxTarget=AWFYPlanner class>>projectionTest:
Data references : count= 181, sum= 14534, min= 0, average= 80.30, max= 619, maxTarget=AWFYPlanner>>incrementalAdd: <split-756>
Raw
c4528635-Havlak.trace.log
# Havlak (iterations: 250, problem size: 1500) on Tue May 3 07:14:16 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Havlak.trace.log" --quiet --code "AWFYHarness run: #('Havlak' 250 1500)"`
[engine] opt done id=666 Behavior>>new <split-666> |Tier 2|Time 208( 193+15 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2406406577522731|Src n/a
[engine] opt done id=665 AWFYVector class>>new: |Tier 2|Time 278( 269+9 )ms|AST 28|Inlined 2Y 0N|IR 53/ 292|CodeSize 956|Timestamp 2406406621782111|Src n/a
[engine] opt done id=688 AWFYVector>>size |Tier 2|Time 64( 60+4 )ms|AST 17|Inlined 0Y 0N|IR 40/ 115|CodeSize 411|Timestamp 2406406752229882|Src n/a
[engine] opt done id=682 AWFYVector>>at: |Tier 2|Time 126( 116+10 )ms|AST 38|Inlined 0Y 0N|IR 179/ 238|CodeSize 733|Timestamp 2406406752824820|Src n/a
[engine] opt done id=680 AWFYVector>>append: |Tier 2|Time 472( 370+102 )ms|AST 160|Inlined 0Y 0N|IR 563/ 1784|CodeSize 7285|Timestamp 2406406808604678|Src n/a
[engine] opt done id=775 Integer>>>> |Tier 2|Time 89( 84+5 )ms|AST 30|Inlined 0Y 0N|IR 40/ 120|CodeSize 435|Timestamp 2406406844373728|Src n/a
[engine] opt done id=776 AWFYSomDictionary>>bucketIdx: |Tier 2|Time 106( 97+9 )ms|AST 34|Inlined 0Y 0N|IR 109/ 246|CodeSize 797|Timestamp 2406406917427946|Src n/a
[engine] opt done id=774 AWFYSomDictionary>>hash: |Tier 2|Time 171( 166+5 )ms|AST 59|Inlined 1Y 0N|IR 33/ 111|CodeSize 396|Timestamp 2406406926106091|Src n/a
[engine] opt done id=772 AWFYHavlakLoopFinder>>Unvisited |Tier 2|Time 47( 43+3 )ms|AST 7|Inlined 0Y 0N|IR 18/ 58|CodeSize 237|Timestamp 2406406966363505|Src n/a
[engine] opt done id=784 AWFYDictIdEntry>>match:key: |Tier 2|Time 85( 80+5 )ms|AST 28|Inlined 0Y 0N|IR 51/ 96|CodeSize 359|Timestamp 2406407013628796|Src n/a
[engine] opt done id=664 AWFYVector class>>new |Tier 2|Time 233( 167+66 )ms|AST 19|Inlined 3Y 0N|IR 45/ 218|CodeSize 747|Timestamp 2406407080209800|Src n/a
[engine] opt done id=787 AWFYSomDictionary>>bucket: |Tier 2|Time 232( 210+22 )ms|AST 32|Inlined 1Y 0N|IR 162/ 138|CodeSize 561|Timestamp 2406407247966977|Src n/a
[engine] opt done id=803 AWFYVector>>isEmpty |Tier 2|Time 63( 59+4 )ms|AST 17|Inlined 0Y 0N|IR 39/ 54|CodeSize 221|Timestamp 2406407313940052|Src n/a
[engine] opt done id=786 AWFYSomDictionary>>at: |Tier 2|Time 365( 344+21 )ms|AST 85|Inlined 5Y 0N|IR 249/ 238|CodeSize 885|Timestamp 2406407333666593|Src n/a
[engine] opt done id=793 AWFYHavlakLoopFinder>>isAncestor:v: |Tier 2|Time 141( 133+7 )ms|AST 40|Inlined 0Y 0N|IR 119/ 240|CodeSize 783|Timestamp 2406407465933123|Src n/a
[engine] opt done id=794 AWFYVector>>forEach: <split-794> |Tier 2|Time 1425( 986+439 )ms|AST 78|Inlined 18Y 0N|IR 2096/ 5336|CodeSize 22368|Timestamp 2406408892935552|Src n/a
[engine] opt deopt id=682 AWFYVector>>at: |Timestamp 2406409115388177|Src n/a
[engine] opt done id=841 AWFYVector>>hasSome: <split-841> |Tier 2|Time 339( 299+40 )ms|AST 78|Inlined 1Y 0N|IR 229/ 1625|CodeSize 5754|Timestamp 2406409244623024|Src n/a
[engine] opt done id=682 AWFYVector>>at: |Tier 2|Time 141( 130+11 )ms|AST 38|Inlined 0Y 0N|IR 184/ 298|CodeSize 1004|Timestamp 2406409387991451|Src n/a
[engine] opt done id=768 AWFYUnionFindNode>>initialize |Tier 2|Time 39( 36+4 )ms|AST 9|Inlined 0Y 0N|IR 73/ 84|CodeSize 214|Timestamp 2406409429723219|Src n/a
[engine] opt inval. id=794 AWFYVector>>forEach: <split-794> |Timestamp 2406409478823472|Src n/a|Reason Latest layout assumption Layout no longer valid
[engine] opt inval. id=786 AWFYSomDictionary>>at: |Timestamp 2406409483005707|Src n/a|Reason Latest layout assumption Layout no longer valid
[engine] opt inval. id=784 AWFYDictIdEntry>>match:key: |Timestamp 2406409483453692|Src n/a|Reason Latest layout assumption Layout no longer valid
[engine] opt done id=784 AWFYDictIdEntry>>match:key: |Tier 2|Time 141( 135+6 )ms|AST 29|Inlined 0Y 0N|IR 88/ 144|CodeSize 436|Timestamp 2406409883456152|Src n/a
[engine] opt deopt id=841 AWFYVector>>hasSome: <split-841> |Timestamp 2406410341689184|Src n/a
[engine] opt done id=763 AWFYHavlakLoopFinder>>findLoops |Tier 2|Time 4646(2330+2316)ms|AST 741|Inlined 34Y 17N|IR 7165/ 31153|CodeSize 115943|Timestamp 2406411729368864|Src n/a
[engine] opt done id=816 AWFYVector>>forEach: <split-816> |Tier 2|Time 2439(1405+1034)ms|AST 78|Inlined 23Y 0N|IR 2973/ 9137|CodeSize 41306|Timestamp 2406411870805035|Src n/a
[engine] opt deopt id=819 AWFYVector>>hasSome: <split-819> |Timestamp 2406412003625084|Src n/a
[engine] opt deopt id=817 [] in AWFYHavlakLoopFinder>>stepEProcessNonBackPreds:nodePool:workList:x: |Timestamp 2406412004428160|Src n/a
[engine] opt deopt id=816 AWFYVector>>forEach: <split-816> |Timestamp 2406412004919797|Src n/a
[engine] opt done id=841 AWFYVector>>hasSome: <split-841> |Tier 2|Time 236( 158+78 )ms|AST 78|Inlined 1Y 0N|IR 259/ 1777|CodeSize 6152|Timestamp 2406412112427818|Src n/a
[engine] opt done id=781 AWFYHavlakLoopFinder>>doDFS:current: |Tier 2|Time 3080(2280+799 )ms|AST 225|Inlined 68Y 1N|IR 3732/ 7134|CodeSize 33196|Timestamp 2406412965225546|Src n/a
[engine] opt done id=794 AWFYVector>>forEach: <split-794> |Tier 2|Time 1345( 911+434 )ms|AST 78|Inlined 18Y 0N|IR 2185/ 5731|CodeSize 24339|Timestamp 2406413103422107|Src n/a
[engine] opt done id=786 AWFYSomDictionary>>at: |Tier 2|Time 242( 232+11 )ms|AST 85|Inlined 5Y 0N|IR 302/ 238|CodeSize 885|Timestamp 2406413240787236|Src n/a
[engine] opt done id=808 Object>>= |Tier 2|Time 39( 37+3 )ms|AST 13|Inlined 0Y 0N|IR 23/ 33|CodeSize 150|Timestamp 2406413282407462|Src n/a
[engine] opt done id=819 AWFYVector>>hasSome: <split-819> |Tier 2|Time 227( 157+70 )ms|AST 80|Inlined 1Y 0N|IR 259/ 1777|CodeSize 6176|Timestamp 2406413334381618|Src n/a
[engine] opt done id=675 Behavior>>new <split-675> |Tier 2|Time 103( 93+10 )ms|AST 26|Inlined 0Y 0N|IR 135/ 227|CodeSize 733|Timestamp 2406413386872276|Src n/a
[engine] opt done id=674 AWFYSomSet class>>new |Tier 2|Time 224( 199+25 )ms|AST 27|Inlined 5Y 0N|IR 261/ 586|CodeSize 1777|Timestamp 2406413560120091|Src n/a
[engine] opt done id=676 AWFYSomSet>>initialize: |Tier 2|Time 178( 164+14 )ms|AST 22|Inlined 3Y 0N|IR 121/ 714|CodeSize 2205|Timestamp 2406413566915919|Src n/a
[engine] opt done id=832 Object>>~= <split-832> |Tier 2|Time 88( 85+3 )ms|AST 25|Inlined 1Y 0N|IR 27/ 42|CodeSize 195|Timestamp 2406413652696625|Src n/a
[engine] opt done id=818 [] in [] in AWFYHavlakLoopFinder>>stepEProcessNonBackPreds:nodePool:workList:x: |Tier 2|Time 47( 44+3 )ms|AST 13|Inlined 0Y 0N|IR 25/ 33|CodeSize 150|Timestamp 2406413701836829|Src n/a
[engine] opt done id=806 AWFYUnionFindNode>>findSet |Tier 2|Time 764( 622+142 )ms|AST 153|Inlined 12Y 0N|IR 865/ 2174|CodeSize 9033|Timestamp 2406414333042280|Src n/a
[engine] opt done id=809 AWFYVector>>forEach: <split-809> |Tier 2|Time 192( 166+26 )ms|AST 78|Inlined 2Y 0N|IR 279/ 1100|CodeSize 3703|Timestamp 2406414528762933|Src n/a
[engine] opt done id=816 AWFYVector>>forEach: <split-816> |Tier 2|Time 2548(1319+1229)ms|AST 78|Inlined 26Y 0N|IR 3605/ 11732|CodeSize 56972|Timestamp 2406414662580925|Src n/a
[engine] opt done id=822 AWFYSomIdentitySet>>contains: |Tier 2|Time 287( 219+68 )ms|AST 24|Inlined 3Y 0N|IR 337/ 707|CodeSize 2227|Timestamp 2406414954547967|Src n/a
[engine] opt done id=1057 AWFYSomDictionary>>transferEntries: |Tier 2|Time 603( 467+137 )ms|AST 188|Inlined 3Y 0N|IR 823/ 2185|CodeSize 9200|Timestamp 2406415560232554|Src n/a
[engine] opt done id=801 AWFYVector>>forEach: <split-801> |Tier 2|Time 1257( 834+423 )ms|AST 78|Inlined 15Y 0N|IR 1555/ 4764|CodeSize 20392|Timestamp 2406415787991008|Src n/a
[engine] opt done id=766 AWFYUnionFindNode class>>new |Tier 2|Time 141( 137+4 )ms|AST 25|Inlined 3Y 0N|IR 33/ 107|CodeSize 406|Timestamp 2406415932782174|Src n/a
[engine] opt done id=826 AWFYVector>>forEach: <split-826> |Tier 2|Time 1778( 868+910 )ms|AST 78|Inlined 17Y 0N|IR 2222/ 6119|CodeSize 25374|Timestamp 2406417341375970|Src n/a
[engine] opt done id=1068 AWFYHavlakLoopFinder>>findLoops <split-1068> |Tier 2|Time 3862(1909+1953)ms|AST 741|Inlined 25Y 18N|IR 6767/ 28850|CodeSize 107677|Timestamp 2406417566284828|Src n/a
[engine] opt done id=777 AWFYSomIdentityDictionary>>newEntry:value:hash: |Tier 2|Time 174( 168+6 )ms|AST 28|Inlined 3Y 0N|IR 48/ 179|CodeSize 626|Timestamp 2406417747534271|Src n/a
[engine] opt done id=1073 AWFYVector>>forEach: <split-1073> |Tier 2|Time 416( 276+140 )ms|AST 78|Inlined 2Y 0N|IR 692/ 2581|CodeSize 9769|Timestamp 2406417761828355|Src n/a
[engine] opt done id=791 AWFYBasicBlock>>numPred |Tier 2|Time 134( 129+5 )ms|AST 19|Inlined 1Y 0N|IR 46/ 143|CodeSize 511|Timestamp 2406417898432246|Src n/a
[engine] opt done id=789 AWFYHavlakLoopFinder>>identifyEdges: |Tier 2|Time 2101(1274+827 )ms|AST 127|Inlined 22Y 0N|IR 2548/ 6294|CodeSize 27446|Timestamp 2406418035816582|Src n/a
[engine] opt done id=778 AWFYDictIdEntry class>>new:key:value:next: |Tier 2|Time 147( 141+5 )ms|AST 39|Inlined 2Y 0N|IR 48/ 118|CodeSize 425|Timestamp 2406418186898039|Src n/a
[engine] opt done id=779 Behavior>>new <split-779> |Tier 2|Time 83( 79+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2406418272355923|Src n/a
[engine] opt done id=800 AWFYHavlakLoopFinder>>stepD:nodePool: |Tier 2|Time 1386( 803+583 )ms|AST 44|Inlined 17Y 0N|IR 1747/ 4467|CodeSize 19696|Timestamp 2406419286809611|Src n/a
[engine] opt done id=1070 AWFYVector>>forEach: <split-1070> |Tier 2|Time 1722(1045+677 )ms|AST 78|Inlined 23Y 0N|IR 1935/ 5289|CodeSize 24077|Timestamp 2406419995859377|Src n/a
[engine] opt done id=1071 [] in AWFYHavlakLoopFinder>>initAllNodes <split-1071> |Tier 2|Time 1428(1055+373 )ms|AST 33|Inlined 22Y 0N|IR 1762/ 4253|CodeSize 18758|Timestamp 2406420080407533|Src n/a
[engine] opt done id=1074 Symbol>>= <split-1074> |Tier 2|Time 81( 78+3 )ms|AST 25|Inlined 0Y 0N|IR 27/ 39|CodeSize 185|Timestamp 2406420091555738|Src n/a
[engine] opt done id=780 AWFYDictEntry>>init:key:value:next: |Tier 2|Time 71( 55+16 )ms|AST 25|Inlined 0Y 0N|IR 140/ 370|CodeSize 900|Timestamp 2406420155821598|Src n/a
[engine] opt done id=812 AWFYSomSet>>size |Tier 2|Time 124( 110+15 )ms|AST 19|Inlined 1Y 0N|IR 46/ 143|CodeSize 511|Timestamp 2406420282029582|Src n/a
[engine] opt done id=811 AWFYVector>>removeFirst |Tier 2|Time 191( 173+18 )ms|AST 52|Inlined 1Y 0N|IR 125/ 192|CodeSize 641|Timestamp 2406420283847572|Src n/a
[engine] opt done id=813 AWFYHavlakLoopFinder>>MaxNonBackPreds |Tier 2|Time 73( 70+3 )ms|AST 13|Inlined 0Y 0N|IR 18/ 58|CodeSize 237|Timestamp 2406420356709369|Src n/a
[engine] opt done id=828 AWFYUnionFindNode>>union: |Tier 2|Time 61( 56+5 )ms|AST 10|Inlined 0Y 0N|IR 66/ 174|CodeSize 415|Timestamp 2406420419379695|Src n/a
[engine] opt done id=679 AWFYSimpleLoop>>counter: |Tier 2|Time 64( 60+4 )ms|AST 10|Inlined 0Y 0N|IR 79/ 95|CodeSize 241|Timestamp 2406420485149872|Src n/a
[engine] opt inval. id=1068 AWFYHavlakLoopFinder>>findLoops <split-1068> |Timestamp 2406420499337023|Src n/a|Reason Profiled Argument Types
[engine] opt inval. id=763 AWFYHavlakLoopFinder>>findLoops |Timestamp 2406420500099379|Src n/a|Reason Profiled Argument Types
[engine] opt done id=815 AWFYSomSet>>forEach: |Tier 2|Time 6314(2693+3621)ms|AST 23|Inlined 49Y 1N|IR 5189/ 15225|CodeSize 69942|Timestamp 2406426600181289|Src n/a
[engine] opt done id=814 AWFYHavlakLoopFinder>>stepEProcessNonBackPreds:nodePool:workList:x: |Tier 2|Time 4930(1970+2960)ms|AST 57|Inlined 29Y 0N|IR 4034/ 13266|CodeSize 61789|Timestamp 2406428076314648|Src n/a
[engine] opt done id=1068 AWFYHavlakLoopFinder>>findLoops <split-1068> |Tier 2|Time 5134(2560+2574)ms|AST 741|Inlined 26Y 17N|IR 6738/ 28225|CodeSize 103510|Timestamp 2406428260393155|Src n/a
[engine] opt done id=821 AWFYLoopStructureGraph>>createNewLoop:reducible: |Tier 2|Time 2195(1435+759 )ms|AST 77|Inlined 23Y 0N|IR 1887/ 5396|CodeSize 19989|Timestamp 2406430461943781|Src n/a
[engine] opt done id=817 [] in AWFYHavlakLoopFinder>>stepEProcessNonBackPreds:nodePool:workList:x: |Tier 2|Time 3357(2034+1323)ms|AST 212|Inlined 25Y 0N|IR 3344/ 10987|CodeSize 52625|Timestamp 2406431439033660|Src n/a
[engine] opt done id=825 AWFYUnionFindNode>>loop: |Tier 2|Time 39( 34+5 )ms|AST 10|Inlined 0Y 0N|IR 66/ 174|CodeSize 415|Timestamp 2406431483185131|Src n/a
[engine] opt done id=1075 Object>>~= <split-1075> |Tier 2|Time 107( 102+5 )ms|AST 25|Inlined 1Y 0N|IR 102/ 137|CodeSize 284|Timestamp 2406431617445032|Src n/a
[engine] opt done id=1200 AWFYVector>>forEach: <split-1200> |Tier 2|Time 3893(2332+1561)ms|AST 78|Inlined 26Y 0N|IR 3605/ 11733|CodeSize 54245|Timestamp 2406432577564584|Src n/a
[engine] opt done id=767 Behavior>>new <split-767> |Tier 2|Time 155( 138+17 )ms|AST 27|Inlined 1Y 0N|IR 33/ 107|CodeSize 406|Timestamp 2406432738113363|Src n/a
[engine] opt done id=824 AWFYHavlakLoopFinder>>setLoopAttribute:nodePool:loop: |Tier 2|Time 2278(1236+1042)ms|AST 59|Inlined 19Y 0N|IR 2352/ 5776|CodeSize 23547|Timestamp 2406432744053452|Src n/a
[engine] opt done id=850 AWFYVector>>hasSome: <split-850> |Tier 2|Time 358( 220+139 )ms|AST 80|Inlined 1Y 0N|IR 262/ 1788|CodeSize 6378|Timestamp 2406433098509436|Src n/a
[engine] opt done id=1197 AWFYVector>>forEach: <split-1197> |Tier 2|Time 677( 370+307 )ms|AST 78|Inlined 2Y 0N|IR 681/ 2581|CodeSize 10117|Timestamp 2406433777615422|Src n/a
[engine] opt done id=687 AWFYControlFlowGraph>>numNodes |Tier 2|Time 140( 120+21 )ms|AST 19|Inlined 1Y 0N|IR 46/ 143|CodeSize 511|Timestamp 2406433940902465|Src n/a
[engine] opt done id=792 [] in AWFYHavlakLoopFinder>>processEdges:w: |Tier 2|Time 1710(1153+557 )ms|AST 124|Inlined 17Y 0N|IR 2001/ 4839|CodeSize 20471|Timestamp 2406434457724519|Src n/a
[engine] opt done id=810 [] in AWFYHavlakLoopFinder>>findLoops |Tier 2|Time 626( 388+238 )ms|AST 22|Inlined 1Y 0N|IR 524/ 1816|CodeSize 7665|Timestamp 2406434568686855|Src n/a
[engine] opt done id=796 AWFYSomSet>>contains: |Tier 2|Time 507( 436+72 )ms|AST 24|Inlined 3Y 0N|IR 338/ 685|CodeSize 2221|Timestamp 2406435078036076|Src n/a
[engine] opt done id=1194 AWFYVector>>forEach: <split-1194> |Tier 2|Time 1048( 823+224 )ms|AST 78|Inlined 10Y 0N|IR 631/ 2102|CodeSize 7783|Timestamp 2406435508935289|Src n/a
[engine] opt done id=849 AWFYSomSet>>hasSome: <split-849> |Tier 2|Time 442( 352+90 )ms|AST 22|Inlined 2Y 0N|IR 315/ 1862|CodeSize 6409|Timestamp 2406435541625790|Src n/a
[engine] opt done id=831 [] in AWFYSomIdentitySet>>contains: |Tier 2|Time 58( 55+3 )ms|AST 13|Inlined 0Y 0N|IR 25/ 33|CodeSize 150|Timestamp 2406435569562167|Src n/a
[engine] opt done id=686 AWFYVector>>at:put: |Tier 2|Time 536( 316+220 )ms|AST 198|Inlined 0Y 0N|IR 586/ 1925|CodeSize 7837|Timestamp 2406436106840920|Src n/a
[engine] opt done id=848 AWFYSomSet>>add: <split-848> |Tier 2|Time 791( 600+191 )ms|AST 39|Inlined 5Y 0N|IR 819/ 2328|CodeSize 9728|Timestamp 2406436334195534|Src n/a
[engine] opt done id=1198 Symbol>>= <split-1198> |Tier 2|Time 98( 78+20 )ms|AST 25|Inlined 0Y 0N|IR 27/ 39|CodeSize 185|Timestamp 2406436434198875|Src n/a
[engine] opt done id=1192 AWFYHavlakLoopFinder>>findLoops <split-1192> |Tier 2|Time 4956(2324+2633)ms|AST 741|Inlined 37Y 13N|IR 7041/ 28327|CodeSize 102305|Timestamp 2406436575818251|Src n/a
[engine] opt done id=783 AWFYSomDictionary>>insertBucketEntry:value:hash:head: |Tier 2|Time 406( 368+39 )ms|AST 121|Inlined 7Y 0N|IR 314/ 562|CodeSize 2053|Timestamp 2406437008653142|Src n/a
[engine] opt done id=782 AWFYUnionFindNode>>initNode:dfs: |Tier 2|Time 71( 64+7 )ms|AST 19|Inlined 0Y 0N|IR 111/ 210|CodeSize 696|Timestamp 2406437082192713|Src n/a
[engine] opt done id=785 AWFYDictEntry>>value: |Tier 2|Time 57( 52+5 )ms|AST 10|Inlined 0Y 0N|IR 70/ 178|CodeSize 425|Timestamp 2406437140389621|Src n/a
[engine] opt done id=788 AWFYSomDictionary>>at:put: <split-788> |Tier 2|Time 632( 593+40 )ms|AST 114|Inlined 11Y 0N|IR 508/ 780|CodeSize 2920|Timestamp 2406437774257004|Src n/a
[engine] opt done id=699 AWFYBasicBlock>>addOutEdge: |Tier 2|Time 389( 276+113 )ms|AST 23|Inlined 1Y 0N|IR 523/ 1799|CodeSize 7600|Timestamp 2406438165580766|Src n/a
[engine] opt done id=700 AWFYBasicBlock>>addInEdge: |Tier 2|Time 456( 346+110 )ms|AST 23|Inlined 1Y 0N|IR 523/ 1799|CodeSize 7600|Timestamp 2406438623288921|Src n/a
[engine] opt done id=1084 AWFYVector>>forEach: <split-1084> |Tier 2|Time 2193( 937+1256)ms|AST 78|Inlined 23Y 1N|IR 1720/ 4008|CodeSize 14787|Timestamp 2406438628693860|Src n/a
[engine] opt done id=701 AWFYControlFlowGraph>>addEdge: |Tier 2|Time 513( 394+119 )ms|AST 23|Inlined 1Y 0N|IR 523/ 1799|CodeSize 7600|Timestamp 2406439138254712|Src n/a
[engine] opt done id=843 AWFYSimpleLoop>>parent: |Tier 2|Time 916( 606+310 )ms|AST 27|Inlined 7Y 0N|IR 933/ 2430|CodeSize 8795|Timestamp 2406439548053398|Src n/a
[engine] opt done id=844 AWFYSimpleLoop>>addChildLoop: |Tier 2|Time 762( 541+221 )ms|AST 23|Inlined 6Y 0N|IR 867/ 2272|CodeSize 8731|Timestamp 2406439902335818|Src n/a
[engine] opt done id=1247 AWFYVector>>forEach: <split-1247> |Tier 2|Time 723( 527+196 )ms|AST 78|Inlined 2Y 0N|IR 692/ 2581|CodeSize 9769|Timestamp 2406440272942571|Src n/a
[engine] opt done id=845 AWFYSomSet>>add: <split-845> |Tier 2|Time 857( 590+266 )ms|AST 39|Inlined 5Y 0N|IR 810/ 2201|CodeSize 8291|Timestamp 2406440761113319|Src n/a
[engine] opt done id=1078 AWFYVector>>forEach: <split-1078> |Tier 2|Time 1359( 950+409 )ms|AST 78|Inlined 9Y 0N|IR 1233/ 3525|CodeSize 14184|Timestamp 2406441634304689|Src n/a
[engine] opt done id=684 Behavior>>new <split-684> |Tier 2|Time 107( 103+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2406441783427769|Src n/a
[engine] opt done id=683 AWFYBasicBlock class>>new: |Tier 2|Time 443( 323+120 )ms|AST 30|Inlined 8Y 0N|IR 66/ 541|CodeSize 1772|Timestamp 2406442080283810|Src n/a
[engine] opt done id=1242 AWFYHavlakLoopFinder>>findLoops <split-1242> |Tier 2|Time 6473(2404+4070)ms|AST 741|Inlined 24Y 27N|IR 8621/ 30572|CodeSize 113845|Timestamp 2406442582458438|Src n/a
[engine] opt done id=805 [] in AWFYHavlakLoopFinder>>stepD:nodePool: |Tier 2|Time 1061( 704+356 )ms|AST 54|Inlined 14Y 0N|IR 1364/ 3959|CodeSize 17536|Timestamp 2406443143046841|Src n/a
[engine] opt done id=1244 AWFYVector>>forEach: <split-1244> |Tier 2|Time 1633(1024+609 )ms|AST 78|Inlined 23Y 0N|IR 1935/ 5289|CodeSize 23690|Timestamp 2406443753114337|Src n/a
[engine] opt done id=1201 Object>>~= <split-1201> |Tier 2|Time 173( 168+5 )ms|AST 25|Inlined 1Y 0N|IR 102/ 137|CodeSize 284|Timestamp 2406443946557564|Src n/a
[engine] opt done id=22 Magnitude>>max: |Tier 2|Time 74( 70+4 )ms|AST 20|Inlined 0Y 0N|IR 59/ 72|CodeSize 190|Timestamp 2406444076605895|Src n/a
[engine] opt done id=677 AWFYSimpleLoop>>nestingLevel: |Tier 2|Time 144( 136+9 )ms|AST 33|Inlined 1Y 0N|IR 159/ 185|CodeSize 403|Timestamp 2406444102606873|Src n/a
[engine] opt done id=1081 AWFYSimpleLoop>>depthLevel: |Tier 2|Time 72( 57+15 )ms|AST 10|Inlined 0Y 0N|IR 79/ 95|CodeSize 241|Timestamp 2406444176453901|Src n/a
[engine] opt done id=1080 AWFYLoopStructureGraph>>calculateNestingLevelRec:depth: |Tier 2|Time 1842(1116+726 )ms|AST 57|Inlined 23Y 1N|IR 1573/ 2020|CodeSize 7064|Timestamp 2406445919884374|Src n/a
[engine] opt done id=1248 Symbol>>= <split-1248> |Tier 2|Time 59( 55+3 )ms|AST 25|Inlined 0Y 0N|IR 27/ 39|CodeSize 185|Timestamp 2406445981524001|Src n/a
[engine] opt done id=764 AWFYVector>>removeAll |Tier 2|Time 109( 99+10 )ms|AST 34|Inlined 0Y 0N|IR 175/ 347|CodeSize 944|Timestamp 2406446091568297|Src n/a
[engine] opt done id=842 Object>>~= <split-842> |Tier 2|Time 85( 82+3 )ms|AST 25|Inlined 1Y 0N|IR 27/ 42|CodeSize 195|Timestamp 2406446178016582|Src n/a
[engine] opt done id=771 [] in AWFYHavlakLoopFinder>>initAllNodes |Tier 2|Time 217( 214+3 )ms|AST 33|Inlined 5Y 0N|IR 5/ 5|CodeSize 88|Timestamp 2406446396050691|Src n/a
[engine] opt done id=1083 AWFYSomSet>>forEach: <split-1083> |Tier 2|Time 2302(1210+1092)ms|AST 23|Inlined 23Y 1N|IR 1720/ 3925|CodeSize 14529|Timestamp 2406446479995529|Src n/a
[engine] opt done id=757 Behavior>>new <split-757> |Tier 2|Time 94( 86+9 )ms|AST 25|Inlined 0Y 0N|IR 99/ 215|CodeSize 758|Timestamp 2406446577613530|Src n/a
[engine] opt done id=756 AWFYHavlakLoopFinder class>>new:lsg: |Tier 2|Time 343( 325+19 )ms|AST 33|Inlined 14Y 0N|IR 261/ 850|CodeSize 2759|Timestamp 2406446741293521|Src n/a
[engine] opt done id=765 AWFYSomDictionary>>removeAll |Tier 2|Time 116( 108+8 )ms|AST 30|Inlined 0Y 0N|IR 145/ 325|CodeSize 913|Timestamp 2406446859695864|Src n/a
[engine] opt done id=1249 Object>>~= <split-1249> |Tier 2|Time 155( 150+5 )ms|AST 25|Inlined 1Y 0N|IR 102/ 137|CodeSize 284|Timestamp 2406447029333196|Src n/a
[engine] opt done id=804 Symbol>>= <split-804> |Tier 2|Time 79( 76+3 )ms|AST 25|Inlined 0Y 0N|IR 27/ 39|CodeSize 185|Timestamp 2406447110342178|Src n/a
[engine] opt done id=1082 [] in AWFYLoopStructureGraph>>calculateNestingLevelRec:depth: |Tier 2|Time 2929(1262+1667)ms|AST 84|Inlined 23Y 1N|IR 1726/ 4996|CodeSize 18761|Timestamp 2406447167444479|Src n/a
[engine] opt done id=1191 AWFYLoopTesterApp>>findLoops: <split-1191> |Tier 2|Time 6125(2508+3617)ms|AST 41|Inlined 36Y 16N|IR 7205/ 29775|CodeSize 108645|Timestamp 2406453296094174|Src n/a
[engine] opt done id=754 [] in AWFYLoopTesterApp>>addDummyLoops: |Tier 2|Time 6804(2264+4540)ms|AST 20|Inlined 37Y 16N|IR 7248/ 29850|CodeSize 111374|Timestamp 2406453665686853|Src n/a
[engine] opt done id=1190 Integer>>timesRepeat: <split-1190> |Tier 2|Time 8321(2651+5671)ms|AST 45|Inlined 38Y 16N|IR 7386/ 30605|CodeSize 117903|Timestamp 2406455433330145|Src n/a
[engine] opt done id=939 AWFYLoopTesterApp>>buildStraight:n: <split-939> |Tier 2|Time 2596(1162+1434)ms|AST 94|Inlined 30Y 0N|IR 3074/ 9160|CodeSize 39057|Timestamp 2406456272306447|Src n/a
[engine] opt done id=1193 AWFYHavlakLoopFinder>>initAllNodes <split-1193> |Tier 2|Time 3647(2561+1086)ms|AST 63|Inlined 80Y 1N|IR 4426/ 8571|CodeSize 38962|Timestamp 2406456949916994|Src n/a
[engine] opt done id=967 AWFYLoopTesterApp>>buildStraight:n: <split-967> |Tier 2|Time 2521(1153+1368)ms|AST 94|Inlined 30Y 0N|IR 3074/ 9160|CodeSize 39025|Timestamp 2406457961365909|Src n/a
[engine] opt done id=799 [] in AWFYSomSet>>contains: |Tier 2|Time 38( 35+3 )ms|AST 14|Inlined 0Y 0N|IR 29/ 37|CodeSize 166|Timestamp 2406458004379539|Src n/a
[engine] opt done id=995 AWFYLoopTesterApp>>buildStraight:n: <split-995> |Tier 2|Time 2426(1140+1286)ms|AST 94|Inlined 29Y 0N|IR 2849/ 8932|CodeSize 40043|Timestamp 2406458703621855|Src n/a
[engine] opt done id=1020 AWFYLoopTesterApp>>buildStraight:n: <split-1020> |Tier 2|Time 2343(1060+1284)ms|AST 94|Inlined 29Y 0N|IR 2849/ 8932|CodeSize 40043|Timestamp 2406459301977223|Src n/a
[engine] opt done id=861 [] in [] in [] in AWFYLoopTesterApp>>constructCFG:p:p: |Tier 2|Time 3461(2508+952 )ms|AST 25|Inlined 40Y 15N|IR 2076/ 6383|CodeSize 24605|Timestamp 2406462169296948|Src n/a
[engine] opt done id=950 AWFYControlFlowGraph>>createNode: <split-950> |Tier 2|Time 232( 205+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406462482636221|Src n/a
[engine] opt done id=1221 Integer>>timesRepeat: <split-1221> |Tier 2|Time 4923(2644+2279)ms|AST 45|Inlined 41Y 15N|IR 2269/ 13434|CodeSize 54404|Timestamp 2406462928761253|Src n/a
[engine] opt done id=951 AWFYControlFlowGraph>>createNode: <split-951> |Tier 2|Time 714( 501+213 )ms|AST 112|Inlined 14Y 0N|IR 990/ 3432|CodeSize 13365|Timestamp 2406463198826374|Src n/a
[engine] opt done id=955 AWFYControlFlowGraph>>createNode: <split-955> |Tier 2|Time 266( 239+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406463468198287|Src n/a
[engine] opt done id=949 AWFYBasicBlockEdge>>init:from:to: <split-949> |Tier 2|Time 1676( 967+709 )ms|AST 95|Inlined 26Y 0N|IR 2887/ 9137|CodeSize 38709|Timestamp 2406463854896025|Src n/a
[engine] opt done id=956 AWFYControlFlowGraph>>createNode: <split-956> |Tier 2|Time 824( 622+202 )ms|AST 112|Inlined 14Y 0N|IR 990/ 3432|CodeSize 13402|Timestamp 2406464294124793|Src n/a
[engine] opt done id=960 AWFYControlFlowGraph>>createNode: <split-960> |Tier 2|Time 231( 204+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406464527651594|Src n/a
[engine] opt done id=954 AWFYBasicBlockEdge>>init:from:to: <split-954> |Tier 2|Time 1803(1156+646 )ms|AST 95|Inlined 26Y 0N|IR 2887/ 9137|CodeSize 38706|Timestamp 2406464741874484|Src n/a
[engine] opt done id=994 AWFYControlFlowGraph>>createNode: <split-994> |Tier 2|Time 233( 206+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406464762772533|Src n/a
[engine] opt done id=961 AWFYControlFlowGraph>>createNode: <split-961> |Tier 2|Time 865( 668+196 )ms|AST 112|Inlined 14Y 0N|IR 990/ 3432|CodeSize 13369|Timestamp 2406465611203308|Src n/a
[engine] opt done id=959 AWFYBasicBlockEdge>>init:from:to: <split-959> |Tier 2|Time 1768(1028+740 )ms|AST 95|Inlined 26Y 0N|IR 2887/ 9137|CodeSize 38706|Timestamp 2406465627267538|Src n/a
[engine] opt done id=965 AWFYControlFlowGraph>>createNode: <split-965> |Tier 2|Time 225( 198+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406465838988798|Src n/a
[engine] opt done id=966 AWFYControlFlowGraph>>createNode: <split-966> |Tier 2|Time 220( 193+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406465851706206|Src n/a
[engine] opt done id=964 AWFYBasicBlockEdge>>init:from:to: <split-964> |Tier 2|Time 1203( 818+384 )ms|AST 95|Inlined 16Y 0N|IR 2275/ 6300|CodeSize 25437|Timestamp 2406465967453889|Src n/a
[engine] opt done id=978 AWFYControlFlowGraph>>createNode: <split-978> |Tier 2|Time 257( 199+57 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406466110543151|Src n/a
[engine] opt done id=979 AWFYControlFlowGraph>>createNode: <split-979> |Tier 2|Time 797( 548+249 )ms|AST 112|Inlined 14Y 0N|IR 990/ 3432|CodeSize 13365|Timestamp 2406466767640568|Src n/a
[engine] opt done id=983 AWFYControlFlowGraph>>createNode: <split-983> |Tier 2|Time 290( 263+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406467060403359|Src n/a
[engine] opt done id=977 AWFYBasicBlockEdge>>init:from:to: <split-977> |Tier 2|Time 1845(1176+669 )ms|AST 95|Inlined 26Y 0N|IR 2887/ 9137|CodeSize 38677|Timestamp 2406467685377973|Src n/a
[engine] opt done id=984 AWFYControlFlowGraph>>createNode: <split-984> |Tier 2|Time 706( 550+156 )ms|AST 91|Inlined 13Y 0N|IR 778/ 3179|CodeSize 12213|Timestamp 2406467768060786|Src n/a
[engine] opt done id=982 AWFYBasicBlockEdge>>init:from:to: <split-982> |Tier 2|Time 1703(1085+618 )ms|AST 95|Inlined 25Y 0N|IR 2655/ 8907|CodeSize 37709|Timestamp 2406467815118919|Src n/a
[engine] opt done id=988 AWFYControlFlowGraph>>createNode: <split-988> |Tier 2|Time 280( 224+56 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406468050626937|Src n/a
[engine] opt done id=989 AWFYControlFlowGraph>>createNode: <split-989> |Tier 2|Time 753( 561+192 )ms|AST 91|Inlined 13Y 0N|IR 778/ 3179|CodeSize 12213|Timestamp 2406468572223590|Src n/a
[engine] opt done id=993 AWFYControlFlowGraph>>createNode: <split-993> |Tier 2|Time 259( 232+28 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406468834100040|Src n/a
[engine] opt done id=992 AWFYBasicBlockEdge>>init:from:to: <split-992> |Tier 2|Time 1185( 712+473 )ms|AST 95|Inlined 16Y 0N|IR 2275/ 6300|CodeSize 25437|Timestamp 2406469237560178|Src n/a
[engine] opt done id=987 AWFYBasicBlockEdge>>init:from:to: <split-987> |Tier 2|Time 1749(1049+701 )ms|AST 95|Inlined 25Y 0N|IR 2655/ 8907|CodeSize 37709|Timestamp 2406469439214011|Src n/a
[engine] opt done id=1006 AWFYControlFlowGraph>>createNode: <split-1006> |Tier 2|Time 232( 205+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406469472856706|Src n/a
[engine] opt done id=1007 AWFYControlFlowGraph>>createNode: <split-1007> |Tier 2|Time 239( 211+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406469682281750|Src n/a
[engine] opt done id=1012 AWFYControlFlowGraph>>createNode: <split-1012> |Tier 2|Time 235( 208+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406469919093841|Src n/a
[engine] opt done id=1005 AWFYBasicBlockEdge>>init:from:to: <split-1005> |Tier 2|Time 1170( 763+408 )ms|AST 95|Inlined 16Y 0N|IR 2275/ 6300|CodeSize 25437|Timestamp 2406470006270957|Src n/a
[engine] opt done id=1013 AWFYControlFlowGraph>>createNode: <split-1013> |Tier 2|Time 328( 223+105 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406470248772604|Src n/a
[engine] opt done id=1018 AWFYControlFlowGraph>>createNode: <split-1018> |Tier 2|Time 253( 169+85 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406470503770740|Src n/a
[engine] opt done id=1011 AWFYBasicBlockEdge>>init:from:to: <split-1011> |Tier 2|Time 1148( 769+379 )ms|AST 95|Inlined 16Y 0N|IR 2275/ 6300|CodeSize 25437|Timestamp 2406470622641882|Src n/a
[engine] opt done id=1019 AWFYControlFlowGraph>>createNode: <split-1019> |Tier 2|Time 195( 167+28 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406470700400778|Src n/a
[engine] opt done id=1017 AWFYBasicBlockEdge>>init:from:to: <split-1017> |Tier 2|Time 1131( 745+386 )ms|AST 95|Inlined 16Y 0N|IR 2275/ 6300|CodeSize 25437|Timestamp 2406471140624486|Src n/a
[engine] opt done id=972 AWFYControlFlowGraph>>createNode: <split-972> |Tier 2|Time 305( 278+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406471449377822|Src n/a
[engine] opt done id=973 AWFYControlFlowGraph>>createNode: <split-973> |Tier 2|Time 756( 540+217 )ms|AST 112|Inlined 14Y 0N|IR 990/ 3432|CodeSize 13366|Timestamp 2406472207244431|Src n/a
[engine] opt done id=998 Behavior>>new <split-998> |Tier 2|Time 65( 60+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2406472274521091|Src n/a
[engine] opt done id=971 AWFYBasicBlockEdge>>init:from:to: <split-971> |Tier 2|Time 1749(1163+586 )ms|AST 95|Inlined 26Y 0N|IR 2887/ 9137|CodeSize 38677|Timestamp 2406472451476482|Src n/a
[engine] opt done id=997 AWFYBasicBlockEdge class>>for:from:to: <split-997> |Tier 2|Time 1826(1073+753 )ms|AST 36|Inlined 27Y 0N|IR 2691/ 8762|CodeSize 38466|Timestamp 2406472451856368|Src n/a
[engine] opt done id=1000 AWFYControlFlowGraph>>createNode: <split-1000> |Tier 2|Time 284( 257+28 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406472742986398|Src n/a
[engine] opt done id=1001 AWFYControlFlowGraph>>createNode: <split-1001> |Tier 2|Time 733( 577+157 )ms|AST 91|Inlined 13Y 0N|IR 778/ 3179|CodeSize 12213|Timestamp 2406473192360961|Src n/a
[engine] opt done id=1023 Behavior>>new <split-1023> |Tier 2|Time 166( 161+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2406473360620747|Src n/a
[engine] opt done id=999 AWFYBasicBlockEdge>>init:from:to: <split-999> |Tier 2|Time 1754(1050+705 )ms|AST 95|Inlined 25Y 0N|IR 2655/ 8907|CodeSize 37709|Timestamp 2406474030030614|Src n/a
[engine] opt done id=1025 AWFYControlFlowGraph>>createNode: <split-1025> |Tier 2|Time 226( 199+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406474260616672|Src n/a
[engine] opt done id=1022 AWFYBasicBlockEdge class>>for:from:to: <split-1022> |Tier 2|Time 2075(1115+960 )ms|AST 36|Inlined 27Y 0N|IR 2691/ 8762|CodeSize 38466|Timestamp 2406474820066614|Src n/a
[engine] opt done id=1026 AWFYControlFlowGraph>>createNode: <split-1026> |Tier 2|Time 751( 566+186 )ms|AST 91|Inlined 13Y 0N|IR 778/ 3179|CodeSize 12213|Timestamp 2406475013765895|Src n/a
[engine] opt done id=1024 AWFYBasicBlockEdge>>init:from:to: <split-1024> |Tier 2|Time 1703(1063+640 )ms|AST 95|Inlined 25Y 0N|IR 2655/ 8907|CodeSize 37709|Timestamp 2406475065267692|Src n/a
[engine] opt done id=944 AWFYControlFlowGraph>>createNode: <split-944> |Tier 2|Time 220( 193+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406475236482960|Src n/a
[engine] opt done id=834 Object>>~= <split-834> |Tier 2|Time 114( 109+5 )ms|AST 25|Inlined 1Y 0N|IR 102/ 137|CodeSize 284|Timestamp 2406475352418386|Src n/a
[engine] opt done id=945 AWFYControlFlowGraph>>createNode: <split-945> |Tier 2|Time 802( 612+190 )ms|AST 112|Inlined 14Y 0N|IR 990/ 3432|CodeSize 13400|Timestamp 2406475871668675|Src n/a
[engine] opt done id=943 AWFYBasicBlockEdge>>init:from:to: <split-943> |Tier 2|Time 1835(1117+717 )ms|AST 95|Inlined 26Y 0N|IR 2887/ 9137|CodeSize 38674|Timestamp 2406476659166027|Src n/a
[engine] opt done id=1059 [] in AWFYHavlakLoopFinder>>initAllNodes <split-1059> |Tier 2|Time 1328(1049+279 )ms|AST 33|Inlined 22Y 0N|IR 1665/ 3542|CodeSize 15899|Timestamp 2406477991981836|Src n/a
[engine] opt done id=1214 AWFYLoopTesterApp>>buildStraight:n: <split-1214> |Tier 2|Time 2719(1273+1445)ms|AST 94|Inlined 30Y 0N|IR 3074/ 9160|CodeSize 40013|Timestamp 2406478072977619|Src n/a
[engine] opt done id=1222 AWFYLoopTesterApp>>buildStraight:n: <split-1222> |Tier 2|Time 2644(1258+1386)ms|AST 94|Inlined 29Y 0N|IR 2849/ 8932|CodeSize 40043|Timestamp 2406478518684703|Src n/a
[engine] opt done id=833 AWFYSomSet>>add: <split-833> |Tier 2|Time 551( 333+218 )ms|AST 39|Inlined 5Y 0N|IR 819/ 2239|CodeSize 8769|Timestamp 2406478546887817|Src n/a
[engine] opt done id=1064 AWFYSimpleLoop class>>basicBlock:reducible: <split-1064> |Tier 2|Time 573( 410+163 )ms|AST 33|Inlined 14Y 0N|IR 509/ 1420|CodeSize 3976|Timestamp 2406479121552399|Src n/a
[engine] opt done id=670 AWFYLoopStructureGraph>>initialize |Tier 2|Time 993( 769+224 )ms|AST 108|Inlined 23Y 0N|IR 1306/ 3713|CodeSize 12454|Timestamp 2406479516065073|Src n/a
[engine] opt done id=1229 AWFYLoopTesterApp>>buildConnect:end: <split-1229> |Tier 2|Time 1742( 925+817 )ms|AST 28|Inlined 19Y 0N|IR 2368/ 6212|CodeSize 26277|Timestamp 2406481261223185|Src n/a
[engine] opt done id=1212 Integer>>timesRepeat: <split-1212> |Tier 2|Time 4813(2727+2085)ms|AST 45|Inlined 42Y 18N|IR 3058/ 10221|CodeSize 40117|Timestamp 2406482890482751|Src n/a
[engine] opt done id=668 AWFYLoopStructureGraph class>>new |Tier 2|Time 1767(1442+325 )ms|AST 25|Inlined 49Y 0N|IR 1648/ 3976|CodeSize 10341|Timestamp 2406483032129160|Src n/a
[engine] opt done id=1067 AWFYLoopTesterApp>>findLoops: <split-1067> |Tier 2|Time 7251(2546+4705)ms|AST 41|Inlined 25Y 28N|IR 8701/ 30815|CodeSize 115192|Timestamp 2406490954364519|Src n/a
[engine] opt done id=970 Behavior>>new <split-970> |Tier 2|Time 126( 121+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2406491086524191|Src n/a
[engine] opt done id=1063 [] in AWFYLoopTesterApp>>main:loop:p:p:p: |Tier 2|Time 7969(2714+5256)ms|AST 28|Inlined 26Y 31N|IR 8437/ 29626|CodeSize 109032|Timestamp 2406491432579464|Src n/a
[engine] opt done id=1062 Integer>>timesRepeat: <split-1062> |Tier 2|Time 9873(2958+6915)ms|AST 45|Inlined 27Y 31N|IR 8565/ 30274|CodeSize 112573|Timestamp 2406492910628291|Src n/a
[engine] opt done id=969 AWFYBasicBlockEdge class>>for:from:to: <split-969> |Tier 2|Time 2046(1183+863 )ms|AST 36|Inlined 28Y 0N|IR 2920/ 8990|CodeSize 38788|Timestamp 2406493133865423|Src n/a
[engine] opt done id=1217 Behavior>>new <split-1217> |Tier 2|Time 95( 91+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2406493233333545|Src n/a
[engine] opt done id=1215 AWFYLoopTesterApp>>buildConnect:end: <split-1215> |Tier 2|Time 2395(1273+1122)ms|AST 28|Inlined 29Y 0N|IR 2973/ 8959|CodeSize 38103|Timestamp 2406493833804870|Src n/a
[engine] opt done id=1219 AWFYControlFlowGraph>>createNode: <split-1219> |Tier 2|Time 306( 254+51 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406494144042271|Src n/a
[engine] opt done id=1220 AWFYControlFlowGraph>>createNode: <split-1220> |Tier 2|Time 1033( 759+275 )ms|AST 112|Inlined 14Y 0N|IR 990/ 3432|CodeSize 13175|Timestamp 2406495179311627|Src n/a
[engine] opt done id=1216 AWFYBasicBlockEdge class>>for:from:to: <split-1216> |Tier 2|Time 2263(1166+1097)ms|AST 36|Inlined 28Y 0N|IR 2920/ 8990|CodeSize 39604|Timestamp 2406495179721756|Src n/a
[engine] opt done id=1218 AWFYBasicBlockEdge>>init:from:to: <split-1218> |Tier 2|Time 2050(1248+802 )ms|AST 95|Inlined 26Y 0N|IR 2887/ 9137|CodeSize 39937|Timestamp 2406495284660122|Src n/a
[engine] opt done id=753 Integer>>timesRepeat: |Tier 2|Time 150( 100+50 )ms|AST 45|Inlined 0Y 0N|IR 175/ 1181|CodeSize 4095|Timestamp 2406495335044403|Src n/a
[engine] opt done id=755 AWFYLoopTesterApp>>findLoops: |Tier 2|Time 7185(3202+3983)ms|AST 41|Inlined 36Y 16N|IR 7259/ 30670|CodeSize 112300|Timestamp 2406502474326896|Src n/a
[engine] opt done id=769 AWFYHavlakLoopFinder>>initAllNodes |Tier 2|Time 7298(4752+2545)ms|AST 63|Inlined 69Y 11N|IR 5296/ 11635|CodeSize 51679|Timestamp 2406502633974193|Src n/a
[engine] opt done id=1069 AWFYHavlakLoopFinder>>initAllNodes <split-1069> |Tier 2|Time 7503(4895+2607)ms|AST 63|Inlined 69Y 9N|IR 5588/ 12567|CodeSize 55846|Timestamp 2406502685604854|Src n/a
[engine] opt done id=1055 AWFYDictEntry>>next: |Tier 2|Time 38( 33+5 )ms|AST 10|Inlined 0Y 0N|IR 67/ 194|CodeSize 482|Timestamp 2406503995777978|Src n/a
[engine] opt done id=1061 [] in AWFYUnionFindNode>>findSet |Tier 2|Time 111( 104+7 )ms|AST 21|Inlined 1Y 0N|IR 107/ 240|CodeSize 510|Timestamp 2406521421234543|Src n/a
[engine] opt done id=1203 Integer>>timesRepeat: <split-1203> |Tier 2|Time 4932(2353+2579)ms|AST 45|Inlined 45Y 21N|IR 3820/ 13778|CodeSize 57372|Timestamp 2406581806136468|Src n/a
[engine] opt done id=1208 Behavior>>new <split-1208> |Tier 2|Time 103( 99+5 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2406589714574034|Src n/a
[engine] opt done id=1205 AWFYControlFlowGraph>>createNode: <split-1205> |Tier 2|Time 1070( 788+282 )ms|AST 112|Inlined 14Y 0N|IR 975/ 3423|CodeSize 13183|Timestamp 2406590681311725|Src n/a
[engine] opt done id=1210 AWFYControlFlowGraph>>createNode: <split-1210> |Tier 2|Time 398( 360+39 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406591082633516|Src n/a
[engine] opt done id=1211 AWFYControlFlowGraph>>createNode: <split-1211> |Tier 2|Time 267( 240+27 )ms|AST 75|Inlined 4Y 0N|IR 379/ 599|CodeSize 2109|Timestamp 2406591351189725|Src n/a
[engine] opt done id=1209 AWFYBasicBlockEdge>>init:from:to: <split-1209> |Tier 2|Time 1654(1083+571 )ms|AST 95|Inlined 16Y 0N|IR 2275/ 6300|CodeSize 25437|Timestamp 2406591369435209|Src n/a
[engine] opt done id=1207 AWFYBasicBlockEdge class>>for:from:to: <split-1207> |Tier 2|Time 1819(1081+737 )ms|AST 36|Inlined 18Y 0N|IR 2310/ 6154|CodeSize 27228|Timestamp 2406591430221826|Src n/a
[engine] opt done id=1237 Behavior>>new <split-1237> |Tier 2|Time 107( 103+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2406591540532307|Src n/a
[engine] opt done id=1238 AWFYBasicBlockEdge>>init:from:to: <split-1238> |Tier 2|Time 1740(1155+584 )ms|AST 95|Inlined 16Y 0N|IR 2275/ 6300|CodeSize 25437|Timestamp 2406593290821578|Src n/a
[engine] opt done id=1236 AWFYBasicBlockEdge class>>for:from:to: <split-1236> |Tier 2|Time 1942(1205+737 )ms|AST 36|Inlined 18Y 0N|IR 2310/ 6154|CodeSize 27228|Timestamp 2406593323451177|Src n/a
[engine] opt done id=1235 AWFYLoopTesterApp>>buildConnect:end: <split-1235> |Tier 2|Time 2033(1099+933 )ms|AST 28|Inlined 19Y 0N|IR 2368/ 6212|CodeSize 26277|Timestamp 2406593385579861|Src n/a
[engine] opt done id=1092 SmallInteger>>printString |Tier 2|Time 309( 294+15 )ms|AST 149|Inlined 4Y 1N|IR 221/ 316|CodeSize 1129|Timestamp 2406631267134143|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 156( 146+10 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1107|Timestamp 2406813922698323|Src n/a
[engine] opt done id=663 AWFYControlFlowGraph>>initialize |Tier 2|Time 235( 216+19 )ms|AST 33|Inlined 8Y 0N|IR 120/ 614|CodeSize 1770|Timestamp 2406826726691869|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 233
Success : 216
Temporary Bailouts : 5
org.graalvm.compiler.core.common.CancellationBailoutException: Compilation cancelled.: 4
org.graalvm.compiler.core.common.RetryableBailoutException: Assumption invalidated while compiling code: Object[Instance<org.graalvm.compiler.truffle.runtime.OptimizedAssumption>]: 1
Permanent Bailouts : 0
Failed : 0
Interrupted : 12
Invalidated : 5
Latest layout assumption Layout no longer valid: 3
Profiled Argument Types : 2
Queues : 359
Dequeues : 142
Target inlined into only caller : 139
Split call node : 3
Splits : 636
Compilation Accuracy : 0.978541
Queue Accuracy : 0.604457
Compilation Utilization : 0.694180
Remaining Compilation Queue : 0
Time to queue : count= 359, sum= 8554365, min= 4, average= 23828.32, max= 420350 (milliseconds), maxTarget=AWFYControlFlowGraph>>initialize
Time waiting in queue : count= 233, sum= 4365036, min= 0, average= 18734.06, max= 87056 (milliseconds), maxTarget=AWFYHavlakLoopFinder>>initAllNodes
Time for compilation : count= 221, sum= 292839, min= 38, average= 1325.06, max= 9873 (milliseconds), maxTarget=Integer>>timesRepeat: <split-1062>
Truffle Tier : count= 216, sum= 156660, min= 33, average= 725.28, max= 4895 (milliseconds), maxTarget=AWFYHavlakLoopFinder>>initAllNodes <split-1069>
Graal Tier : count= 216, sum= 90482, min= 1, average= 418.90, max= 5393 (milliseconds), maxTarget=Integer>>timesRepeat: <split-1062>
Code Installation : count= 216, sum= 33806, min= 1, average= 156.51, max= 1522 (milliseconds), maxTarget=Integer>>timesRepeat: <split-1062>
Truffle node count : count= 221, sum= 256118, min= 11, average= 1158.90, max= 6366, maxTarget=AWFYHavlakLoopFinder>>initAllNodes <split-1069>
Trivial : count= 221, sum= 97200, min= 4, average= 439.82, max= 2365, maxTarget=AWFYHavlakLoopFinder>>initAllNodes <split-1069>
Non Trivial : count= 221, sum= 158918, min= 7, average= 719.09, max= 4001, maxTarget=AWFYHavlakLoopFinder>>initAllNodes <split-1069>
Monomorphic : count= 221, sum= 156571, min= 7, average= 708.47, max= 3962, maxTarget=AWFYHavlakLoopFinder>>initAllNodes <split-1069>
Polymorphic : count= 221, sum= 2347, min= 0, average= 10.62, max= 42, maxTarget=AWFYLoopStructureGraph class>>new
Megamorphic : count= 221, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new <split-666>
Truffle call count : count= 221, sum= 3224, min= 0, average= 14.59, max= 81, maxTarget=AWFYHavlakLoopFinder>>initAllNodes <split-1193>
Indirect : count= 221, sum= 1, min= 0, average= 0.00, max= 1, maxTarget=Integer>>timesRepeat:
Direct : count= 221, sum= 3223, min= 0, average= 14.58, max= 81, maxTarget=AWFYHavlakLoopFinder>>initAllNodes <split-1193>
Dispatched : count= 221, sum= 378, min= 0, average= 1.71, max= 31, maxTarget=Integer>>timesRepeat: <split-1062>
Inlined : count= 221, sum= 2845, min= 0, average= 12.87, max= 80, maxTarget=AWFYHavlakLoopFinder>>initAllNodes <split-1193>
---------- :
Cloned : count= 221, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new <split-666>
Not Cloned : count= 221, sum= 3228, min= 0, average= 14.61, max= 81, maxTarget=AWFYHavlakLoopFinder>>initAllNodes <split-1193>
Truffle loops : count= 221, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new <split-666>
Graal node count :
After Truffle Tier : count= 221, sum= 322464, min= 5, average= 1459.11, max= 8701, maxTarget=AWFYLoopTesterApp>>findLoops: <split-1067>
After Graal Tier : count= 217, sum= 1003682, min= 5, average= 4625.26, max= 31153, maxTarget=AWFYHavlakLoopFinder>>findLoops
Graal compilation result :
Code size : count= 216, sum= 4002003, min= 88, average= 18527.79, max= 117903, maxTarget=Integer>>timesRepeat: <split-1190>
Total frame size : count= 216, sum= 72560, min= 32, average= 335.93, max= 1632, maxTarget=Integer>>timesRepeat: <split-1062>
Exception handlers : count= 216, sum= 421, min= 0, average= 1.95, max= 33, maxTarget=[] in AWFYLoopTesterApp>>main:loop:p:p:p:
Infopoints : count= 216, sum= 33938, min= 4, average= 157.12, max= 1060, maxTarget=AWFYHavlakLoopFinder>>findLoops
CALL : count= 216, sum= 28577, min= 4, average= 132.30, max= 909, maxTarget=AWFYHavlakLoopFinder>>findLoops
IMPLICIT_EXCEPTION : count= 216, sum= 4980, min= 0, average= 23.06, max= 156, maxTarget=AWFYLoopTesterApp>>findLoops:
SAFEPOINT : count= 216, sum= 381, min= 0, average= 1.76, max= 9, maxTarget=AWFYSomSet>>forEach:
Marks : count= 216, sum= 2097, min= 5, average= 9.71, max= 42, maxTarget=[] in AWFYLoopTesterApp>>main:loop:p:p:p:
Data references : count= 216, sum= 25258, min= 0, average= 116.94, max= 631, maxTarget=Integer>>timesRepeat: <split-1221>
Raw
c4528635-Json.trace.log
# Json (iterations: 250, problem size: 100) on Tue May 3 07:02:12 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Json.trace.log" --quiet --code "AWFYHarness run: #('Json' 250 100)"`
[engine] opt done id=9 String>>compareWith: |Tier 2|Time 185( 166+19 )ms|AST 23|Inlined 0Y 0N|IR 150/ 226|CodeSize 646|Timestamp 2405682213108882|Src n/a
[engine] opt done id=8 String>>= |Tier 2|Time 317( 272+45 )ms|AST 73|Inlined 1Y 0N|IR 263/ 385|CodeSize 1122|Timestamp 2405682320036329|Src n/a
[engine] opt done id=689 SequenceableCollection>>atAllPut: |Tier 2|Time 292( 247+45 )ms|AST 71|Inlined 0Y 0N|IR 209/ 422|CodeSize 1577|Timestamp 2405682326303364|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 223( 200+23 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1083|Timestamp 2405682457004308|Src n/a
[engine] opt done id=672 Character>>asString |Tier 2|Time 259( 250+9 )ms|AST 19|Inlined 4Y 1N|IR 130/ 194|CodeSize 663|Timestamp 2405682581741762|Src n/a
[engine] opt done id=696 AWFYJsonParser>>read <split-696> |Tier 2|Time 635( 592+43 )ms|AST 104|Inlined 7Y 1N|IR 607/ 783|CodeSize 2246|Timestamp 2405683221964163|Src n/a
[engine] opt done id=690 AWFYJsonParser>>readChar: |Tier 2|Time 710( 654+55 )ms|AST 38|Inlined 10Y 1N|IR 955/ 1112|CodeSize 3371|Timestamp 2405683322792691|Src n/a
[engine] opt done id=717 AWFYVector>>append: |Tier 2|Time 330( 256+74 )ms|AST 160|Inlined 0Y 0N|IR 564/ 1784|CodeSize 7285|Timestamp 2405683656309695|Src n/a
[engine] opt done id=693 AWFYJsonParser>>readStringInternal |Tier 2|Time 1958(1638+320 )ms|AST 110|Inlined 36Y 4N|IR 2870/ 3201|CodeSize 10636|Timestamp 2405684417664162|Src n/a
[engine] opt done id=728 AWFYJsonArray>>add: |Tier 2|Time 383( 263+120 )ms|AST 32|Inlined 1Y 0N|IR 522/ 1798|CodeSize 7606|Timestamp 2405684807636238|Src n/a
[engine] opt done id=676 AWFYJsonParser>>readValue |Tier 2|Time 4542(2890+1652)ms|AST 530|Inlined 62Y 39N|IR 7301/ 11139|CodeSize 39874|Timestamp 2405688191783487|Src n/a
[engine] opt done id=723 AWFYJsonParser>>readArrayElement: |Tier 2|Time 4629(2741+1888)ms|AST 57|Inlined 55Y 36N|IR 7691/ 11973|CodeSize 43618|Timestamp 2405688288038437|Src n/a
[engine] opt done id=673 String class>>with: |Tier 2|Time 225( 219+6 )ms|AST 61|Inlined 3Y 1N|IR 91/ 185|CodeSize 640|Timestamp 2405688523397779|Src n/a
[engine] opt done id=700 AWFYJsonParser>>read <split-700> |Tier 2|Time 396( 358+37 )ms|AST 108|Inlined 7Y 1N|IR 637/ 861|CodeSize 2663|Timestamp 2405688597878539|Src n/a
[engine] opt done id=704 AWFYJsonParser>>isDigit |Tier 2|Time 1024( 892+133 )ms|AST 195|Inlined 20Y 0N|IR 2851/ 2291|CodeSize 6502|Timestamp 2405689625652824|Src n/a
[engine] opt done id=718 AWFYJsonParser>>readArray |Tier 2|Time 4831(2787+2044)ms|AST 132|Inlined 53Y 43N|IR 7727/ 11952|CodeSize 44942|Timestamp 2405689641139164|Src n/a
[engine] opt done id=703 AWFYJsonParser>>readDigit |Tier 2|Time 1388(1138+250 )ms|AST 33|Inlined 29Y 1N|IR 3492/ 2961|CodeSize 8439|Timestamp 2405689913768885|Src n/a
[engine] opt done id=681 AWFYVector class>>new |Tier 2|Time 199( 193+6 )ms|AST 19|Inlined 3Y 0N|IR 45/ 218|CodeSize 747|Timestamp 2405690192343027|Src n/a
[engine] opt done id=722 AWFYJsonArray>>initialize |Tier 2|Time 143( 134+8 )ms|AST 19|Inlined 4Y 0N|IR 90/ 361|CodeSize 1001|Timestamp 2405690337341902|Src n/a
[engine] opt done id=695 AWFYJsonParser>>startCapture |Tier 2|Time 47( 43+4 )ms|AST 11|Inlined 0Y 0N|IR 85/ 94|CodeSize 241|Timestamp 2405690385964088|Src n/a
[engine] opt done id=731 AWFYJsonParser>>readRequiredChar: |Tier 2|Time 512( 454+58 )ms|AST 21|Inlined 11Y 1N|IR 994/ 1103|CodeSize 3059|Timestamp 2405690439159153|Src n/a
[engine] opt done id=698 SequenceableCollection>>copyFrom:to: <split-698> |Tier 2|Time 245( 230+15 )ms|AST 67|Inlined 3Y 1N|IR 224/ 510|CodeSize 2187|Timestamp 2405690687763376|Src n/a
[engine] opt done id=697 AWFYJsonParser>>endCapture |Tier 2|Time 387( 339+49 )ms|AST 63|Inlined 6Y 1N|IR 569/ 894|CodeSize 3429|Timestamp 2405690774924322|Src n/a
[engine] opt done id=725 AWFYJsonString class>>new: |Tier 2|Time 153( 148+5 )ms|AST 30|Inlined 2Y 0N|IR 39/ 106|CodeSize 399|Timestamp 2405690843235201|Src n/a
[engine] opt done id=727 AWFYJsonString>>initializeWith: |Tier 2|Time 40( 36+5 )ms|AST 10|Inlined 0Y 0N|IR 66/ 174|CodeSize 415|Timestamp 2405690885778583|Src n/a
[engine] opt done id=726 Behavior>>new <split-726> |Tier 2|Time 120( 116+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2405690898741641|Src n/a
[engine] opt done id=706 Object>>~= |Tier 2|Time 156( 138+18 )ms|AST 25|Inlined 2Y 0N|IR 301/ 368|CodeSize 916|Timestamp 2405691043576730|Src n/a
[engine] opt done id=707 AWFYJsonParser>>readFraction |Tier 2|Time 555( 512+43 )ms|AST 20|Inlined 11Y 1N|IR 994/ 644|CodeSize 1607|Timestamp 2405691455454653|Src n/a
[engine] opt done id=709 AWFYJsonNumber class>>new: |Tier 2|Time 167( 162+5 )ms|AST 39|Inlined 2Y 0N|IR 39/ 106|CodeSize 399|Timestamp 2405691626101730|Src n/a
[engine] opt done id=687 AWFYHashIndexTable>>initialize |Tier 2|Time 274( 237+36 )ms|AST 23|Inlined 2Y 0N|IR 278/ 536|CodeSize 1559|Timestamp 2405691901892905|Src n/a
[engine] opt done id=715 AWFYHashIndexTable>>hashSlotFor: |Tier 2|Time 145( 139+6 )ms|AST 46|Inlined 1Y 0N|IR 60/ 201|CodeSize 717|Timestamp 2405692048836330|Src n/a
[engine] opt done id=708 AWFYJsonParser>>readExponent |Tier 2|Time 1006( 899+107 )ms|AST 50|Inlined 22Y 2N|IR 1851/ 1030|CodeSize 2606|Timestamp 2405692051628935|Src n/a
[engine] opt done id=713 AWFYVector>>size |Tier 2|Time 48( 44+4 )ms|AST 17|Inlined 0Y 0N|IR 40/ 115|CodeSize 411|Timestamp 2405692099071581|Src n/a
[engine] opt done id=702 AWFYJsonParser>>readNumber |Tier 2|Time 3878(2276+1602)ms|AST 133|Inlined 58Y 27N|IR 6904/ 10731|CodeSize 39435|Timestamp 2405693529024929|Src n/a
[engine] opt done id=692 AWFYJsonParser>>readName |Tier 2|Time 1666(1364+301 )ms|AST 34|Inlined 39Y 4N|IR 3187/ 3411|CodeSize 11135|Timestamp 2405693766919288|Src n/a
[engine] opt done id=694 AWFYJsonParser>>read <split-694> |Tier 2|Time 440( 409+32 )ms|AST 104|Inlined 7Y 1N|IR 607/ 783|CodeSize 2246|Timestamp 2405693979440355|Src n/a
[engine] opt done id=699 AWFYJsonParser>>read <split-699> |Tier 2|Time 533( 361+172 )ms|AST 104|Inlined 7Y 1N|IR 607/ 783|CodeSize 2246|Timestamp 2405694306705550|Src n/a
[engine] opt done id=712 AWFYJsonObject>>add:with: |Tier 2|Time 738( 562+176 )ms|AST 97|Inlined 6Y 0N|IR 1131/ 3672|CodeSize 15574|Timestamp 2405694719809319|Src n/a
[engine] opt done id=751 AWFYJsonParser>>skipWhiteSpace <split-751> |Tier 2|Time 447( 371+76 )ms|AST 18|Inlined 9Y 0N|IR 1229/ 1136|CodeSize 3098|Timestamp 2405695169506880|Src n/a
[engine] opt done id=753 AWFYJsonParser>>skipWhiteSpace <split-753> |Tier 2|Time 569( 489+80 )ms|AST 18|Inlined 9Y 0N|IR 1229/ 1136|CodeSize 3098|Timestamp 2405695741684301|Src n/a
[engine] opt done id=691 AWFYJsonParser>>readObjectKeyValuePair: |Tier 2|Time 3907(2491+1416)ms|AST 116|Inlined 51Y 26N|IR 6173/ 11187|CodeSize 43159|Timestamp 2405695963506182|Src n/a
[engine] opt done id=737 AWFYJsonParser>>read <split-737> |Tier 2|Time 423( 392+31 )ms|AST 104|Inlined 7Y 1N|IR 607/ 783|CodeSize 2246|Timestamp 2405696510561892|Src n/a
[engine] opt done id=738 AWFYJsonLiteral class>>NULL |Tier 2|Time 195( 192+3 )ms|AST 9|Inlined 0Y 0N|IR 21/ 29|CodeSize 175|Timestamp 2405696708482320|Src n/a
[engine] opt done id=719 AWFYJsonParser>>read <split-719> |Tier 2|Time 435( 387+48 )ms|AST 104|Inlined 7Y 1N|IR 607/ 783|CodeSize 2246|Timestamp 2405697144913557|Src n/a
[engine] opt done id=720 AWFYJsonArray class>>new |Tier 2|Time 262( 254+8 )ms|AST 25|Inlined 11Y 0N|IR 63/ 334|CodeSize 1110|Timestamp 2405697409453712|Src n/a
[engine] opt done id=736 AWFYJsonParser>>readNull |Tier 2|Time 1796(1540+255 )ms|AST 75|Inlined 45Y 4N|IR 3341/ 3299|CodeSize 9888|Timestamp 2405697769179213|Src n/a
[engine] opt done id=759 AWFYJsonParser>>skipWhiteSpace <split-759> |Tier 2|Time 550( 474+76 )ms|AST 18|Inlined 9Y 0N|IR 1229/ 1136|CodeSize 3098|Timestamp 2405697962252481|Src n/a
[engine] opt done id=680 AWFYJsonObject>>initialize |Tier 2|Time 559( 456+102 )ms|AST 47|Inlined 16Y 0N|IR 662/ 1547|CodeSize 4112|Timestamp 2405698523702717|Src n/a
[engine] opt done id=677 AWFYJsonParser>>readObject |Tier 2|Time 4556(2682+1874)ms|AST 127|Inlined 57Y 36N|IR 6865/ 11552|CodeSize 42698|Timestamp 2405698865575815|Src n/a
[engine] opt done id=679 Behavior>>new <split-679> |Tier 2|Time 652( 428+223 )ms|AST 27|Inlined 17Y 0N|IR 657/ 1515|CodeSize 4198|Timestamp 2405699183541662|Src n/a
[engine] opt done id=701 AWFYJsonParser>>read <split-701> |Tier 2|Time 473( 361+112 )ms|AST 104|Inlined 7Y 1N|IR 607/ 783|CodeSize 2246|Timestamp 2405699349859199|Src n/a
[engine] opt done id=678 AWFYJsonObject class>>new |Tier 2|Time 1128( 733+395 )ms|AST 25|Inlined 35Y 0N|IR 1203/ 2195|CodeSize 5838|Timestamp 2405699654703371|Src n/a
[engine] opt done id=749 AWFYJsonParser>>skipWhiteSpace <split-749> |Tier 2|Time 511( 389+122 )ms|AST 18|Inlined 9Y 0N|IR 1229/ 1136|CodeSize 3098|Timestamp 2405699697881294|Src n/a
[engine] opt done id=732 AWFYJsonLiteral class>>TRUE |Tier 2|Time 37( 34+3 )ms|AST 9|Inlined 0Y 0N|IR 21/ 29|CodeSize 175|Timestamp 2405699756338746|Src n/a
[engine] opt done id=730 AWFYJsonParser>>read <split-730> |Tier 2|Time 404( 372+32 )ms|AST 104|Inlined 7Y 1N|IR 607/ 783|CodeSize 2246|Timestamp 2405700104554870|Src n/a
[engine] opt done id=674 AWFYJsonParser>>skipWhiteSpace |Tier 2|Time 537( 392+146 )ms|AST 18|Inlined 13Y 0N|IR 1351/ 1380|CodeSize 4392|Timestamp 2405700295284495|Src n/a
[engine] opt done id=744 AWFYVector>>at: |Tier 2|Time 78( 73+5 )ms|AST 38|Inlined 0Y 0N|IR 90/ 124|CodeSize 471|Timestamp 2405700376331157|Src n/a
[engine] opt done id=671 Object>>= |Tier 2|Time 37( 35+2 )ms|AST 13|Inlined 0Y 0N|IR 19/ 20|CodeSize 124|Timestamp 2405700415461852|Src n/a
[engine] opt done id=734 AWFYJsonParser>>read <split-734> |Tier 2|Time 404( 373+32 )ms|AST 104|Inlined 7Y 1N|IR 607/ 783|CodeSize 2246|Timestamp 2405701017484100|Src n/a
[engine] opt done id=735 AWFYJsonLiteral class>>FALSE |Tier 2|Time 35( 32+3 )ms|AST 9|Inlined 0Y 0N|IR 21/ 29|CodeSize 175|Timestamp 2405701055040982|Src n/a
[engine] opt done id=729 AWFYJsonParser>>readTrue |Tier 2|Time 1672(1400+272 )ms|AST 75|Inlined 45Y 4N|IR 3342/ 3328|CodeSize 10124|Timestamp 2405701330909686|Src n/a
[engine] opt done id=741 AWFYJsonObject>>at: |Tier 2|Time 429( 389+40 )ms|AST 59|Inlined 8Y 0N|IR 555/ 729|CodeSize 2141|Timestamp 2405701485425964|Src n/a
[engine] opt done id=733 AWFYJsonParser>>readFalse |Tier 2|Time 2039(1754+285 )ms|AST 90|Inlined 57Y 5N|IR 4226/ 4163|CodeSize 12749|Timestamp 2405702456265971|Src n/a
[engine] opt done id=665 AWFYJson class>>RapBenchmarkMinified |Tier 2|Time 31( 28+3 )ms|AST 7|Inlined 0Y 0N|IR 17/ 20|CodeSize 124|Timestamp 2405703336554137|Src n/a
[engine] opt done id=666 AWFYJsonParser class>>with: |Tier 2|Time 165( 153+12 )ms|AST 30|Inlined 2Y 0N|IR 193/ 299|CodeSize 1003|Timestamp 2405703471260331|Src n/a
[engine] opt done id=669 AWFYJsonParser>>parse |Tier 2|Time 4128(2562+1565)ms|AST 81|Inlined 56Y 37N|IR 7480/ 12335|CodeSize 43514|Timestamp 2405707600906503|Src n/a
[engine] opt done id=740 AWFYJson>>verifyResult: |Tier 2|Time 1161(1074+87 )ms|AST 125|Inlined 29Y 0N|IR 1609/ 1536|CodeSize 4322|Timestamp 2405708771395039|Src n/a
[engine] opt done id=664 AWFYJson>>benchmark |Tier 2|Time 5771(2505+3265)ms|AST 39|Inlined 56Y 35N|IR 6119/ 26374|CodeSize 102850|Timestamp 2405709071675342|Src n/a
[engine] opt done id=663 AWFYBenchmark>>innerBenchmarkLoop: |Tier 2|Time 6141(2588+3553)ms|AST 58|Inlined 65Y 33N|IR 6055/ 25885|CodeSize 101295|Timestamp 2405709511104667|Src n/a
[engine] opt done id=771 SmallInteger>>printString |Tier 2|Time 268( 250+18 )ms|AST 149|Inlined 4Y 1N|IR 274/ 382|CodeSize 1169|Timestamp 2405802235831236|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 79
Success : 70
Temporary Bailouts : 2
org.graalvm.compiler.core.common.CancellationBailoutException: Compilation cancelled.: 2
Permanent Bailouts : 0
Failed : 0
Interrupted : 7
Invalidated : 0
Queues : 122
Dequeues : 51
Target inlined into only caller : 48
Split call node : 3
Splits : 215
Compilation Accuracy : 1.000000
Queue Accuracy : 0.581967
Compilation Utilization : 0.375356
Remaining Compilation Queue : 0
Time to queue : count= 122, sum= 878229, min= 84, average= 7198.60, max= 188074 (milliseconds), maxTarget=SmallInteger>>printString
Time waiting in queue : count= 79, sum= 512250, min= 0, average= 6484.18, max= 17819 (milliseconds), maxTarget=AWFYJsonParser>>isWhiteSpace
Time for compilation : count= 72, sum= 74292, min= 31, average= 1031.83, max= 6141 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle Tier : count= 70, sum= 50013, min= 27, average= 714.48, max= 2889 (milliseconds), maxTarget=AWFYJsonParser>>readValue
Graal Tier : count= 70, sum= 16438, min= 1, average= 234.83, max= 2318 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Code Installation : count= 70, sum= 7211, min= 1, average= 103.03, max= 1236 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle node count : count= 72, sum= 98814, min= 11, average= 1372.42, max= 5814, maxTarget=AWFYJsonParser>>readValue
Trivial : count= 72, sum= 36778, min= 4, average= 510.81, max= 2122, maxTarget=AWFYJsonParser>>readValue
Non Trivial : count= 72, sum= 62036, min= 7, average= 861.61, max= 3692, maxTarget=AWFYJsonParser>>readValue
Monomorphic : count= 72, sum= 60503, min= 7, average= 840.32, max= 3594, maxTarget=AWFYJsonParser>>readValue
Polymorphic : count= 72, sum= 1533, min= 0, average= 21.29, max= 112, maxTarget=AWFYJsonParser>>readNumber
Megamorphic : count= 72, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=String>>compareWith:
Truffle call count : count= 72, sum= 1480, min= 0, average= 20.56, max= 101, maxTarget=AWFYJsonParser>>readValue
Indirect : count= 72, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=String>>compareWith:
Direct : count= 72, sum= 1480, min= 0, average= 20.56, max= 101, maxTarget=AWFYJsonParser>>readValue
Dispatched : count= 72, sum= 355, min= 0, average= 4.93, max= 43, maxTarget=AWFYJsonParser>>readArray
Inlined : count= 72, sum= 1125, min= 0, average= 15.63, max= 65, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
---------- :
Cloned : count= 72, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=String>>compareWith:
Not Cloned : count= 72, sum= 1480, min= 0, average= 20.56, max= 101, maxTarget=AWFYJsonParser>>readValue
Truffle loops : count= 72, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=String>>compareWith:
Graal node count :
After Truffle Tier : count= 72, sum= 113891, min= 17, average= 1581.82, max= 7727, maxTarget=AWFYJsonParser>>readArray
After Graal Tier : count= 70, sum= 194290, min= 20, average= 2775.57, max= 26374, maxTarget=AWFYJson>>benchmark
Graal compilation result :
Code size : count= 70, sum= 693069, min= 124, average= 9900.99, max= 102850, maxTarget=AWFYJson>>benchmark
Total frame size : count= 70, sum= 11744, min= 32, average= 167.77, max= 832, maxTarget=AWFYJsonParser>>readObject
Exception handlers : count= 70, sum= 293, min= 0, average= 4.19, max= 41, maxTarget=AWFYJsonParser>>readArray
Infopoints : count= 70, sum= 6950, min= 4, average= 99.29, max= 1100, maxTarget=AWFYJson>>benchmark
CALL : count= 70, sum= 5656, min= 4, average= 80.80, max= 844, maxTarget=AWFYJson>>benchmark
IMPLICIT_EXCEPTION : count= 70, sum= 1265, min= 0, average= 18.07, max= 255, maxTarget=AWFYJson>>benchmark
SAFEPOINT : count= 70, sum= 29, min= 0, average= 0.41, max= 4, maxTarget=AWFYJsonObject class>>new
Marks : count= 70, sum= 742, min= 6, average= 10.60, max= 50, maxTarget=AWFYJsonParser>>readArray
Data references : count= 70, sum= 6498, min= 2, average= 92.83, max= 780, maxTarget=AWFYJson>>benchmark
Raw
c4528635-List.trace.log
# List (iterations: 250, problem size: 1500) on Tue May 3 07:22:16 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/List.trace.log" --quiet --code "AWFYHarness run: #('List' 250 1500)"`
[engine] opt done id=672 AWFYList>>isShorter:than: <split-672> |Tier 2|Time 259( 228+31 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406886805553801|Src n/a
[engine] opt done id=692 AWFYList>>isShorter:than: <split-692> |Tier 2|Time 261( 230+31 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406886805683223|Src n/a
[engine] opt done id=670 AWFYList>>isShorter:than: <split-670> |Tier 2|Time 297( 266+31 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406886805680220|Src n/a
[engine] opt done id=690 AWFYList>>isShorter:than: <split-690> |Tier 2|Time 127( 110+17 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406886943084554|Src n/a
[engine] opt done id=665 AWFYList>>isShorter:than: <split-665> |Tier 2|Time 128( 111+17 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406886943626759|Src n/a
[engine] opt done id=688 AWFYList>>isShorter:than: <split-688> |Tier 2|Time 127( 110+18 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406887073887228|Src n/a
[engine] opt done id=674 AWFYList>>isShorter:than: <split-674> |Tier 2|Time 128( 111+17 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406887074197478|Src n/a
[engine] opt done id=686 AWFYList>>isShorter:than: <split-686> |Tier 2|Time 154( 99+55 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406887231665567|Src n/a
[engine] opt done id=684 AWFYList>>isShorter:than: <split-684> |Tier 2|Time 155( 100+55 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406887232234453|Src n/a
[engine] opt done id=676 AWFYList>>isShorter:than: <split-676> |Tier 2|Time 122( 105+17 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406887356678387|Src n/a
[engine] opt done id=682 AWFYList>>isShorter:than: <split-682> |Tier 2|Time 122( 105+17 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406887357449753|Src n/a
[engine] opt done id=750 AWFYList>>isShorter:than: <split-750> |Tier 2|Time 148( 135+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406887553519662|Src n/a
[engine] opt done id=736 AWFYList>>isShorter:than: <split-736> |Tier 2|Time 203( 139+64 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406887563366241|Src n/a
[engine] opt done id=678 AWFYList>>isShorter:than: <split-678> |Tier 2|Time 125( 108+17 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406887681440680|Src n/a
[engine] opt done id=748 AWFYList>>isShorter:than: <split-748> |Tier 2|Time 116( 102+14 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406887681540139|Src n/a
[engine] opt done id=746 AWFYList>>isShorter:than: <split-746> |Tier 2|Time 109( 96+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406887793352502|Src n/a
[engine] opt done id=680 AWFYList>>isShorter:than: <split-680> |Tier 2|Time 113( 96+17 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406887797344901|Src n/a
[engine] opt done id=720 AWFYList>>isShorter:than: <split-720> |Tier 2|Time 125( 109+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406887920834615|Src n/a
[engine] opt done id=734 AWFYList>>isShorter:than: <split-734> |Tier 2|Time 127( 110+17 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406887926304440|Src n/a
[engine] opt done id=730 AWFYList>>isShorter:than: <split-730> |Tier 2|Time 177( 161+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406888100513488|Src n/a
[engine] opt done id=689 AWFYList>>talkWithX:withY:withZ: <split-689> |Tier 2|Time 3137(1929+1208)ms|AST 134|Inlined 33Y 24N|IR 4277/ 8266|CodeSize 34023|Timestamp 2406891239919380|Src n/a
[engine] opt done id=664 AWFYList>>talkWithX:withY:withZ: <split-664> |Tier 2|Time 3339(1960+1379)ms|AST 134|Inlined 33Y 28N|IR 4380/ 8759|CodeSize 36549|Timestamp 2406891267219335|Src n/a
[engine] opt done id=662 AWFYList>>talkWithX:withY:withZ: |Tier 2|Time 4645(2376+2268)ms|AST 134|Inlined 41Y 44N|IR 6212/ 12468|CodeSize 53179|Timestamp 2406891460782445|Src n/a
[engine] opt done id=758 AWFYList>>isShorter:than: <split-758> |Tier 2|Time 117( 104+14 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406891588670845|Src n/a
[engine] opt done id=744 AWFYList>>isShorter:than: <split-744> |Tier 2|Time 121( 105+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406891712468994|Src n/a
[engine] opt done id=738 AWFYList>>isShorter:than: <split-738> |Tier 2|Time 122( 105+17 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406891836742927|Src n/a
[engine] opt done id=760 AWFYList>>isShorter:than: <split-760> |Tier 2|Time 121( 104+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406891959846260|Src n/a
[engine] opt done id=702 AWFYList>>isShorter:than: <split-702> |Tier 2|Time 164( 148+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406892126139239|Src n/a
[engine] opt done id=722 AWFYList>>isShorter:than: <split-722> |Tier 2|Time 164( 148+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406892143551336|Src n/a
[engine] opt done id=708 AWFYList>>isShorter:than: <split-708> |Tier 2|Time 116( 100+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406892244282334|Src n/a
[engine] opt done id=728 AWFYList>>isShorter:than: <split-728> |Tier 2|Time 116( 99+17 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406892261646518|Src n/a
[engine] opt done id=742 AWFYList>>isShorter:than: <split-742> |Tier 2|Time 109( 96+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406892355520295|Src n/a
[engine] opt done id=740 AWFYList>>isShorter:than: <split-740> |Tier 2|Time 108( 96+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406892372265584|Src n/a
[engine] opt done id=754 AWFYList>>isShorter:than: <split-754> |Tier 2|Time 114( 98+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406892471899670|Src n/a
[engine] opt done id=704 AWFYList>>isShorter:than: <split-704> |Tier 2|Time 113( 97+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406892487592747|Src n/a
[engine] opt done id=724 AWFYList>>isShorter:than: <split-724> |Tier 2|Time 135( 99+36 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406892608687554|Src n/a
[engine] opt done id=712 AWFYList>>isShorter:than: <split-712> |Tier 2|Time 129( 95+33 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406892618279200|Src n/a
[engine] opt done id=718 AWFYList>>isShorter:than: <split-718> |Tier 2|Time 109( 78+32 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406892720761696|Src n/a
[engine] opt done id=756 AWFYList>>isShorter:than: <split-756> |Tier 2|Time 109( 96+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406892728806699|Src n/a
[engine] opt done id=706 AWFYList>>isShorter:than: <split-706> |Tier 2|Time 108( 95+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406892830714512|Src n/a
[engine] opt done id=726 AWFYList>>isShorter:than: <split-726> |Tier 2|Time 108( 95+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406892839152182|Src n/a
[engine] opt done id=714 AWFYList>>isShorter:than: <split-714> |Tier 2|Time 109( 96+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406892941709692|Src n/a
[engine] opt done id=716 AWFYList>>isShorter:than: <split-716> |Tier 2|Time 109( 96+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406892950126059|Src n/a
[engine] opt done id=762 AWFYList>>isShorter:than: <split-762> |Tier 2|Time 193( 176+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406893136255099|Src n/a
[engine] opt done id=768 AWFYList>>isShorter:than: <split-768> |Tier 2|Time 192( 176+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406893144251210|Src n/a
[engine] opt done id=776 AWFYList>>isShorter:than: <split-776> |Tier 2|Time 145( 117+28 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406893283608125|Src n/a
[engine] opt done id=770 AWFYList>>isShorter:than: <split-770> |Tier 2|Time 135( 118+17 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406893297307972|Src n/a
[engine] opt done id=764 AWFYList>>isShorter:than: <split-764> |Tier 2|Time 132( 100+32 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406893417459036|Src n/a
[engine] opt done id=782 AWFYList>>isShorter:than: <split-782> |Tier 2|Time 125( 95+29 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406893423762738|Src n/a
[engine] opt done id=784 AWFYList>>isShorter:than: <split-784> |Tier 2|Time 117( 101+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406893536699952|Src n/a
[engine] opt done id=778 AWFYList>>isShorter:than: <split-778> |Tier 2|Time 130( 114+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406893579533738|Src n/a
[engine] opt done id=774 AWFYList>>isShorter:than: <split-774> |Tier 2|Time 118( 93+25 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406893641045768|Src n/a
[engine] opt done id=772 AWFYList>>isShorter:than: <split-772> |Tier 2|Time 119( 105+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406893657359765|Src n/a
[engine] opt done id=766 AWFYList>>isShorter:than: <split-766> |Tier 2|Time 103( 91+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406893685403497|Src n/a
[engine] opt done id=780 AWFYList>>isShorter:than: <split-780> |Tier 2|Time 103( 91+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406893746337701|Src n/a
[engine] opt done id=677 AWFYList>>talkWithX:withY:withZ: <split-677> |Tier 2|Time 6667(3299+3368)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69027|Timestamp 2406900354437033|Src n/a
[engine] opt done id=675 AWFYList>>talkWithX:withY:withZ: <split-675> |Tier 2|Time 6739(3285+3455)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15666|CodeSize 70545|Timestamp 2406900398537454|Src n/a
[engine] opt done id=679 AWFYList>>talkWithX:withY:withZ: <split-679> |Tier 2|Time 6713(3336+3376)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69027|Timestamp 2406900460794099|Src n/a
[engine] opt done id=658 AWFYListElement class>>new: |Tier 2|Time 193( 187+6 )ms|AST 30|Inlined 2Y 0N|IR 40/ 113|CodeSize 425|Timestamp 2406900665500597|Src n/a
[engine] opt done id=661 AWFYListElement>>next: |Tier 2|Time 53( 48+5 )ms|AST 10|Inlined 0Y 0N|IR 62/ 102|CodeSize 370|Timestamp 2406900720627276|Src n/a
[engine] opt done id=696 AWFYList>>isShorter:than: <split-696> |Tier 2|Time 126( 113+14 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406900848638114|Src n/a
[engine] opt done id=657 AWFYList>>makeList: |Tier 2|Time 525( 441+84 )ms|AST 73|Inlined 14Y 1N|IR 386/ 888|CodeSize 3376|Timestamp 2406900935033539|Src n/a
[engine] opt done id=752 AWFYList>>isShorter:than: <split-752> |Tier 2|Time 159( 128+31 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406901009161704|Src n/a
[engine] opt done id=669 AWFYList>>isShorter:than: <split-669> |Tier 2|Time 183( 139+44 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406901121122488|Src n/a
[engine] opt done id=739 AWFYList>>talkWithX:withY:withZ: <split-739> |Tier 2|Time 285( 188+97 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406901408506083|Src n/a
[engine] opt done id=741 AWFYList>>talkWithX:withY:withZ: <split-741> |Tier 2|Time 218( 187+31 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406901628807247|Src n/a
[engine] opt done id=681 AWFYList>>talkWithX:withY:withZ: <split-681> |Tier 2|Time 8198(4066+4132)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69027|Timestamp 2406908563912437|Src n/a
[engine] opt done id=732 AWFYList>>isShorter:than: <split-732> |Tier 2|Time 117( 104+12 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406908692324185|Src n/a
[engine] opt done id=737 AWFYList>>talkWithX:withY:withZ: <split-737> |Tier 2|Time 8343(4552+3791)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15666|CodeSize 70389|Timestamp 2406909354213187|Src n/a
[engine] opt done id=700 AWFYList>>isShorter:than: <split-700> |Tier 2|Time 155( 124+31 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406909538814512|Src n/a
[engine] opt done id=710 AWFYList>>isShorter:than: <split-710> |Tier 2|Time 167( 131+36 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406909708107674|Src n/a
[engine] opt done id=743 AWFYList>>talkWithX:withY:withZ: <split-743> |Tier 2|Time 8152(4736+3416)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69027|Timestamp 2406909782348359|Src n/a
[engine] opt done id=755 AWFYList>>talkWithX:withY:withZ: <split-755> |Tier 2|Time 241( 210+31 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406909954283051|Src n/a
[engine] opt done id=753 AWFYList>>talkWithX:withY:withZ: <split-753> |Tier 2|Time 8559(4178+4381)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69027|Timestamp 2406917253161169|Src n/a
[engine] opt done id=757 AWFYList>>talkWithX:withY:withZ: <split-757> |Tier 2|Time 8378(4837+3541)ms|AST 129|Inlined 41Y 64N|IR 7035/ 15624|CodeSize 70263|Timestamp 2406918183857777|Src n/a
[engine] opt done id=759 AWFYList>>talkWithX:withY:withZ: <split-759> |Tier 2|Time 8242(4719+3523)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15666|CodeSize 70322|Timestamp 2406918210863686|Src n/a
[engine] opt done id=705 AWFYList>>talkWithX:withY:withZ: <split-705> |Tier 2|Time 162( 142+20 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406918384308144|Src n/a
[engine] opt done id=701 AWFYList>>talkWithX:withY:withZ: <split-701> |Tier 2|Time 6543(2728+3814)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15666|CodeSize 70430|Timestamp 2406923806955437|Src n/a
[engine] opt done id=667 AWFYList>>isShorter:than: <split-667> |Tier 2|Time 141( 125+16 )ms|AST 74|Inlined 0Y 0N|IR 226/ 386|CodeSize 1497|Timestamp 2406923958787332|Src n/a
[engine] opt done id=698 AWFYList>>isShorter:than: <split-698> |Tier 2|Time 85( 73+12 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406924045830218|Src n/a
[engine] opt done id=703 AWFYList>>talkWithX:withY:withZ: <split-703> |Tier 2|Time 6376(3433+2943)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69027|Timestamp 2406924570988051|Src n/a
[engine] opt done id=707 AWFYList>>talkWithX:withY:withZ: <split-707> |Tier 2|Time 6444(3456+2988)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69027|Timestamp 2406924829701826|Src n/a
[engine] opt done id=725 AWFYList>>talkWithX:withY:withZ: <split-725> |Tier 2|Time 142( 126+16 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406924983253020|Src n/a
[engine] opt done id=721 AWFYList>>talkWithX:withY:withZ: <split-721> |Tier 2|Time 5754(2636+3118)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15666|CodeSize 70564|Timestamp 2406929801785253|Src n/a
[engine] opt done id=694 AWFYList>>isShorter:than: <split-694> |Tier 2|Time 86( 73+12 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406929898971419|Src n/a
[engine] opt done id=723 AWFYList>>talkWithX:withY:withZ: <split-723> |Tier 2|Time 5708(2779+2929)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69027|Timestamp 2406930290020475|Src n/a
[engine] opt done id=713 AWFYList>>talkWithX:withY:withZ: <split-713> |Tier 2|Time 144( 128+16 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406930445313947|Src n/a
[engine] opt done id=715 AWFYList>>talkWithX:withY:withZ: <split-715> |Tier 2|Time 144( 128+16 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406930590694348|Src n/a
[engine] opt done id=727 AWFYList>>talkWithX:withY:withZ: <split-727> |Tier 2|Time 5607(2898+2709)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69027|Timestamp 2406930591641234|Src n/a
[engine] opt done id=717 AWFYList>>talkWithX:withY:withZ: <split-717> |Tier 2|Time 143( 127+16 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406930735560971|Src n/a
[engine] opt done id=683 AWFYList>>talkWithX:withY:withZ: <split-683> |Tier 2|Time 4746(2378+2367)ms|AST 134|Inlined 33Y 48N|IR 5466/ 11740|CodeSize 52288|Timestamp 2406935482953074|Src n/a
[engine] opt done id=711 AWFYList>>talkWithX:withY:withZ: <split-711> |Tier 2|Time 5922(2527+3395)ms|AST 129|Inlined 41Y 64N|IR 7035/ 15624|CodeSize 70263|Timestamp 2406935822019793|Src n/a
[engine] opt done id=691 AWFYList>>talkWithX:withY:withZ: <split-691> |Tier 2|Time 1327( 755+573 )ms|AST 134|Inlined 17Y 8N|IR 2021/ 3723|CodeSize 14198|Timestamp 2406936819250065|Src n/a
[engine] opt done id=673 AWFYList>>talkWithX:withY:withZ: <split-673> |Tier 2|Time 6269(2974+3295)ms|AST 134|Inlined 41Y 64N|IR 7088/ 16304|CodeSize 72698|Timestamp 2406936872025909|Src n/a
[engine] opt done id=687 AWFYList>>talkWithX:withY:withZ: <split-687> |Tier 2|Time 2412(1299+1113)ms|AST 134|Inlined 17Y 16N|IR 2452/ 4909|CodeSize 20903|Timestamp 2406939295484422|Src n/a
[engine] opt done id=671 AWFYList>>talkWithX:withY:withZ: <split-671> |Tier 2|Time 6136(2930+3206)ms|AST 134|Inlined 41Y 44N|IR 6169/ 12865|CodeSize 54834|Timestamp 2406941969110923|Src n/a
[engine] opt done id=747 AWFYList>>talkWithX:withY:withZ: <split-747> |Tier 2|Time 228( 212+16 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406942206840390|Src n/a
[engine] opt done id=745 AWFYList>>talkWithX:withY:withZ: <split-745> |Tier 2|Time 132( 115+16 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406942339973577|Src n/a
[engine] opt done id=749 AWFYList>>talkWithX:withY:withZ: <split-749> |Tier 2|Time 132( 116+16 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406942473106484|Src n/a
[engine] opt done id=796 AWFYList>>isShorter:than: <split-796> |Tier 2|Time 115( 101+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406942589414479|Src n/a
[engine] opt done id=685 AWFYList>>talkWithX:withY:withZ: <split-685> |Tier 2|Time 5799(3109+2691)ms|AST 134|Inlined 33Y 48N|IR 5527/ 11764|CodeSize 52521|Timestamp 2406942623097131|Src n/a
[engine] opt done id=798 AWFYList>>isShorter:than: <split-798> |Tier 2|Time 107( 94+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406942698135443|Src n/a
[engine] opt done id=800 AWFYList>>isShorter:than: <split-800> |Tier 2|Time 108( 94+13 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406942757686721|Src n/a
[engine] opt done id=814 AWFYList>>isShorter:than: <split-814> |Tier 2|Time 125( 96+29 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406942824729202|Src n/a
[engine] opt done id=731 AWFYList>>talkWithX:withY:withZ: <split-731> |Tier 2|Time 128( 111+17 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406942887282827|Src n/a
[engine] opt done id=735 AWFYList>>talkWithX:withY:withZ: <split-735> |Tier 2|Time 3787(2277+1510)ms|AST 134|Inlined 25Y 32N|IR 3966/ 9401|CodeSize 40185|Timestamp 2406943101013065|Src n/a
[engine] opt done id=733 AWFYList>>talkWithX:withY:withZ: <split-733> |Tier 2|Time 563( 464+99 )ms|AST 134|Inlined 9Y 0N|IR 864/ 1391|CodeSize 4501|Timestamp 2406943670418345|Src n/a
[engine] opt done id=729 AWFYList>>talkWithX:withY:withZ: <split-729> |Tier 2|Time 5300(2308+2992)ms|AST 134|Inlined 33Y 48N|IR 5466/ 11740|CodeSize 52288|Timestamp 2406948188944715|Src n/a
[engine] opt done id=719 AWFYList>>talkWithX:withY:withZ: <split-719> |Tier 2|Time 5450(2251+3198)ms|AST 134|Inlined 33Y 48N|IR 5527/ 12861|CodeSize 56549|Timestamp 2406948275859367|Src n/a
[engine] opt done id=765 AWFYList>>talkWithX:withY:withZ: <split-765> |Tier 2|Time 223( 187+35 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406948507206067|Src n/a
[engine] opt done id=761 AWFYList>>talkWithX:withY:withZ: <split-761> |Tier 2|Time 7750(3336+4414)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15666|CodeSize 70493|Timestamp 2406951435701743|Src n/a
[engine] opt done id=806 AWFYList>>isShorter:than: <split-806> |Tier 2|Time 189( 174+15 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406951636047972|Src n/a
[engine] opt done id=816 AWFYList>>isShorter:than: <split-816> |Tier 2|Time 179( 152+27 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406951816699925|Src n/a
[engine] opt done id=820 AWFYList>>isShorter:than: <split-820> |Tier 2|Time 180( 153+27 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406951998607198|Src n/a
[engine] opt done id=763 AWFYList>>talkWithX:withY:withZ: <split-763> |Tier 2|Time 8528(4260+4268)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69211|Timestamp 2406956725352430|Src n/a
[engine] opt done id=767 AWFYList>>talkWithX:withY:withZ: <split-767> |Tier 2|Time 8421(4272+4149)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69211|Timestamp 2406956929985802|Src n/a
[engine] opt done id=697 AWFYList>>talkWithX:withY:withZ: <split-697> |Tier 2|Time 167( 134+34 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406956931254812|Src n/a
[engine] opt done id=666 AWFYList>>talkWithX:withY:withZ: <split-666> |Tier 2|Time 5884(3325+2559)ms|AST 134|Inlined 33Y 48N|IR 5466/ 11740|CodeSize 52249|Timestamp 2406957884392769|Src n/a
[engine] opt done id=802 AWFYList>>isShorter:than: <split-802> |Tier 2|Time 176( 149+27 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406958082226890|Src n/a
[engine] opt done id=808 AWFYList>>isShorter:than: <split-808> |Tier 2|Time 182( 147+35 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406958265614664|Src n/a
[engine] opt done id=810 AWFYList>>isShorter:than: <split-810> |Tier 2|Time 254( 226+28 )ms|AST 71|Inlined 0Y 0N|IR 166/ 328|CodeSize 1280|Timestamp 2406958520667386|Src n/a
[engine] opt done id=709 AWFYList>>talkWithX:withY:withZ: <split-709> |Tier 2|Time 2511(1287+1224)ms|AST 134|Inlined 17Y 16N|IR 2391/ 5911|CodeSize 24135|Timestamp 2406959451987157|Src n/a
[engine] opt done id=779 AWFYList>>talkWithX:withY:withZ: <split-779> |Tier 2|Time 155( 138+16 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406959611238106|Src n/a
[engine] opt done id=699 AWFYList>>talkWithX:withY:withZ: <split-699> |Tier 2|Time 6567(2819+3748)ms|AST 129|Inlined 33Y 48N|IR 5462/ 12819|CodeSize 55982|Timestamp 2406963499684197|Src n/a
[engine] opt done id=777 AWFYList>>talkWithX:withY:withZ: <split-777> |Tier 2|Time 8143(3976+4167)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69211|Timestamp 2406966665222704|Src n/a
[engine] opt done id=804 AWFYList>>isShorter:than: <split-804> |Tier 2|Time 290( 74+216 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406966965819402|Src n/a
[engine] opt done id=812 AWFYList>>isShorter:than: <split-812> |Tier 2|Time 106( 73+33 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406967073720528|Src n/a
[engine] opt done id=818 AWFYList>>isShorter:than: <split-818> |Tier 2|Time 101( 88+12 )ms|AST 71|Inlined 0Y 0N|IR 166/ 307|CodeSize 1182|Timestamp 2406967175650763|Src n/a
[engine] opt done id=781 AWFYList>>talkWithX:withY:withZ: <split-781> |Tier 2|Time 8054(4447+3607)ms|AST 129|Inlined 41Y 64N|IR 7035/ 15624|CodeSize 70488|Timestamp 2406967667132374|Src n/a
[engine] opt done id=771 AWFYList>>talkWithX:withY:withZ: <split-771> |Tier 2|Time 138( 122+16 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406967837155207|Src n/a
[engine] opt done id=773 AWFYList>>talkWithX:withY:withZ: <split-773> |Tier 2|Time 181( 165+16 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406968019423858|Src n/a
[engine] opt done id=775 AWFYList>>talkWithX:withY:withZ: <split-775> |Tier 2|Time 257( 211+46 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406968277931523|Src n/a
[engine] opt done id=783 AWFYList>>talkWithX:withY:withZ: <split-783> |Tier 2|Time 6890(3523+3367)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15666|CodeSize 70752|Timestamp 2406970412501576|Src n/a
[engine] opt done id=693 AWFYList>>talkWithX:withY:withZ: <split-693> |Tier 2|Time 202( 168+34 )ms|AST 27|Inlined 1Y 0N|IR 179/ 364|CodeSize 1163|Timestamp 2406970637285661|Src n/a
[engine] opt done id=769 AWFYList>>talkWithX:withY:withZ: <split-769> |Tier 2|Time 6886(2946+3940)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15666|CodeSize 70668|Timestamp 2406974063640907|Src n/a
[engine] opt done id=668 AWFYList>>talkWithX:withY:withZ: <split-668> |Tier 2|Time 6990(3302+3689)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15226|CodeSize 69211|Timestamp 2406975289393714|Src n/a
[engine] opt done id=793 AWFYListElement>>length |Tier 2|Time 230( 188+42 )ms|AST 42|Inlined 2Y 1N|IR 330/ 711|CodeSize 2726|Timestamp 2406975530210183|Src n/a
[engine] opt done id=695 AWFYList>>talkWithX:withY:withZ: <split-695> |Tier 2|Time 6738(3376+3362)ms|AST 129|Inlined 41Y 64N|IR 7035/ 15624|CodeSize 70488|Timestamp 2406977377230617|Src n/a
[engine] opt done id=656 AWFYList>>benchmark |Tier 2|Time 4040(2402+1638)ms|AST 75|Inlined 74Y 24N|IR 3951/ 9619|CodeSize 35881|Timestamp 2406979571657941|Src n/a
[engine] opt done id=794 AWFYList>>verifyResult: |Tier 2|Time 36( 33+3 )ms|AST 14|Inlined 0Y 0N|IR 25/ 34|CodeSize 155|Timestamp 2406979616280732|Src n/a
[engine] opt done id=826 AWFYListElement>>length <split-826> |Tier 2|Time 187( 150+37 )ms|AST 37|Inlined 2Y 1N|IR 276/ 652|CodeSize 2449|Timestamp 2406979801447942|Src n/a
[engine] opt done id=825 AWFYListElement>>length <split-825> |Tier 2|Time 216( 152+64 )ms|AST 42|Inlined 2Y 1N|IR 330/ 711|CodeSize 2726|Timestamp 2406980018866475|Src n/a
[engine] opt done id=751 AWFYList>>talkWithX:withY:withZ: <split-751> |Tier 2|Time 6110(2962+3148)ms|AST 134|Inlined 41Y 64N|IR 7100/ 15666|CodeSize 70547|Timestamp 2406980184092717|Src n/a
[engine] opt done id=655 AWFYBenchmark>>innerBenchmarkLoop: |Tier 2|Time 3499(1920+1579)ms|AST 58|Inlined 76Y 24N|IR 4044/ 9812|CodeSize 38634|Timestamp 2406983116344592|Src n/a
[engine] opt done id=831 SmallInteger>>printString |Tier 2|Time 315( 293+22 )ms|AST 149|Inlined 4Y 1N|IR 274/ 382|CodeSize 1166|Timestamp 2407055530097608|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 144( 135+9 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1107|Timestamp 2407142938392679|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 151
Success : 146
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 5
Invalidated : 0
Queues : 255
Dequeues : 108
Target inlined into only caller : 108
Splits : 335
Compilation Accuracy : 1.000000
Queue Accuracy : 0.576471
Compilation Utilization : 1.027574
Remaining Compilation Queue : 0
Time to queue : count= 255, sum= 1794606, min= 36, average= 7037.67, max= 263066 (milliseconds), maxTarget=SmallInteger>>printString
Time waiting in queue : count= 151, sum= 3949555, min= 0, average= 26156.00, max= 86348 (milliseconds), maxTarget=AWFYListElement>>length <split-826>
Time for compilation : count= 146, sum= 278296, min= 36, average= 1906.14, max= 8559 (milliseconds), maxTarget=AWFYList>>talkWithX:withY:withZ: <split-753>
Truffle Tier : count= 146, sum= 145877, min= 33, average= 999.16, max= 4837 (milliseconds), maxTarget=AWFYList>>talkWithX:withY:withZ: <split-757>
Graal Tier : count= 146, sum= 89356, min= 2, average= 612.03, max= 3310 (milliseconds), maxTarget=AWFYList>>talkWithX:withY:withZ: <split-753>
Code Installation : count= 146, sum= 43062, min= 1, average= 294.95, max= 1786 (milliseconds), maxTarget=AWFYList>>talkWithX:withY:withZ: <split-761>
Truffle node count : count= 146, sum= 269179, min= 16, average= 1843.69, max= 6699, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-675>
Trivial : count= 146, sum= 94070, min= 6, average= 644.32, max= 2331, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-675>
Non Trivial : count= 146, sum= 175109, min= 10, average= 1199.38, max= 4368, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-675>
Monomorphic : count= 146, sum= 170069, min= 10, average= 1164.86, max= 4242, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-675>
Polymorphic : count= 146, sum= 5040, min= 0, average= 34.52, max= 126, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-675>
Megamorphic : count= 146, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYList>>isShorter:than: <split-672>
Truffle call count : count= 146, sum= 4017, min= 0, average= 27.51, max= 105, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-675>
Indirect : count= 146, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYList>>isShorter:than: <split-672>
Direct : count= 146, sum= 4017, min= 0, average= 27.51, max= 105, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-675>
Dispatched : count= 146, sum= 2282, min= 0, average= 15.63, max= 64, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-675>
Inlined : count= 146, sum= 1735, min= 0, average= 11.88, max= 76, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
---------- :
Cloned : count= 146, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYList>>isShorter:than: <split-672>
Not Cloned : count= 146, sum= 4017, min= 0, average= 27.51, max= 105, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-675>
Truffle loops : count= 146, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYList>>isShorter:than: <split-672>
Graal node count :
After Truffle Tier : count= 146, sum= 284802, min= 25, average= 1950.70, max= 7100, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-675>
After Graal Tier : count= 146, sum= 614272, min= 34, average= 4207.34, max= 16304, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-673>
Graal compilation result :
Code size : count= 146, sum= 2702890, min= 155, average= 18512.95, max= 72698, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-673>
Total frame size : count= 146, sum= 74432, min= 32, average= 509.81, max= 1840, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-673>
Exception handlers : count= 146, sum= 2302, min= 0, average= 15.77, max= 64, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-677>
Infopoints : count= 146, sum= 30638, min= 4, average= 209.85, max= 829, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-673>
CALL : count= 146, sum= 24609, min= 4, average= 168.55, max= 665, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-673>
IMPLICIT_EXCEPTION : count= 146, sum= 5120, min= 0, average= 35.07, max= 143, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-677>
SAFEPOINT : count= 146, sum= 909, min= 0, average= 6.23, max= 21, maxTarget=AWFYList>>talkWithX:withY:withZ:
Marks : count= 146, sum= 4087, min= 6, average= 27.99, max= 91, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-677>
Data references : count= 146, sum= 27792, min= 2, average= 190.36, max= 743, maxTarget=AWFYList>>talkWithX:withY:withZ: <split-781>
Raw
c4528635-Mandelbrot.trace.log
# Mandelbrot (iterations: 250, problem size: 500) on Tue May 3 07:26:53 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Mandelbrot.trace.log" --quiet --code "AWFYHarness run: #('Mandelbrot' 250 500)"`
[engine] opt done id=457 Integer>><< |Tier 2|Time 128( 114+13 )ms|AST 24|Inlined 0Y 0N|IR 39/ 117|CodeSize 421|Timestamp 2407162899414423|Src n/a
[engine] opt done id=658 AWFYMandelbrot>>mandelbrot: |Tier 2|Time 442( 369+73 )ms|AST 499|Inlined 2Y 0N|IR 461/ 1071|CodeSize 7521|Timestamp 2407206968076699|Src n/a
[engine] opt done id=664 SmallInteger>>printString |Tier 2|Time 322( 298+24 )ms|AST 149|Inlined 4Y 1N|IR 274/ 381|CodeSize 1169|Timestamp 2407247722013542|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 140( 131+10 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1107|Timestamp 2407260080878287|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 5
Success : 4
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 1
Invalidated : 0
Queues : 5
Dequeues : 0
Splits : 173
Compilation Accuracy : 1.000000
Queue Accuracy : 1.000000
Compilation Utilization : 0.010408
Remaining Compilation Queue : 0
Time to queue : count= 5, sum= 279940, min= 167, average= 55988.08, max= 97633 (milliseconds), maxTarget=String class>>new:
Time waiting in queue : count= 5, sum= 8, min= 1, average= 1.73, max= 2 (milliseconds), maxTarget=Integer>><<
Time for compilation : count= 4, sum= 1044, min= 134, average= 261.06, max= 444 (milliseconds), maxTarget=AWFYMandelbrot>>mandelbrot:
Truffle Tier : count= 4, sum= 910, min= 114, average= 227.74, max= 368 (milliseconds), maxTarget=AWFYMandelbrot>>mandelbrot:
Graal Tier : count= 4, sum= 79, min= 7, average= 19.98, max= 43 (milliseconds), maxTarget=AWFYMandelbrot>>mandelbrot:
Code Installation : count= 4, sum= 53, min= 3, average= 13.35, max= 31 (milliseconds), maxTarget=AWFYMandelbrot>>mandelbrot:
Truffle node count : count= 4, sum= 1701, min= 39, average= 425.25, max= 889, maxTarget=AWFYMandelbrot>>mandelbrot:
Trivial : count= 4, sum= 655, min= 15, average= 163.75, max= 342, maxTarget=AWFYMandelbrot>>mandelbrot:
Non Trivial : count= 4, sum= 1046, min= 24, average= 261.50, max= 547, maxTarget=AWFYMandelbrot>>mandelbrot:
Monomorphic : count= 4, sum= 1046, min= 24, average= 261.50, max= 547, maxTarget=AWFYMandelbrot>>mandelbrot:
Polymorphic : count= 4, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Integer>><<
Megamorphic : count= 4, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Integer>><<
Truffle call count : count= 4, sum= 10, min= 0, average= 2.50, max= 5, maxTarget=SmallInteger>>printString
Indirect : count= 4, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Integer>><<
Direct : count= 4, sum= 10, min= 0, average= 2.50, max= 5, maxTarget=SmallInteger>>printString
Dispatched : count= 4, sum= 2, min= 0, average= 0.50, max= 1, maxTarget=SmallInteger>>printString
Inlined : count= 4, sum= 8, min= 0, average= 2.00, max= 4, maxTarget=SmallInteger>>printString
---------- :
Cloned : count= 4, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Integer>><<
Not Cloned : count= 4, sum= 10, min= 0, average= 2.50, max= 5, maxTarget=SmallInteger>>printString
Truffle loops : count= 4, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Integer>><<
Graal node count :
After Truffle Tier : count= 4, sum= 879, min= 39, average= 219.75, max= 461, maxTarget=AWFYMandelbrot>>mandelbrot:
After Graal Tier : count= 4, sum= 1898, min= 117, average= 474.50, max= 1071, maxTarget=AWFYMandelbrot>>mandelbrot:
Graal compilation result :
Code size : count= 4, sum= 10218, min= 421, average= 2554.50, max= 7521, maxTarget=AWFYMandelbrot>>mandelbrot:
Total frame size : count= 4, sum= 720, min= 32, average= 180.00, max= 592, maxTarget=AWFYMandelbrot>>mandelbrot:
Exception handlers : count= 4, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Integer>><<
Infopoints : count= 4, sum= 92, min= 8, average= 23.00, max= 53, maxTarget=AWFYMandelbrot>>mandelbrot:
CALL : count= 4, sum= 71, min= 7, average= 17.75, max= 39, maxTarget=AWFYMandelbrot>>mandelbrot:
IMPLICIT_EXCEPTION : count= 4, sum= 18, min= 1, average= 4.50, max= 11, maxTarget=AWFYMandelbrot>>mandelbrot:
SAFEPOINT : count= 4, sum= 3, min= 0, average= 0.75, max= 3, maxTarget=AWFYMandelbrot>>mandelbrot:
Marks : count= 4, sum= 27, min= 6, average= 6.75, max= 9, maxTarget=AWFYMandelbrot>>mandelbrot:
Data references : count= 4, sum= 81, min= 4, average= 20.25, max= 50, maxTarget=AWFYMandelbrot>>mandelbrot:
Raw
c4528635-NBody.trace.log
# NBody (iterations: 250, problem size: 250000) on Tue May 3 07:00:47 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/NBody.trace.log" --quiet --code "AWFYHarness run: #('NBody' 250 250000)"`
[engine] opt done id=681 AWFYBody>>vy: |Tier 2|Time 158( 142+15 )ms|AST 10|Inlined 0Y 0N|IR 81/ 98|CodeSize 253|Timestamp 2405602533704609|Src n/a
[engine] opt done id=680 AWFYBody>>vx: |Tier 2|Time 157( 142+15 )ms|AST 10|Inlined 0Y 0N|IR 81/ 98|CodeSize 253|Timestamp 2405602533699301|Src n/a
[engine] opt done id=682 AWFYBody>>vz: |Tier 2|Time 157( 143+15 )ms|AST 10|Inlined 0Y 0N|IR 81/ 98|CodeSize 253|Timestamp 2405602533703003|Src n/a
[engine] opt done id=687 AWFYBody>>z: |Tier 2|Time 69( 65+4 )ms|AST 10|Inlined 0Y 0N|IR 80/ 96|CodeSize 244|Timestamp 2405602612630224|Src n/a
[engine] opt done id=684 [] in AWFYNBodySystem>>advance: |Tier 2|Time 263( 250+13 )ms|AST 186|Inlined 3Y 0N|IR 310/ 311|CodeSize 627|Timestamp 2405602877985887|Src n/a
[engine] opt done id=683 SequenceableCollection>>do: <split-683> |Tier 2|Time 510( 401+108 )ms|AST 72|Inlined 4Y 0N|IR 498/ 2152|CodeSize 6984|Timestamp 2405603053372424|Src n/a
[engine] opt done id=679 AWFYNBodySystem>>advance: |Tier 2|Time 1171(1029+142 )ms|AST 815|Inlined 11Y 0N|IR 1775/ 1818|CodeSize 7993|Timestamp 2405603715372370|Src n/a
[engine] opt done id=658 AWFYNBody>>innerBenchmarkLoop: |Tier 2|Time 3821(2404+1417)ms|AST 92|Inlined 43Y 16N|IR 4321/ 10193|CodeSize 43812|Timestamp 2405608900211405|Src n/a
[engine] opt done id=666 AWFYBody class>>DaysPerYear |Tier 2|Time 32( 28+3 )ms|AST 7|Inlined 0Y 0N|IR 18/ 58|CodeSize 242|Timestamp 2405616034815555|Src n/a
[engine] opt done id=688 AWFYNBodySystem>>energy |Tier 2|Time 380( 331+49 )ms|AST 558|Inlined 0Y 0N|IR 643/ 985|CodeSize 5644|Timestamp 2405625035217737|Src n/a
[engine] opt done id=667 AWFYBody class>>SolarMass |Tier 2|Time 51( 48+3 )ms|AST 9|Inlined 0Y 0N|IR 23/ 67|CodeSize 293|Timestamp 2405627782140539|Src n/a
[engine] opt done id=665 AWFYBody>>initX:y:z:vx:vy:vz:mass: |Tier 2|Time 143( 131+12 )ms|AST 124|Inlined 4Y 0N|IR 311/ 331|CodeSize 1057|Timestamp 2405634556901284|Src n/a
[engine] opt done id=694 SmallInteger>>printString |Tier 2|Time 293( 272+21 )ms|AST 149|Inlined 4Y 1N|IR 274/ 382|CodeSize 1166|Timestamp 2405647232324318|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 139( 129+9 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1107|Timestamp 2405670798784914|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 15
Success : 14
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 1
Invalidated : 0
Queues : 17
Dequeues : 2
Target inlined into only caller : 2
Splits : 181
Compilation Accuracy : 1.000000
Queue Accuracy : 0.882353
Compilation Utilization : 0.099424
Remaining Compilation Queue : 0
Time to queue : count= 17, sum= 279127, min= 72, average= 16419.27, max= 72125 (milliseconds), maxTarget=SmallInteger>>printString
Time waiting in queue : count= 15, sum= 395, min= 0, average= 26.37, max= 162 (milliseconds), maxTarget=AWFYNBodySystem>>advance:
Time for compilation : count= 14, sum= 7382, min= 32, average= 527.29, max= 3822 (milliseconds), maxTarget=AWFYNBody>>innerBenchmarkLoop:
Truffle Tier : count= 14, sum= 5522, min= 28, average= 394.45, max= 2404 (milliseconds), maxTarget=AWFYNBody>>innerBenchmarkLoop:
Graal Tier : count= 14, sum= 1121, min= 2, average= 80.09, max= 820 (milliseconds), maxTarget=AWFYNBody>>innerBenchmarkLoop:
Code Installation : count= 14, sum= 738, min= 1, average= 52.75, max= 597 (milliseconds), maxTarget=AWFYNBody>>innerBenchmarkLoop:
Truffle node count : count= 14, sum= 9281, min= 11, average= 662.93, max= 4667, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Trivial : count= 14, sum= 3384, min= 4, average= 241.71, max= 1680, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Non Trivial : count= 14, sum= 5897, min= 7, average= 421.21, max= 2987, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Monomorphic : count= 14, sum= 5897, min= 7, average= 421.21, max= 2987, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Polymorphic : count= 14, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYBody>>vx:
Megamorphic : count= 14, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYBody>>vx:
Truffle call count : count= 14, sum= 89, min= 0, average= 6.36, max= 59, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Indirect : count= 14, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYBody>>vx:
Direct : count= 14, sum= 89, min= 0, average= 6.36, max= 59, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Dispatched : count= 14, sum= 18, min= 0, average= 1.29, max= 16, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Inlined : count= 14, sum= 71, min= 0, average= 5.07, max= 43, maxTarget=AWFYNBody>>innerBenchmarkLoop:
---------- :
Cloned : count= 14, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYBody>>vx:
Not Cloned : count= 14, sum= 89, min= 0, average= 6.36, max= 59, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Truffle loops : count= 14, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYBody>>vx:
Graal node count :
After Truffle Tier : count= 14, sum= 8601, min= 18, average= 614.36, max= 4321, maxTarget=AWFYNBody>>innerBenchmarkLoop:
After Graal Tier : count= 14, sum= 17016, min= 58, average= 1215.43, max= 10193, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Graal compilation result :
Code size : count= 14, sum= 69928, min= 242, average= 4994.86, max= 43812, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Total frame size : count= 14, sum= 2336, min= 32, average= 166.86, max= 1040, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Exception handlers : count= 14, sum= 16, min= 0, average= 1.14, max= 16, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Infopoints : count= 14, sum= 675, min= 5, average= 48.21, max= 431, maxTarget=AWFYNBody>>innerBenchmarkLoop:
CALL : count= 14, sum= 533, min= 5, average= 38.07, max= 329, maxTarget=AWFYNBody>>innerBenchmarkLoop:
IMPLICIT_EXCEPTION : count= 14, sum= 135, min= 0, average= 9.64, max= 99, maxTarget=AWFYNBody>>innerBenchmarkLoop:
SAFEPOINT : count= 14, sum= 7, min= 0, average= 0.50, max= 3, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Marks : count= 14, sum= 107, min= 6, average= 7.64, max= 25, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Data references : count= 14, sum= 686, min= 2, average= 49.00, max= 441, maxTarget=AWFYNBody>>innerBenchmarkLoop:
Raw
c4528635-Permute.trace.log
# Permute (iterations: 250, problem size: 1000) on Tue May 3 07:08:39 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Permute.trace.log" --quiet --code "AWFYHarness run: #('Permute' 250 1000)"`
[engine] opt done id=662 AWFYPermute>>swap:with: |Tier 2|Time 312( 292+20 )ms|AST 73|Inlined 0Y 0N|IR 242/ 186|CodeSize 489|Timestamp 2406069833089960|Src n/a
[engine] opt done id=661 AWFYPermute>>permute: |Tier 2|Time 1656(1311+345 )ms|AST 137|Inlined 20Y 8N|IR 3019/ 3994|CodeSize 21019|Timestamp 2406071168690166|Src n/a
[engine] opt done id=660 SequenceableCollection>>atAllPut: |Tier 2|Time 142( 123+19 )ms|AST 71|Inlined 0Y 0N|IR 209/ 422|CodeSize 1577|Timestamp 2406071365694376|Src n/a
[engine] opt done id=663 AWFYPermute>>verifyResult: |Tier 2|Time 67( 64+3 )ms|AST 14|Inlined 0Y 0N|IR 25/ 34|CodeSize 158|Timestamp 2406071588955678|Src n/a
[engine] opt done id=659 ArrayedCollection class>>new:withAll: |Tier 2|Time 228( 208+21 )ms|AST 30|Inlined 1Y 0N|IR 244/ 237|CodeSize 770|Timestamp 2406071747556234|Src n/a
[engine] opt done id=658 AWFYPermute>>benchmark |Tier 2|Time 1708(1318+390 )ms|AST 46|Inlined 23Y 8N|IR 3060/ 3542|CodeSize 13479|Timestamp 2406073226875943|Src n/a
[engine] opt done id=657 AWFYBenchmark>>innerBenchmarkLoop: |Tier 2|Time 1816(1351+465 )ms|AST 58|Inlined 25Y 8N|IR 3159/ 3608|CodeSize 14543|Timestamp 2406073758616981|Src n/a
[engine] opt done id=668 SmallInteger>>printString |Tier 2|Time 294( 275+19 )ms|AST 149|Inlined 4Y 1N|IR 274/ 382|CodeSize 1166|Timestamp 2406106577506057|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 136( 127+10 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1107|Timestamp 2406126662225177|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 10
Success : 9
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 1
Invalidated : 0
Queues : 10
Dequeues : 0
Splits : 173
Compilation Accuracy : 1.000000
Queue Accuracy : 1.000000
Compilation Utilization : 0.102629
Remaining Compilation Queue : 0
Time to queue : count= 10, sum= 162340, min= 25, average= 16234.04, max= 60041 (milliseconds), maxTarget=SmallInteger>>printString
Time waiting in queue : count= 10, sum= 13, min= 0, average= 1.34, max= 2 (milliseconds), maxTarget=AWFYPermute>>permute:
Time for compilation : count= 9, sum= 6378, min= 68, average= 708.73, max= 1817 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle Tier : count= 9, sum= 5067, min= 63, average= 563.01, max= 1350 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Graal Tier : count= 9, sum= 873, min= 2, average= 97.07, max= 333 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Code Installation : count= 9, sum= 437, min= 2, average= 48.65, max= 138 (milliseconds), maxTarget=AWFYPermute>>benchmark
Truffle node count : count= 9, sum= 11638, min= 22, average= 1293.11, max= 3632, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Trivial : count= 9, sum= 4595, min= 8, average= 510.56, max= 1432, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Non Trivial : count= 9, sum= 7043, min= 14, average= 782.56, max= 2200, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Monomorphic : count= 9, sum= 7035, min= 14, average= 781.67, max= 2198, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Polymorphic : count= 9, sum= 8, min= 0, average= 0.89, max= 2, maxTarget=SequenceableCollection>>atAllPut:
Megamorphic : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYPermute>>swap:with:
Truffle call count : count= 9, sum= 101, min= 0, average= 11.22, max= 33, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Indirect : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYPermute>>swap:with:
Direct : count= 9, sum= 101, min= 0, average= 11.22, max= 33, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Dispatched : count= 9, sum= 26, min= 0, average= 2.89, max= 8, maxTarget=AWFYPermute>>permute:
Inlined : count= 9, sum= 75, min= 0, average= 8.33, max= 25, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
---------- :
Cloned : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYPermute>>swap:with:
Not Cloned : count= 9, sum= 101, min= 0, average= 11.22, max= 33, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle loops : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYPermute>>swap:with:
Graal node count :
After Truffle Tier : count= 9, sum= 10337, min= 25, average= 1148.56, max= 3159, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
After Graal Tier : count= 9, sum= 12734, min= 34, average= 1414.89, max= 3994, maxTarget=AWFYPermute>>permute:
Graal compilation result :
Code size : count= 9, sum= 54308, min= 158, average= 6034.22, max= 21019, maxTarget=AWFYPermute>>permute:
Total frame size : count= 9, sum= 1840, min= 32, average= 204.44, max= 672, maxTarget=AWFYPermute>>permute:
Exception handlers : count= 9, sum= 28, min= 0, average= 3.11, max= 10, maxTarget=AWFYPermute>>benchmark
Infopoints : count= 9, sum= 427, min= 4, average= 47.44, max= 155, maxTarget=AWFYPermute>>permute:
CALL : count= 9, sum= 351, min= 4, average= 39.00, max= 123, maxTarget=AWFYPermute>>permute:
IMPLICIT_EXCEPTION : count= 9, sum= 72, min= 0, average= 8.00, max= 29, maxTarget=AWFYPermute>>permute:
SAFEPOINT : count= 9, sum= 4, min= 0, average= 0.44, max= 3, maxTarget=AWFYPermute>>permute:
Marks : count= 9, sum= 86, min= 6, average= 9.56, max= 17, maxTarget=AWFYPermute>>permute:
Data references : count= 9, sum= 404, min= 3, average= 44.89, max= 158, maxTarget=AWFYPermute>>permute:
Raw
c4528635-Queens.trace.log
# Queens (iterations: 250, problem size: 1000) on Tue May 3 07:13:05 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Queens.trace.log" --quiet --code "AWFYHarness run: #('Queens' 250 1000)"`
[engine] opt done id=662 AWFYQueens>>row:column:put: |Tier 2|Time 231( 216+15 )ms|AST 82|Inlined 0Y 0N|IR 237/ 358|CodeSize 1155|Timestamp 2406334870466105|Src n/a
[engine] opt done id=661 AWFYQueens>>row:column: |Tier 2|Time 278( 253+25 )ms|AST 76|Inlined 0Y 0N|IR 274/ 386|CodeSize 1361|Timestamp 2406334870463939|Src n/a
[engine] opt done id=659 SequenceableCollection>>atAllPut: |Tier 2|Time 177( 148+29 )ms|AST 71|Inlined 0Y 0N|IR 284/ 634|CodeSize 2794|Timestamp 2406335057534657|Src n/a
[engine] opt done id=659 SequenceableCollection>>atAllPut: |Tier 2|Time 172( 144+28 )ms|AST 71|Inlined 0Y 0N|IR 284/ 639|CodeSize 2844|Timestamp 2406335233116189|Src n/a
[engine] opt done id=658 ArrayedCollection class>>new:withAll: |Tier 2|Time 213( 176+37 )ms|AST 30|Inlined 1Y 0N|IR 309/ 603|CodeSize 2352|Timestamp 2406335492064936|Src n/a
[engine] opt done id=660 AWFYQueens>>placeQueen: |Tier 2|Time 1063( 842+222 )ms|AST 148|Inlined 11Y 1N|IR 2111/ 3136|CodeSize 14412|Timestamp 2406335644324737|Src n/a
[engine] opt done id=658 ArrayedCollection class>>new:withAll: |Tier 2|Time 186( 150+37 )ms|AST 30|Inlined 1Y 0N|IR 309/ 608|CodeSize 2356|Timestamp 2406335682348794|Src n/a
[engine] opt done id=663 True>>and: |Tier 2|Time 83( 79+3 )ms|AST 16|Inlined 0Y 0N|IR 23/ 30|CodeSize 168|Timestamp 2406335767157327|Src n/a
[engine] opt done id=664 AWFYQueens>>verifyResult: |Tier 2|Time 30( 28+3 )ms|AST 8|Inlined 0Y 0N|IR 19/ 22|CodeSize 122|Timestamp 2406336052550425|Src n/a
[engine] opt done id=657 AWFYQueens>>queens |Tier 2|Time 1500(1154+345 )ms|AST 91|Inlined 20Y 1N|IR 2879/ 4215|CodeSize 17376|Timestamp 2406337165099521|Src n/a
[engine] opt done id=656 AWFYQueens>>benchmark |Tier 2|Time 1664(1222+442 )ms|AST 67|Inlined 22Y 1N|IR 2984/ 4357|CodeSize 18218|Timestamp 2406337325121940|Src n/a
[engine] opt done id=655 AWFYBenchmark>>innerBenchmarkLoop: |Tier 2|Time 1875(1348+527 )ms|AST 58|Inlined 24Y 1N|IR 3080/ 4491|CodeSize 19829|Timestamp 2406338222418928|Src n/a
[engine] opt done id=669 SmallInteger>>printString |Tier 2|Time 312( 293+19 )ms|AST 149|Inlined 4Y 1N|IR 274/ 382|CodeSize 1166|Timestamp 2406373862241788|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 137( 128+9 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1107|Timestamp 2406395553287372|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 15
Success : 14
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 1
Invalidated : 0
Queues : 15
Dequeues : 0
Splits : 173
Compilation Accuracy : 1.000000
Queue Accuracy : 1.000000
Compilation Utilization : 0.119927
Remaining Compilation Queue : 0
Time to queue : count= 15, sum= 172587, min= 28, average= 11505.82, max= 64800 (milliseconds), maxTarget=SmallInteger>>printString
Time waiting in queue : count= 15, sum= 116, min= 0, average= 7.74, max= 75 (milliseconds), maxTarget=SequenceableCollection>>atAllPut:
Time for compilation : count= 14, sum= 7956, min= 31, average= 568.29, max= 1876 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle Tier : count= 14, sum= 6180, min= 27, average= 441.45, max= 1348 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Graal Tier : count= 14, sum= 1266, min= 1, average= 90.47, max= 369 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Code Installation : count= 14, sum= 509, min= 1, average= 36.36, max= 158 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle node count : count= 14, sum= 12068, min= 12, average= 862.00, max= 2945, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Trivial : count= 14, sum= 4694, min= 4, average= 335.29, max= 1137, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Non Trivial : count= 14, sum= 7374, min= 8, average= 526.71, max= 1808, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Monomorphic : count= 14, sum= 7342, min= 8, average= 524.43, max= 1800, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Polymorphic : count= 14, sum= 32, min= 0, average= 2.29, max= 8, maxTarget=AWFYQueens>>queens
Megamorphic : count= 14, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYQueens>>row:column:
Truffle call count : count= 14, sum= 91, min= 0, average= 6.50, max= 25, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Indirect : count= 14, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYQueens>>row:column:
Direct : count= 14, sum= 91, min= 0, average= 6.50, max= 25, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Dispatched : count= 14, sum= 6, min= 0, average= 0.43, max= 1, maxTarget=AWFYQueens>>placeQueen:
Inlined : count= 14, sum= 85, min= 0, average= 6.07, max= 24, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
---------- :
Cloned : count= 14, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYQueens>>row:column:
Not Cloned : count= 14, sum= 91, min= 0, average= 6.50, max= 25, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle loops : count= 14, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYQueens>>row:column:
Graal node count :
After Truffle Tier : count= 14, sum= 13172, min= 19, average= 940.86, max= 3080, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
After Graal Tier : count= 14, sum= 20190, min= 22, average= 1442.14, max= 4491, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Graal compilation result :
Code size : count= 14, sum= 85260, min= 122, average= 6090.00, max= 19829, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Total frame size : count= 14, sum= 3360, min= 32, average= 240.00, max= 688, maxTarget=AWFYQueens>>benchmark
Exception handlers : count= 14, sum= 4, min= 0, average= 0.29, max= 1, maxTarget=AWFYQueens>>placeQueen:
Infopoints : count= 14, sum= 554, min= 4, average= 39.57, max= 117, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
CALL : count= 14, sum= 474, min= 4, average= 33.86, max= 98, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
IMPLICIT_EXCEPTION : count= 14, sum= 62, min= 0, average= 4.43, max= 14, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
SAFEPOINT : count= 14, sum= 18, min= 0, average= 1.29, max= 5, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Marks : count= 14, sum= 106, min= 6, average= 7.57, max= 12, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Data references : count= 14, sum= 596, min= 1, average= 42.57, max= 123, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Raw
c4528635-Richards.trace.log
# Richards (iterations: 250, problem size: 100) on Tue May 3 07:28:38 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Richards.trace.log" --quiet --code "AWFYHarness run: #('Richards' 250 100)"`
[engine] opt done id=704 AWFYTaskState>>isTaskHoldingOrWaiting |Tier 2|Time 182( 164+18 )ms|AST 31|Inlined 0Y 0N|IR 147/ 154|CodeSize 491|Timestamp 2407268699890760|Src n/a
[engine] opt done id=706 AWFYTaskState>>isWaitingWithPacket |Tier 2|Time 145( 127+18 )ms|AST 30|Inlined 0Y 0N|IR 105/ 118|CodeSize 327|Timestamp 2407268699889014|Src n/a
[engine] opt done id=711 AWFYPacket>>link: |Tier 2|Time 74( 68+6 )ms|AST 10|Inlined 0Y 0N|IR 67/ 194|CodeSize 482|Timestamp 2407268783726378|Src n/a
[engine] opt done id=719 AWFYScheduler>>findTask: |Tier 2|Time 168( 161+7 )ms|AST 42|Inlined 0Y 0N|IR 76/ 147|CodeSize 550|Timestamp 2407268877851950|Src n/a
[engine] opt done id=705 AWFYTaskControlBlock>>runTask |Tier 2|Time 395( 326+69 )ms|AST 116|Inlined 3Y 0N|IR 531/ 1184|CodeSize 3805|Timestamp 2407268946807972|Src n/a
[engine] opt done id=715 AWFYPacket>>identity: |Tier 2|Time 74( 70+4 )ms|AST 10|Inlined 0Y 0N|IR 79/ 95|CodeSize 241|Timestamp 2407268954576459|Src n/a
[engine] opt done id=675 AWFYTaskState>>taskWaiting: |Tier 2|Time 60( 55+4 )ms|AST 10|Inlined 0Y 0N|IR 81/ 94|CodeSize 233|Timestamp 2407269010792022|Src n/a
[engine] opt done id=712 AWFYScheduler>>wait |Tier 2|Time 99( 93+6 )ms|AST 26|Inlined 1Y 0N|IR 130/ 157|CodeSize 305|Timestamp 2407269112261634|Src n/a
[engine] opt done id=723 [] in AWFYScheduler>>createDevice:priority:work:state: |Tier 2|Time 725( 641+84 )ms|AST 150|Inlined 15Y 0N|IR 1138/ 1359|CodeSize 4046|Timestamp 2407269511371077|Src n/a
[engine] opt done id=718 AWFYScheduler>>queuePacket: |Tier 2|Time 518( 471+47 )ms|AST 122|Inlined 8Y 0N|IR 647/ 1090|CodeSize 3080|Timestamp 2407269670081993|Src n/a
[engine] opt done id=716 AWFYPacket>>datum: |Tier 2|Time 59( 55+4 )ms|AST 10|Inlined 0Y 0N|IR 79/ 95|CodeSize 241|Timestamp 2407269731931796|Src n/a
[engine] opt deopt id=705 AWFYTaskControlBlock>>runTask |Timestamp 2407269753545547|Src n/a
[engine] opt inval. id=705 AWFYTaskControlBlock>>runTask |Timestamp 2407269757426194|Src n/a|Reason Profiled Return Type
[engine] opt done id=720 AWFYTaskControlBlock>>addInput:checkPriority: |Tier 2|Time 297( 216+81 )ms|AST 94|Inlined 4Y 0N|IR 397/ 825|CodeSize 2487|Timestamp 2407269831175455|Src n/a
[engine] opt done id=710 AWFYRBObject>>append:head: |Tier 2|Time 212( 195+16 )ms|AST 111|Inlined 2Y 0N|IR 215/ 497|CodeSize 1532|Timestamp 2407269945925846|Src n/a
[engine] opt done id=676 AWFYTaskState>>taskHolding: |Tier 2|Time 72( 67+4 )ms|AST 10|Inlined 0Y 0N|IR 81/ 94|CodeSize 233|Timestamp 2407270019878774|Src n/a
[engine] opt done id=705 AWFYTaskControlBlock>>runTask |Tier 2|Time 314( 213+101 )ms|AST 116|Inlined 3Y 0N|IR 616/ 1201|CodeSize 3957|Timestamp 2407270147330512|Src n/a
[engine] opt done id=708 [] in AWFYScheduler>>createHandler:priority:work:state: |Tier 2|Time 1470(1209+261 )ms|AST 340|Inlined 34Y 0N|IR 2378/ 4031|CodeSize 14387|Timestamp 2407270427062764|Src n/a
[engine] opt done id=726 [] in AWFYScheduler>>createIdler:priority:work:state: |Tier 2|Time 499( 465+34 )ms|AST 226|Inlined 13Y 0N|IR 818/ 845|CodeSize 1843|Timestamp 2407270649126333|Src n/a
[engine] opt done id=728 AWFYIdleTaskDataRecord>>control: |Tier 2|Time 92( 36+55 )ms|AST 10|Inlined 0Y 0N|IR 78/ 95|CodeSize 241|Timestamp 2407270744065248|Src n/a
[engine] opt done id=717 AWFYWorkerTaskDataRecord>>count: |Tier 2|Time 40( 36+4 )ms|AST 10|Inlined 0Y 0N|IR 78/ 95|CodeSize 241|Timestamp 2407270786213789|Src n/a
[engine] opt done id=713 [] in AWFYScheduler>>createWorker:priority:work:state: |Tier 2|Time 783( 644+139 )ms|AST 310|Inlined 19Y 0N|IR 1338/ 1656|CodeSize 4556|Timestamp 2407270805541102|Src n/a
[engine] opt done id=689 AWFYRBObject class>>DeviceA |Tier 2|Time 28( 26+2 )ms|AST 7|Inlined 0Y 0N|IR 18/ 20|CodeSize 124|Timestamp 2407270838793162|Src n/a
[engine] opt done id=694 AWFYRBObject class>>DeviceB |Tier 2|Time 69( 66+2 )ms|AST 7|Inlined 0Y 0N|IR 18/ 20|CodeSize 124|Timestamp 2407270909395286|Src n/a
[engine] opt done id=703 AWFYScheduler>>schedule |Tier 2|Time 497( 318+180 )ms|AST 105|Inlined 5Y 1N|IR 979/ 3210|CodeSize 11906|Timestamp 2407270930174811|Src n/a
[engine] opt done id=688 AWFYRBObject class>>HandlerA |Tier 2|Time 28( 25+2 )ms|AST 7|Inlined 0Y 0N|IR 18/ 20|CodeSize 124|Timestamp 2407270938774312|Src n/a
[engine] opt done id=724 AWFYDeviceTaskDataRecord>>pending: |Tier 2|Time 42( 37+5 )ms|AST 10|Inlined 0Y 0N|IR 67/ 194|CodeSize 482|Timestamp 2407270975163172|Src n/a
[engine] opt done id=729 AWFYScheduler>>release: |Tier 2|Time 201( 191+10 )ms|AST 90|Inlined 2Y 0N|IR 190/ 293|CodeSize 741|Timestamp 2407270989819823|Src n/a
[engine] opt done id=665 AWFYTaskState>>running |Tier 2|Time 53( 45+8 )ms|AST 15|Inlined 0Y 0N|IR 212/ 187|CodeSize 649|Timestamp 2407270993610370|Src n/a
[engine] opt done id=674 AWFYTaskState>>packetPending: |Tier 2|Time 42( 38+4 )ms|AST 10|Inlined 0Y 0N|IR 79/ 92|CodeSize 226|Timestamp 2407271018716082|Src n/a
[engine] opt done id=707 AWFYTaskState>>packetPending |Tier 2|Time 58( 44+15 )ms|AST 17|Inlined 0Y 0N|IR 137/ 126|CodeSize 325|Timestamp 2407271049999567|Src n/a
[engine] opt done id=695 AWFYRBObject class>>HandlerB |Tier 2|Time 39( 37+3 )ms|AST 7|Inlined 0Y 0N|IR 18/ 20|CodeSize 124|Timestamp 2407271059699403|Src n/a
[engine] opt done id=725 AWFYScheduler>>holdSelf |Tier 2|Time 111( 105+6 )ms|AST 48|Inlined 1Y 0N|IR 171/ 183|CodeSize 417|Timestamp 2407271106630846|Src n/a
[engine] opt done id=661 SequenceableCollection>>atAllPut: |Tier 2|Time 120( 99+21 )ms|AST 71|Inlined 0Y 0N|IR 231/ 458|CodeSize 1826|Timestamp 2407271324420612|Src n/a
[engine] opt done id=661 SequenceableCollection>>atAllPut: |Tier 2|Time 125( 104+21 )ms|AST 71|Inlined 0Y 0N|IR 231/ 464|CodeSize 1863|Timestamp 2407271452366571|Src n/a
[engine] opt done id=660 ArrayedCollection class>>new:withAll: |Tier 2|Time 192( 162+30 )ms|AST 30|Inlined 1Y 0N|IR 265/ 512|CodeSize 1892|Timestamp 2407272633023365|Src n/a
[engine] opt done id=660 ArrayedCollection class>>new:withAll: |Tier 2|Time 185( 152+33 )ms|AST 30|Inlined 1Y 0N|IR 265/ 518|CodeSize 1970|Timestamp 2407272823511569|Src n/a
[engine] opt done id=679 Behavior>>new <split-679> |Tier 2|Time 76( 71+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2407272901403604|Src n/a
[engine] opt done id=678 AWFYPacket class>>create:identity:kind: |Tier 2|Time 280( 257+23 )ms|AST 34|Inlined 4Y 0N|IR 317/ 340|CodeSize 1128|Timestamp 2407273088259807|Src n/a
[engine] opt done id=677 AWFYScheduler>>createPacket:identity:kind: |Tier 2|Time 290( 269+21 )ms|AST 26|Inlined 5Y 0N|IR 355/ 334|CodeSize 1117|Timestamp 2407273097748014|Src n/a
[engine] opt done id=672 Behavior>>new <split-672> |Tier 2|Time 88( 80+8 )ms|AST 25|Inlined 0Y 0N|IR 100/ 292|CodeSize 987|Timestamp 2407273499570927|Src n/a
[engine] opt done id=671 AWFYTaskControlBlock class>>link:create:priority:initialWorkQueue:initialState:function:privateData: |Tier 2|Time 247( 227+20 )ms|AST 46|Inlined 5Y 0N|IR 429/ 648|CodeSize 1667|Timestamp 2407273658446467|Src n/a
[engine] opt done id=670 AWFYScheduler>>createTask:priority:work:state:function:data: |Tier 2|Time 339( 277+62 )ms|AST 66|Inlined 6Y 0N|IR 583/ 1396|CodeSize 4515|Timestamp 2407273750026406|Src n/a
[engine] opt done id=683 AWFYTaskState>>waitingWithPacket |Tier 2|Time 50( 45+5 )ms|AST 16|Inlined 0Y 0N|IR 136/ 151|CodeSize 388|Timestamp 2407275310780261|Src n/a
[engine] opt done id=682 Behavior>>new <split-682> |Tier 2|Time 93( 67+26 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2407275353992958|Src n/a
[engine] opt done id=681 AWFYTaskState class>>waitingWithPacket |Tier 2|Time 133( 124+9 )ms|AST 25|Inlined 2Y 0N|IR 164/ 258|CodeSize 571|Timestamp 2407275393555495|Src n/a
[engine] opt done id=691 AWFYHandlerTaskDataRecord class>>create |Tier 2|Time 122( 117+5 )ms|AST 25|Inlined 2Y 0N|IR 38/ 113|CodeSize 422|Timestamp 2407277166876612|Src n/a
[engine] opt done id=702 AWFYDeviceTaskDataRecord>>create |Tier 2|Time 62( 57+5 )ms|AST 16|Inlined 0Y 0N|IR 69/ 183|CodeSize 443|Timestamp 2407277230529109|Src n/a
[engine] opt done id=659 AWFYScheduler>>initialize |Tier 2|Time 238( 224+14 )ms|AST 68|Inlined 2Y 0N|IR 325/ 454|CodeSize 1190|Timestamp 2407277282269086|Src n/a
[engine] opt done id=697 Behavior>>new <split-697> |Tier 2|Time 69( 65+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2407277353382125|Src n/a
[engine] opt done id=696 AWFYTaskState class>>waiting |Tier 2|Time 143( 120+23 )ms|AST 25|Inlined 2Y 0N|IR 164/ 258|CodeSize 571|Timestamp 2407277374781104|Src n/a
[engine] opt done id=690 AWFYScheduler>>createHandler:priority:work:state: |Tier 2|Time 463( 360+103 )ms|AST 52|Inlined 10Y 0N|IR 820/ 2820|CodeSize 9948|Timestamp 2407277507178342|Src n/a
[engine] opt done id=700 AWFYDeviceTaskDataRecord class>>create |Tier 2|Time 122( 117+5 )ms|AST 25|Inlined 2Y 0N|IR 38/ 113|CodeSize 422|Timestamp 2407277533263069|Src n/a
[engine] opt done id=699 AWFYScheduler>>createDevice:priority:work:state: |Tier 2|Time 432( 347+85 )ms|AST 52|Inlined 10Y 0N|IR 820/ 2820|CodeSize 9948|Timestamp 2407277808576940|Src n/a
[engine] opt done id=658 Behavior>>new <split-658> |Tier 2|Time 255( 244+11 )ms|AST 27|Inlined 3Y 0N|IR 228/ 312|CodeSize 1026|Timestamp 2407282654605489|Src n/a
[engine] opt done id=687 AWFYWorkerTaskDataRecord>>create |Tier 2|Time 92( 88+4 )ms|AST 23|Inlined 1Y 0N|IR 99/ 106|CodeSize 277|Timestamp 2407282749068761|Src n/a
[engine] opt done id=657 AWFYScheduler class>>new |Tier 2|Time 362( 348+15 )ms|AST 25|Inlined 7Y 0N|IR 387/ 312|CodeSize 1026|Timestamp 2407282762076516|Src n/a
[engine] opt done id=663 AWFYTaskState class>>running |Tier 2|Time 178( 146+33 )ms|AST 25|Inlined 2Y 0N|IR 216/ 282|CodeSize 723|Timestamp 2407282943071345|Src n/a
[engine] opt done id=666 AWFYScheduler>>createIdler:priority:work:state: |Tier 2|Time 522( 433+89 )ms|AST 52|Inlined 10Y 0N|IR 816/ 2819|CodeSize 9789|Timestamp 2407283467163024|Src n/a
[engine] opt done id=684 AWFYScheduler>>createWorker:priority:work:state: |Tier 2|Time 582( 468+114 )ms|AST 52|Inlined 11Y 0N|IR 821/ 2826|CodeSize 9948|Timestamp 2407284051934115|Src n/a
[engine] opt done id=731 True>>and: |Tier 2|Time 50( 47+3 )ms|AST 16|Inlined 0Y 0N|IR 23/ 30|CodeSize 168|Timestamp 2407284104122357|Src n/a
[engine] opt done id=732 AWFYRichards>>verifyResult: |Tier 2|Time 54( 52+2 )ms|AST 8|Inlined 0Y 0N|IR 19/ 22|CodeSize 122|Timestamp 2407284159765262|Src n/a
[engine] opt done id=656 AWFYRichards>>benchmark |Tier 2|Time 4608(2413+2195)ms|AST 27|Inlined 66Y 21N|IR 5095/ 20334|CodeSize 71026|Timestamp 2407287007418652|Src n/a
[engine] opt done id=662 AWFYScheduler>>start |Tier 2|Time 4320(2373+1947)ms|AST 629|Inlined 72Y 21N|IR 5081/ 20985|CodeSize 73184|Timestamp 2407287070597042|Src n/a
[engine] opt done id=686 Behavior>>new <split-686> |Tier 2|Time 81( 76+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2407287160078145|Src n/a
[engine] opt done id=685 AWFYWorkerTaskDataRecord class>>create |Tier 2|Time 149( 144+5 )ms|AST 25|Inlined 3Y 0N|IR 39/ 119|CodeSize 437|Timestamp 2407287165810936|Src n/a
[engine] opt done id=655 AWFYBenchmark>>innerBenchmarkLoop: |Tier 2|Time 4889(2695+2195)ms|AST 58|Inlined 64Y 23N|IR 5256/ 20496|CodeSize 74734|Timestamp 2407289050647096|Src n/a
[engine] opt done id=669 AWFYIdleTaskDataRecord>>create |Tier 2|Time 47( 43+4 )ms|AST 13|Inlined 0Y 0N|IR 104/ 95|CodeSize 254|Timestamp 2407289954079346|Src n/a
[engine] opt done id=668 Behavior>>new <split-668> |Tier 2|Time 89( 85+4 )ms|AST 25|Inlined 0Y 0N|IR 33/ 104|CodeSize 399|Timestamp 2407289995802672|Src n/a
[engine] opt done id=667 AWFYIdleTaskDataRecord class>>create |Tier 2|Time 124( 119+4 )ms|AST 25|Inlined 2Y 0N|IR 35/ 112|CodeSize 425|Timestamp 2407290030004552|Src n/a
[engine] opt done id=737 SmallInteger>>printString |Tier 2|Time 284( 259+25 )ms|AST 149|Inlined 4Y 1N|IR 219/ 465|CodeSize 1738|Timestamp 2407407760547399|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 136( 126+9 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1107|Timestamp 2407531654578266|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 74
Success : 70
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 4
Invalidated : 1
Profiled Return Type : 1
Queues : 92
Dequeues : 22
Target inlined into only caller : 22
Splits : 183
Compilation Accuracy : 0.986486
Queue Accuracy : 0.760870
Compilation Utilization : 0.103472
Remaining Compilation Queue : 0
Time to queue : count= 92, sum= 1200928, min= 79, average= 13053.58, max= 268767 (milliseconds), maxTarget=SmallInteger>>printString
Time waiting in queue : count= 74, sum= 38632, min= 0, average= 522.06, max= 2182 (milliseconds), maxTarget=AWFYDeviceTaskDataRecord>>pending:
Time for compilation : count= 70, sum= 28227, min= 28, average= 403.25, max= 4890 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle Tier : count= 70, sum= 19747, min= 25, average= 282.11, max= 2694 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Graal Tier : count= 70, sum= 5918, min= 1, average= 84.56, max= 1521 (milliseconds), maxTarget=AWFYRichards>>benchmark
Code Installation : count= 70, sum= 2561, min= 1, average= 36.59, max= 726 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle node count : count= 70, sum= 30678, min= 11, average= 438.26, max= 4555, maxTarget=AWFYScheduler>>start
Trivial : count= 70, sum= 11717, min= 4, average= 167.39, max= 1691, maxTarget=AWFYScheduler>>start
Non Trivial : count= 70, sum= 18961, min= 7, average= 270.87, max= 2864, maxTarget=AWFYScheduler>>start
Monomorphic : count= 70, sum= 18831, min= 7, average= 269.01, max= 2841, maxTarget=AWFYScheduler>>start
Polymorphic : count= 70, sum= 130, min= 0, average= 1.86, max= 27, maxTarget=AWFYRichards>>benchmark
Megamorphic : count= 70, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYTaskState>>isWaitingWithPacket
Truffle call count : count= 70, sum= 483, min= 0, average= 6.90, max= 94, maxTarget=AWFYScheduler>>start
Indirect : count= 70, sum= 6, min= 0, average= 0.09, max= 1, maxTarget=AWFYTaskControlBlock>>runTask
Direct : count= 70, sum= 477, min= 0, average= 6.81, max= 93, maxTarget=AWFYScheduler>>start
Dispatched : count= 70, sum= 68, min= 0, average= 0.97, max= 23, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Inlined : count= 70, sum= 409, min= 0, average= 5.84, max= 72, maxTarget=AWFYScheduler>>start
---------- :
Cloned : count= 70, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYTaskState>>isWaitingWithPacket
Not Cloned : count= 70, sum= 473, min= 0, average= 6.76, max= 92, maxTarget=AWFYScheduler>>start
Truffle loops : count= 70, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYTaskState>>isWaitingWithPacket
Graal node count :
After Truffle Tier : count= 70, sum= 35044, min= 18, average= 500.63, max= 5256, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
After Graal Tier : count= 70, sum= 100687, min= 20, average= 1438.39, max= 20985, maxTarget=AWFYScheduler>>start
Graal compilation result :
Code size : count= 70, sum= 347367, min= 122, average= 4962.39, max= 74734, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Total frame size : count= 70, sum= 8048, min= 32, average= 114.97, max= 1184, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Exception handlers : count= 70, sum= 82, min= 0, average= 1.17, max= 26, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Infopoints : count= 70, sum= 3612, min= 4, average= 51.60, max= 753, maxTarget=AWFYScheduler>>start
CALL : count= 70, sum= 3045, min= 4, average= 43.50, max= 627, maxTarget=AWFYScheduler>>start
IMPLICIT_EXCEPTION : count= 70, sum= 550, min= 0, average= 7.86, max= 125, maxTarget=AWFYScheduler>>start
SAFEPOINT : count= 70, sum= 17, min= 0, average= 0.24, max= 4, maxTarget=[] in AWFYScheduler>>createHandler:priority:work:state:
Marks : count= 70, sum= 519, min= 6, average= 7.41, max= 33, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Data references : count= 70, sum= 2920, min= 1, average= 41.71, max= 629, maxTarget=AWFYScheduler>>start
Raw
c4528635-Sieve.trace.log
# Sieve (iterations: 250, problem size: 3000) on Tue May 3 07:12:05 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Sieve.trace.log" --quiet --code "AWFYHarness run: #('Sieve' 250 3000)"`
[engine] opt done id=662 AWFYSieve>>sieve:size: |Tier 2|Time 347( 302+45 )ms|AST 133|Inlined 0Y 0N|IR 257/ 445|CodeSize 1948|Timestamp 2406275414989388|Src n/a
[engine] opt done id=404 Magnitude>>min: |Tier 2|Time 72( 68+4 )ms|AST 20|Inlined 0Y 0N|IR 59/ 72|CodeSize 194|Timestamp 2406275503100110|Src n/a
[engine] opt done id=661 SequenceableCollection>>from:to:put: |Tier 2|Time 291( 262+28 )ms|AST 161|Inlined 1Y 0N|IR 273/ 747|CodeSize 3178|Timestamp 2406275719302098|Src n/a
[engine] opt done id=663 AWFYSieve>>verifyResult: |Tier 2|Time 77( 73+3 )ms|AST 14|Inlined 0Y 0N|IR 25/ 34|CodeSize 158|Timestamp 2406275799243635|Src n/a
[engine] opt done id=659 ArrayedCollection class>>new:withAll: |Tier 2|Time 412( 380+32 )ms|AST 30|Inlined 3Y 0N|IR 378/ 466|CodeSize 1989|Timestamp 2406276015045693|Src n/a
[engine] opt done id=658 AWFYSieve>>benchmark |Tier 2|Time 512( 429+84 )ms|AST 41|Inlined 5Y 0N|IR 608/ 811|CodeSize 2902|Timestamp 2406276114890616|Src n/a
[engine] opt done id=657 AWFYBenchmark>>innerBenchmarkLoop: |Tier 2|Time 465( 371+94 )ms|AST 58|Inlined 7Y 0N|IR 705/ 902|CodeSize 3678|Timestamp 2406276605913777|Src n/a
[engine] opt done id=668 SmallInteger>>printString |Tier 2|Time 297( 268+29 )ms|AST 149|Inlined 4Y 1N|IR 219/ 433|CodeSize 1597|Timestamp 2406307017184850|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 136( 127+10 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1107|Timestamp 2406324843702636|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 11
Success : 9
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 2
Invalidated : 0
Queues : 11
Dequeues : 1
Target inlined into only caller : 1
Splits : 173
Compilation Accuracy : 1.000000
Queue Accuracy : 0.909091
Compilation Utilization : 0.048584
Remaining Compilation Queue : 0
Time to queue : count= 11, sum= 139086, min= 103, average= 12644.19, max= 53281 (milliseconds), maxTarget=SmallInteger>>printString
Time waiting in queue : count= 11, sum= 329, min= 0, average= 29.94, max= 199 (milliseconds), maxTarget=SequenceableCollection>>atAllPut:
Time for compilation : count= 9, sum= 2632, min= 73, average= 292.49, max= 517 (milliseconds), maxTarget=AWFYSieve>>benchmark
Truffle Tier : count= 9, sum= 2289, min= 68, average= 254.36, max= 428 (milliseconds), maxTarget=AWFYSieve>>benchmark
Graal Tier : count= 9, sum= 217, min= 2, average= 24.19, max= 63 (milliseconds), maxTarget=AWFYSieve>>benchmark
Code Installation : count= 9, sum= 125, min= 2, average= 13.94, max= 48 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle node count : count= 9, sum= 3217, min= 22, average= 357.44, max= 800, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Trivial : count= 9, sum= 1213, min= 8, average= 134.78, max= 296, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Non Trivial : count= 9, sum= 2004, min= 14, average= 222.67, max= 504, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Monomorphic : count= 9, sum= 2004, min= 14, average= 222.67, max= 504, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Polymorphic : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYSieve>>sieve:size:
Megamorphic : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYSieve>>sieve:size:
Truffle call count : count= 9, sum= 24, min= 0, average= 2.67, max= 7, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Indirect : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYSieve>>sieve:size:
Direct : count= 9, sum= 24, min= 0, average= 2.67, max= 7, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Dispatched : count= 9, sum= 2, min= 0, average= 0.22, max= 1, maxTarget=SmallInteger>>printString
Inlined : count= 9, sum= 22, min= 0, average= 2.44, max= 7, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
---------- :
Cloned : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYSieve>>sieve:size:
Not Cloned : count= 9, sum= 24, min= 0, average= 2.67, max= 7, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle loops : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYSieve>>sieve:size:
Graal node count :
After Truffle Tier : count= 9, sum= 2629, min= 25, average= 292.11, max= 705, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
After Graal Tier : count= 9, sum= 4239, min= 34, average= 471.00, max= 902, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Graal compilation result :
Code size : count= 9, sum= 16751, min= 158, average= 1861.22, max= 3678, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Total frame size : count= 9, sum= 1184, min= 32, average= 131.56, max= 256, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Exception handlers : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYSieve>>sieve:size:
Infopoints : count= 9, sum= 176, min= 4, average= 19.56, max= 34, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
CALL : count= 9, sum= 141, min= 4, average= 15.67, max= 26, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
IMPLICIT_EXCEPTION : count= 9, sum= 20, min= 0, average= 2.22, max= 4, maxTarget=SequenceableCollection>>from:to:put:
SAFEPOINT : count= 9, sum= 15, min= 0, average= 1.67, max= 5, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Marks : count= 9, sum= 69, min= 6, average= 7.67, max= 11, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Data references : count= 9, sum= 117, min= 1, average= 13.00, max= 27, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Raw
c4528635-Storage.trace.log
# Storage (iterations: 250, problem size: 1000) on Tue May 3 07:05:35 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Storage.trace.log" --quiet --code "AWFYHarness run: #('Storage' 250 1000)"`
[engine] opt done id=665 AWFYSomRandom>>next |Tier 2|Time 160( 141+19 )ms|AST 33|Inlined 0Y 0N|IR 102/ 169|CodeSize 507|Timestamp 2405885411327338|Src n/a
[engine] opt done id=664 AWFYStorage>>buildTreeDepth:with: |Tier 2|Time 892( 645+248 )ms|AST 144|Inlined 5Y 1N|IR 1036/ 3025|CodeSize 14014|Timestamp 2405886118298737|Src n/a
[engine] opt done id=663 AWFYSomRandom>>initialize |Tier 2|Time 59( 55+4 )ms|AST 9|Inlined 0Y 0N|IR 73/ 84|CodeSize 214|Timestamp 2405886459879015|Src n/a
[engine] opt done id=661 AWFYSomRandom class>>new |Tier 2|Time 139( 133+5 )ms|AST 25|Inlined 3Y 0N|IR 34/ 110|CodeSize 414|Timestamp 2405886779970929|Src n/a
[engine] opt done id=666 AWFYStorage>>verifyResult: |Tier 2|Time 44( 40+4 )ms|AST 14|Inlined 0Y 0N|IR 25/ 34|CodeSize 158|Timestamp 2405886828918058|Src n/a
[engine] opt done id=660 AWFYStorage>>benchmark |Tier 2|Time 708( 515+193 )ms|AST 46|Inlined 10Y 1N|IR 797/ 2457|CodeSize 9585|Timestamp 2405887357200821|Src n/a
[engine] opt done id=659 AWFYBenchmark>>innerBenchmarkLoop: |Tier 2|Time 779( 491+288 )ms|AST 58|Inlined 12Y 1N|IR 895/ 2513|CodeSize 10853|Timestamp 2405887957480249|Src n/a
[engine] opt done id=671 SmallInteger>>printString |Tier 2|Time 300( 281+19 )ms|AST 149|Inlined 4Y 1N|IR 274/ 382|CodeSize 1166|Timestamp 2405926996688191|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 150( 141+10 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1107|Timestamp 2405950266231340|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 11
Success : 9
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 2
Invalidated : 0
Queues : 11
Dequeues : 1
Target inlined into only caller : 1
Splits : 174
Compilation Accuracy : 1.000000
Queue Accuracy : 0.909091
Compilation Utilization : 0.045874
Remaining Compilation Queue : 0
Time to queue : count= 11, sum= 183537, min= 25, average= 16685.21, max= 69323 (milliseconds), maxTarget=SmallInteger>>printString
Time waiting in queue : count= 11, sum= 157, min= 0, average= 14.30, max= 137 (milliseconds), maxTarget=AWFYStorage>>verifyResult:
Time for compilation : count= 9, sum= 3249, min= 45, average= 361.10, max= 893 (milliseconds), maxTarget=AWFYStorage>>buildTreeDepth:with:
Truffle Tier : count= 9, sum= 2441, min= 40, average= 271.27, max= 644 (milliseconds), maxTarget=AWFYStorage>>buildTreeDepth:with:
Graal Tier : count= 9, sum= 525, min= 2, average= 58.34, max= 197 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Code Installation : count= 9, sum= 283, min= 2, average= 31.50, max= 92 (milliseconds), maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle node count : count= 9, sum= 4111, min= 17, average= 456.78, max= 1177, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Trivial : count= 9, sum= 1613, min= 8, average= 179.22, max= 458, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Non Trivial : count= 9, sum= 2498, min= 9, average= 277.56, max= 719, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Monomorphic : count= 9, sum= 2480, min= 9, average= 275.56, max= 713, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Polymorphic : count= 9, sum= 18, min= 0, average= 2.00, max= 6, maxTarget=AWFYStorage>>buildTreeDepth:with:
Megamorphic : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYSomRandom>>next
Truffle call count : count= 9, sum= 41, min= 0, average= 4.56, max= 13, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Indirect : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYSomRandom>>next
Direct : count= 9, sum= 41, min= 0, average= 4.56, max= 13, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Dispatched : count= 9, sum= 5, min= 0, average= 0.56, max= 1, maxTarget=AWFYStorage>>buildTreeDepth:with:
Inlined : count= 9, sum= 36, min= 0, average= 4.00, max= 12, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
---------- :
Cloned : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYSomRandom>>next
Not Cloned : count= 9, sum= 41, min= 0, average= 4.56, max= 13, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle loops : count= 9, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYSomRandom>>next
Graal node count :
After Truffle Tier : count= 9, sum= 3341, min= 25, average= 371.22, max= 1036, maxTarget=AWFYStorage>>buildTreeDepth:with:
After Graal Tier : count= 9, sum= 9103, min= 34, average= 1011.44, max= 3025, maxTarget=AWFYStorage>>buildTreeDepth:with:
Graal compilation result :
Code size : count= 9, sum= 38018, min= 158, average= 4224.22, max= 14014, maxTarget=AWFYStorage>>buildTreeDepth:with:
Total frame size : count= 9, sum= 1568, min= 32, average= 174.22, max= 512, maxTarget=AWFYStorage>>buildTreeDepth:with:
Exception handlers : count= 9, sum= 3, min= 0, average= 0.33, max= 1, maxTarget=AWFYStorage>>buildTreeDepth:with:
Infopoints : count= 9, sum= 365, min= 4, average= 40.56, max= 120, maxTarget=AWFYStorage>>buildTreeDepth:with:
CALL : count= 9, sum= 304, min= 4, average= 33.78, max= 98, maxTarget=AWFYStorage>>buildTreeDepth:with:
IMPLICIT_EXCEPTION : count= 9, sum= 54, min= 0, average= 6.00, max= 20, maxTarget=AWFYStorage>>buildTreeDepth:with:
SAFEPOINT : count= 9, sum= 7, min= 0, average= 0.78, max= 3, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Marks : count= 9, sum= 64, min= 6, average= 7.11, max= 10, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Data references : count= 9, sum= 326, min= 2, average= 36.22, max= 120, maxTarget=AWFYStorage>>buildTreeDepth:with:
Raw
c4528635-Towers.trace.log
# Towers (iterations: 250, problem size: 600) on Tue May 3 07:06:51 UTC 2022
# `/home/fniephaus/bin/graalvm-ce-java17-22.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.DynamicCompilationThresholds=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Towers.trace.log" --quiet --code "AWFYHarness run: #('Towers' 250 600)"`
[engine] opt done id=666 AWFYTowersDisk>>next: |Tier 2|Time 165( 128+37 )ms|AST 10|Inlined 0Y 0N|IR 67/ 194|CodeSize 482|Timestamp 2405961606579496|Src n/a
[engine] opt done id=669 AWFYTowers>>popDiskFrom: |Tier 2|Time 218( 206+12 )ms|AST 82|Inlined 1Y 0N|IR 183/ 400|CodeSize 980|Timestamp 2405961833286211|Src n/a
[engine] opt done id=665 AWFYTowers>>pushDisk:onPile: |Tier 2|Time 415( 363+52 )ms|AST 98|Inlined 1Y 0N|IR 387/ 1228|CodeSize 4089|Timestamp 2405961878344529|Src n/a
[engine] opt done id=668 AWFYTowers>>moveTopDiskFrom:to: |Tier 2|Time 373( 302+71 )ms|AST 48|Inlined 4Y 0N|IR 627/ 1627|CodeSize 5574|Timestamp 2405962209435348|Src n/a
[engine] opt done id=662 AWFYTowersDisk class>>new: |Tier 2|Time 219( 214+5 )ms|AST 28|Inlined 2Y 0N|IR 37/ 113|CodeSize 425|Timestamp 2405963506740628|Src n/a
[engine] opt done id=661 AWFYTowers>>buildTowerAt:disks: |Tier 2|Time 443( 350+93 )ms|AST 64|Inlined 5Y 0N|IR 466/ 1344|CodeSize 5729|Timestamp 2405963664606817|Src n/a
[engine] opt done id=667 AWFYTowers>>move:disksFrom:to: |Tier 2|Time 3737(2267+1470)ms|AST 127|Inlined 59Y 13N|IR 6798/ 17753|CodeSize 68862|Timestamp 2405965202096897|Src n/a
[engine] opt done id=670 AWFYTowers>>verifyResult: |Tier 2|Time 49( 46+3 )ms|AST 14|Inlined 0Y 0N|IR 25/ 34|CodeSize 158|Timestamp 2405966007848623|Src n/a
[engine] opt done id=660 AWFYTowers>>benchmark |Tier 2|Time 2843(2148+695 )ms|AST 62|Inlined 56Y 19N|IR 2760/ 7335|CodeSize 23972|Timestamp 2405968801039781|Src n/a
[engine] opt done id=659 AWFYBenchmark>>innerBenchmarkLoop: |Tier 2|Time 3008(2204+804 )ms|AST 58|Inlined 57Y 20N|IR 2860/ 7380|CodeSize 25563|Timestamp 2405969137704075|Src n/a
[engine] opt done id=675 SmallInteger>>printString |Tier 2|Time 290( 271+19 )ms|AST 149|Inlined 4Y 1N|IR 274/ 382|CodeSize 1166|Timestamp 2406022558071489|Src n/a
[engine] opt done id=17 String class>>new: |Tier 2|Time 141( 132+9 )ms|AST 45|Inlined 2Y 1N|IR 105/ 329|CodeSize 1107|Timestamp 2406055937448020|Src n/a
[engine] Truffle runtime statistics for engine 3
Compilations : 13
Success : 12
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 1
Invalidated : 0
Queues : 15
Dequeues : 2
Target inlined into only caller : 2
Splits : 174
Compilation Accuracy : 1.000000
Queue Accuracy : 0.866667
Compilation Utilization : 0.116047
Remaining Compilation Queue : 0
Time to queue : count= 15, sum= 271116, min= 34, average= 18074.42, max= 98463 (milliseconds), maxTarget=SmallInteger>>printString
Time waiting in queue : count= 13, sum= 542, min= 0, average= 41.70, max= 371 (milliseconds), maxTarget=AWFYTowers>>moveTopDiskFrom:to:
Time for compilation : count= 12, sum= 11922, min= 50, average= 993.56, max= 3738 (milliseconds), maxTarget=AWFYTowers>>move:disksFrom:to:
Truffle Tier : count= 12, sum= 8630, min= 46, average= 719.17, max= 2266 (milliseconds), maxTarget=AWFYTowers>>move:disksFrom:to:
Graal Tier : count= 12, sum= 2127, min= 2, average= 177.32, max= 967 (milliseconds), maxTarget=AWFYTowers>>move:disksFrom:to:
Code Installation : count= 12, sum= 1164, min= 1, average= 97.08, max= 504 (milliseconds), maxTarget=AWFYTowers>>move:disksFrom:to:
Truffle node count : count= 12, sum= 19330, min= 18, average= 1610.83, max= 5829, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Trivial : count= 12, sum= 7234, min= 8, average= 602.83, max= 2171, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Non Trivial : count= 12, sum= 12096, min= 10, average= 1008.00, max= 3658, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Monomorphic : count= 12, sum= 11844, min= 10, average= 987.00, max= 3581, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Polymorphic : count= 12, sum= 252, min= 0, average= 21.00, max= 77, maxTarget=AWFYTowers>>move:disksFrom:to:
Megamorphic : count= 12, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYTowersDisk>>next:
Truffle call count : count= 12, sum= 245, min= 0, average= 20.42, max= 77, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Indirect : count= 12, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYTowersDisk>>next:
Direct : count= 12, sum= 245, min= 0, average= 20.42, max= 77, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Dispatched : count= 12, sum= 54, min= 0, average= 4.50, max= 20, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Inlined : count= 12, sum= 191, min= 0, average= 15.92, max= 59, maxTarget=AWFYTowers>>move:disksFrom:to:
---------- :
Cloned : count= 12, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYTowersDisk>>next:
Not Cloned : count= 12, sum= 245, min= 0, average= 20.42, max= 77, maxTarget=AWFYBenchmark>>innerBenchmarkLoop:
Truffle loops : count= 12, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=AWFYTowersDisk>>next:
Graal node count :
After Truffle Tier : count= 12, sum= 14589, min= 25, average= 1215.75, max= 6798, maxTarget=AWFYTowers>>move:disksFrom:to:
After Graal Tier : count= 12, sum= 38119, min= 34, average= 3176.58, max= 17753, maxTarget=AWFYTowers>>move:disksFrom:to:
Graal compilation result :
Code size : count= 12, sum= 138107, min= 158, average= 11508.92, max= 68862, maxTarget=AWFYTowers>>move:disksFrom:to:
Total frame size : count= 12, sum= 2368, min= 32, average= 197.33, max= 736, maxTarget=AWFYTowers>>move:disksFrom:to:
Exception handlers : count= 12, sum= 37, min= 0, average= 3.08, max= 13, maxTarget=AWFYTowers>>move:disksFrom:to:
Infopoints : count= 12, sum= 1284, min= 4, average= 107.00, max= 577, maxTarget=AWFYTowers>>move:disksFrom:to:
CALL : count= 12, sum= 1115, min= 4, average= 92.92, max= 500, maxTarget=AWFYTowers>>move:disksFrom:to:
IMPLICIT_EXCEPTION : count= 12, sum= 166, min= 0, average= 13.83, max= 77, maxTarget=AWFYTowers>>move:disksFrom:to:
SAFEPOINT : count= 12, sum= 3, min= 0, average= 0.25, max= 1, maxTarget=AWFYTowers>>buildTowerAt:disks:
Marks : count= 12, sum= 112, min= 6, average= 9.33, max= 19, maxTarget=AWFYTowers>>move:disksFrom:to:
Data references : count= 12, sum= 1009, min= 3, average= 84.08, max= 463, maxTarget=AWFYTowers>>move:disksFrom:to:
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment