Skip to content

Instantly share code, notes, and snippets.

@TruffleSqueak-Bot
Created May 27, 2021 21:41

Revisions

  1. TruffleSqueak-Bot created this gist May 27, 2021.
    41 changes: 41 additions & 0 deletions 5d99b29-1-summary.md
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,41 @@
    # Steady (after 50 iterations)
    | Benchmark Name | Min | Geomean | Median | Mean | Max | Total (ms) | Total (min) |
    |:-------------- | ---:| -------:| ------:| ----:| ---:| ----------:| -----------:|
    | Bounce | 360 | 403 | 365.42 | 361 | 365.31 | 73083 | 1.22 |
    | DeltaBlue | 156 | 227 | 188.06 | 186 | 187.92 | 37611 | 0.63 |
    | Havlak | 1018 | 1120 | 1070.67 | 1080 | 1070.45 | 214133 | 3.57 |
    | Json | 221 | 253 | 224.92 | 223 | 224.85 | 44983 | 0.75 |
    | List | 447 | 497 | 453.42 | 452 | 453.38 | 90683 | 1.51 |
    | Mandelbrot | 140 | 161 | 140.6 | 140 | 140.59 | 28121 | 0.47 |
    | NBody | 203 | 318 | 207.89 | 205 | 207.54 | 41577 | 0.69 |
    | Permute | 208 | 246 | 211.83 | 209 | 211.73 | 42365 | 0.71 |
    | Queens | 175 | 233 | 178.9 | 177 | 178.82 | 35779 | 0.6 |
    | Richards | 861 | 903 | 869.34 | 865 | 869.29 | 173868 | 2.9 |
    | Sieve | 208 | 253 | 211.23 | 209 | 211.08 | 42245 | 0.7 |
    | Storage | 178 | 280 | 183.32 | 180 | 183.12 | 36664 | 0.61 |
    | Towers | 279 | 317 | 280.8 | 280 | 280.76 | 56159 | 0.94 |
    | | 4454 | 5211 | 4586.35 | 4567 | 4584.84 | 917271 | 15.29 |

    <details><summary>Benchmarks ran on <code>graalvm-ee-java11-21.1.0</code>.</summary>

    ```
    Runtime: graalvm-ee-java11-21.1.0
    System: Host: swaarena Kernel: 4.9.0-14-amd64 x86_64 (64 bit) Console: tty 1
    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: 862.0/32174.3MB
    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
    ```
    </details>
    3,214 changes: 3,214 additions & 0 deletions 5d99b29-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.
    1,284 changes: 1,284 additions & 0 deletions 5d99b29-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.
    69 changes: 69 additions & 0 deletions 5d99b29f-Bounce.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,69 @@
    # Bounce (iterations: 250, problem size: 1500) on Thu May 27 21:20:16 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Bounce.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'Bounce' 250 1500)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done Ball>>bounce |AST 207|Tier 2|Time 319( 266+52 )ms|Inlined 8Y 0N|IR 635/ 792|CodeSize 2521|Addr 0x7f49dea82f10|Src n/a
    [engine] opt done Bounce>>benchmark |AST 36|Tier 2|Time 337( 270+67 )ms|Inlined 9Y 0N|IR 770/ 976|CodeSize 3176|Addr 0x7f49dea89190|Src n/a
    [engine] opt done Number>>negated |AST 14|Tier 2|Time 55( 52+3 )ms|Inlined 0Y 0N|IR 24/ 91|CodeSize 403|Addr 0x7f49dea91310|Src n/a
    [engine] opt done Number>>abs |AST 29|Tier 2|Time 95( 91+4 )ms|Inlined 1Y 0N|IR 61/ 163|CodeSize 572|Addr 0x7f49dea96410|Src n/a
    [engine] opt done SomRandom>>next |AST 39|Tier 2|Time 65( 59+5 )ms|Inlined 0Y 0N|IR 83/ 158|CodeSize 527|Addr 0x7f49deaa3590|Src n/a
    [engine] opt done SequenceableCollection>>do: <split-2e1792e7> |AST 73|Tier 2|Time 505( 306+198 )ms|Inlined 10Y 0N|IR 938/ 3673|CodeSize 14097|Addr 0x7f49deaa5890|Src n/a
    [engine] opt done Behavior>>new <split-4e558728> |AST 26|Tier 2|Time 61( 55+6 )ms|Inlined 0Y 0N|IR 34/ 267|CodeSize 990|Addr 0x7f49deab3890|Src n/a
    [engine] opt done Ball class>>new: |AST 31|Tier 2|Time 202( 175+28 )ms|Inlined 6Y 0N|IR 391/ 490|CodeSize 1376|Addr 0x7f49deac2390|Src n/a
    [engine] opt done SomRandom>>initialize |AST 10|Tier 2|Time 40( 37+3 )ms|Inlined 0Y 0N|IR 68/ 77|CodeSize 255|Addr 0x7f49deac6590|Src n/a
    [engine] opt done Behavior>>new <split-11511459> |AST 28|Tier 2|Time 106( 103+4 )ms|Inlined 1Y 0N|IR 34/ 98|CodeSize 439|Addr 0x7f49deacb810|Src n/a
    [engine] opt done SomRandom class>>new |AST 26|Tier 2|Time 119( 115+4 )ms|Inlined 3Y 0N|IR 34/ 98|CodeSize 439|Addr 0x7f49deacbe90|Src n/a
    [engine] opt done Bounce>>verifyResult: |AST 15|Tier 2|Time 34( 32+2 )ms|Inlined 0Y 0N|IR 25/ 26|CodeSize 216|Addr 0x7f49deacd290|Src n/a
    [engine] opt done Bounce>>benchmark |AST 169|Tier 2|Time 903( 502+401 )ms|Inlined 22Y 0N|IR 1939/ 9164|CodeSize 34256|Addr 0x7f49deacef10|Src n/a
    [engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 959( 441+517 )ms|Inlined 24Y 0N|IR 2031/ 9434|CodeSize 36990|Addr 0x7f49deadf910|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 174( 156+18 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f49deaff110|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 265( 240+25 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7f49deb01890|Src n/a
    [engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 275( 235+40 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f49deb0c510|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 19
    Success : 17
    Temporary Bailouts : 0
    Permanent Bailouts : 0
    Failed : 0
    Interrupted : 2
    Invalidated : 0
    Queues : 19
    Dequeues : 1
    Target inlined into only caller : 1
    Splits : 194
    Compilation Accuracy : 1.000000
    Queue Accuracy : 0.947368
    Compilation Utilization : 0.048767
    Remaining Compilation Queue : 0
    Time to queue : count= 19, sum= 294408, min= 40, average= 15495.21, max= 93191 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 19, sum= 1205, min= 1, average= 63.47, max= 269 (milliseconds), maxTarget=Number>>abs
    Time for compilation : count= 17, sum= 4560, min= 35, average= 268.26, max= 959 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle Tier : count= 17, sum= 3144, min= 32, average= 184.96, max= 502 (milliseconds), maxTarget=Bounce>>benchmark
    Graal Tier : count= 17, sum= 1007, min= 1, average= 59.29, max= 383 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Code Installation : count= 17, sum= 408, min= 1, average= 24.01, max= 135 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle node count : count= 17, sum= 8046, min= 18, average= 473.29, max= 1844, maxTarget=Benchmark>>innerBenchmarkLoop:
    Trivial : count= 17, sum= 3119, min= 8, average= 183.47, max= 704, maxTarget=Benchmark>>innerBenchmarkLoop:
    Non Trivial : count= 17, sum= 4927, min= 10, average= 289.82, max= 1140, maxTarget=Benchmark>>innerBenchmarkLoop:
    Monomorphic : count= 17, sum= 4894, min= 10, average= 287.88, max= 1138, maxTarget=Benchmark>>innerBenchmarkLoop:
    Polymorphic : count= 17, sum= 33, min= 0, average= 1.94, max= 11, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Megamorphic : count= 17, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Ball>>bounce
    Truffle call count : count= 17, sum= 96, min= 0, average= 5.65, max= 24, maxTarget=Benchmark>>innerBenchmarkLoop:
    Indirect : count= 17, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Ball>>bounce
    Direct : count= 17, sum= 96, min= 0, average= 5.65, max= 24, maxTarget=Benchmark>>innerBenchmarkLoop:
    Dispatched : count= 17, sum= 3, min= 0, average= 0.18, max= 1, maxTarget=String class>>new:
    Inlined : count= 17, sum= 93, min= 0, average= 5.47, max= 24, maxTarget=Benchmark>>innerBenchmarkLoop:
    ---------- :
    Cloned : count= 17, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Ball>>bounce
    Not Cloned : count= 17, sum= 96, min= 0, average= 5.65, max= 24, maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle loops : count= 17, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Ball>>bounce
    Graal node count :
    After Truffle Tier : count= 17, sum= 8115, min= 24, average= 477.35, max= 2031, maxTarget=Benchmark>>innerBenchmarkLoop:
    After Graal Tier : count= 17, sum= 27457, min= 26, average= 1615.12, max= 9434, maxTarget=Benchmark>>innerBenchmarkLoop:
    Graal compilation result :
    Code size : count= 17, sum= 104369, min= 216, average= 6139.35, max= 36990, maxTarget=Benchmark>>innerBenchmarkLoop:
    Total frame size : count= 17, sum= 2256, min= 32, average= 132.71, max= 624, maxTarget=Benchmark>>innerBenchmarkLoop:
    Exception handlers : count= 17, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Ball>>bounce
    Infopoints : count= 17, sum= 997, min= 4, average= 58.65, max= 308, maxTarget=Benchmark>>innerBenchmarkLoop:
    CALL : count= 17, sum= 787, min= 4, average= 46.29, max= 242, maxTarget=Benchmark>>innerBenchmarkLoop:
    IMPLICIT_EXCEPTION : count= 17, sum= 191, min= 0, average= 11.24, max= 59, maxTarget=Benchmark>>innerBenchmarkLoop:
    SAFEPOINT : count= 17, sum= 19, min= 0, average= 1.12, max= 7, maxTarget=Benchmark>>innerBenchmarkLoop:
    Marks : count= 17, sum= 152, min= 7, average= 8.94, max= 15, maxTarget=Ball>>bounce
    Data references : count= 17, sum= 779, min= 2, average= 45.82, max= 252, maxTarget=Bounce>>benchmark
    269 changes: 269 additions & 0 deletions 5d99b29f-DeltaBlue.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,269 @@
    # DeltaBlue (iterations: 250, problem size: 12000) on Thu May 27 21:27:09 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/DeltaBlue.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'DeltaBlue' 250 12000)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done Behavior>>new <split-3aefae67> |AST 26|Tier 2|Time 170( 136+34 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7f31470dad10|Src n/a
    [engine] opt done Vector>>initialize: |AST 30|Tier 2|Time 171( 146+26 )ms|Inlined 0Y 0N|IR 139/ 337|CodeSize 959|Addr 0x7f31470dce90|Src n/a
    [engine] opt done Vector class>>new: |AST 29|Tier 2|Time 200( 188+12 )ms|Inlined 2Y 0N|IR 57/ 364|CodeSize 1232|Addr 0x7f31470e0d10|Src n/a
    [engine] opt done Strength class>>absoluteWeakest |AST 10|Tier 2|Time 34( 33+2 )ms|Inlined 0Y 0N|IR 21/ 27|CodeSize 230|Addr 0x7f31470e5c90|Src n/a
    [engine] opt done Vector>>isEmpty |AST 18|Tier 2|Time 45( 42+3 )ms|Inlined 0Y 0N|IR 31/ 46|CodeSize 276|Addr 0x7f3147111a90|Src n/a
    [engine] opt done BinaryConstraint>>output |AST 20|Tier 2|Time 79( 70+9 )ms|Inlined 0Y 0N|IR 37/ 64|CodeSize 401|Addr 0x7f3147119410|Src n/a
    [engine] opt done Vector>>append: |AST 60|Tier 2|Time 133( 116+17 )ms|Inlined 0Y 0N|IR 223/ 701|CodeSize 2109|Addr 0x7f3147121d10|Src n/a
    [engine] opt done Vector>>forEach: <split-6999cd39> |AST 79|Tier 2|Time 167( 136+31 )ms|Inlined 1Y 0N|IR 201/ 1279|CodeSize 4349|Addr 0x7f3147135390|Src n/a
    [engine] opt done Variable>>addConstraint: |AST 24|Tier 2|Time 138( 115+22 )ms|Inlined 1Y 0N|IR 289/ 766|CodeSize 2291|Addr 0x7f3147137590|Src n/a
    [engine] opt done Variable>>mark: |AST 11|Tier 2|Time 34( 31+3 )ms|Inlined 0Y 0N|IR 73/ 88|CodeSize 273|Addr 0x7f3147141890|Src n/a
    [engine] opt done Strength>>weaker: |AST 27|Tier 2|Time 51( 48+3 )ms|Inlined 0Y 0N|IR 39/ 62|CodeSize 312|Addr 0x7f3147144d10|Src n/a
    [engine] opt done Integer>>>> |AST 31|Tier 2|Time 48( 45+3 )ms|Inlined 0Y 0N|IR 39/ 111|CodeSize 462|Addr 0x7f314714c510|Src n/a
    [engine] opt done SomDictionary>>hash: |AST 60|Tier 2|Time 82( 78+4 )ms|Inlined 1Y 0N|IR 33/ 106|CodeSize 436|Addr 0x7f314714f410|Src n/a
    [engine] opt done SomDictionary>>bucketIdx: |AST 40|Tier 2|Time 69( 63+6 )ms|Inlined 0Y 0N|IR 91/ 211|CodeSize 770|Addr 0x7f3147158710|Src n/a
    [engine] opt done SomDictionary>>bucket: |AST 33|Tier 2|Time 139( 134+5 )ms|Inlined 1Y 0N|IR 155/ 115|CodeSize 599|Addr 0x7f3147163b90|Src n/a
    [engine] opt done Planner>>addPropagate:mark: |AST 131|Tier 2|Time 561( 433+128 )ms|Inlined 22Y 0N|IR 873/ 1183|CodeSize 4259|Addr 0x7f3147166510|Src n/a
    [engine] opt done SomDictionary>>at: |AST 86|Tier 2|Time 214( 207+7 )ms|Inlined 5Y 0N|IR 238/ 189|CodeSize 867|Addr 0x7f314716ad90|Src n/a
    [engine] opt done Strength class>>SymRequired |AST 10|Tier 2|Time 30( 28+2 )ms|Inlined 0Y 0N|IR 21/ 27|CodeSize 230|Addr 0x7f314716d210|Src n/a
    [engine] opt done Behavior>>new <split-6fe46b62> |AST 26|Tier 2|Time 51( 45+5 )ms|Inlined 0Y 0N|IR 92/ 268|CodeSize 988|Addr 0x7f3147176110|Src n/a
    [engine] opt done Strength class>>of: |AST 23|Tier 2|Time 165( 158+7 )ms|Inlined 6Y 0N|IR 285/ 204|CodeSize 929|Addr 0x7f3147176990|Src n/a
    [engine] opt deopt Vector>>forEach: <split-6999cd39> |AST 79|Src n/a
    [engine] opt inv. Planner>>addPropagate:mark: |AST 143|Calls/Thres 6679/ 3|CallsAndLoop/Thres 13359/ 1000|Src n/a|Reason validRootAssumption Split call node
    [engine] opt inv. Vector>>forEach: <split-6999cd39> |AST 79|Calls/Thres 2397/ 3|CallsAndLoop/Thres 4795/ 1000|Src n/a|Reason validRootAssumption Split call node
    [engine] opt done BinaryConstraint>>initializeVar:var:strength:addTo: |AST 34|Tier 2|Time 180( 177+3 )ms|Inlined 8Y 0N|IR 353/ 5|CodeSize 120|Addr 0x7f314717f390|Src n/a
    [engine] opt done Vector class>>with: |AST 43|Tier 2|Time 141( 134+7 )ms|Inlined 4Y 0N|IR 147/ 394|CodeSize 1353|Addr 0x7f3147186990|Src n/a
    [engine] opt done Vector>>removeFirst |AST 53|Tier 2|Time 207( 201+5 )ms|Inlined 1Y 0N|IR 124/ 164|CodeSize 656|Addr 0x7f3147187710|Src n/a
    [engine] opt done Variable>>walkStrength: |AST 11|Tier 2|Time 29( 26+3 )ms|Inlined 0Y 0N|IR 60/ 165|CodeSize 445|Addr 0x7f3147189390|Src n/a
    [engine] opt done Variable>>stay: |AST 11|Tier 2|Time 29( 27+3 )ms|Inlined 0Y 0N|IR 76/ 91|CodeSize 273|Addr 0x7f314718b190|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: |AST 57|Tier 2|Time 151( 128+24 )ms|Inlined 3Y 0N|IR 310/ 446|CodeSize 1731|Addr 0x7f314718e610|Src n/a
    [engine] opt done BinaryConstraint>>recalculate |AST 147|Tier 2|Time 168( 150+18 )ms|Inlined 9Y 0N|IR 607/ 529|CodeSize 1572|Addr 0x7f3147196390|Src n/a
    [engine] opt done Symbol>>= <split-585ac855> |AST 28|Tier 2|Time 40( 37+3 )ms|Inlined 0Y 0N|IR 58/ 73|CodeSize 298|Addr 0x7f3147197d90|Src n/a
    [engine] opt done Strength>>weakest: |AST 25|Tier 2|Time 53( 50+3 )ms|Inlined 1Y 0N|IR 41/ 63|CodeSize 287|Addr 0x7f3147198390|Src n/a
    [engine] opt deopt Planner>>addConstraintsConsuming:to: |AST 57|Src n/a
    [engine] opt inv. Planner>>addConstraintsConsuming:to: |AST 57|Calls/Thres 20927/ 3|CallsAndLoop/Thres 20927/ 1000|Src n/a|Reason validRootAssumption Split call node
    [engine] opt inv. Vector class>>with: |AST 43|Calls/Thres 12956/ 3|CallsAndLoop/Thres 12956/ 1000|Src n/a|Reason frame version
    [engine] opt inv. Variable>>addConstraint: |AST 24|Calls/Thres 4890/ 3|CallsAndLoop/Thres 4890/ 1000|Src n/a|Reason frame version
    [engine] opt inv. Vector>>append: |AST 124|Calls/Thres 3370/ 3|CallsAndLoop/Thres 3370/ 1000|Src n/a|Reason frame version
    [engine] opt done EqualityConstraint>>execute |AST 80|Tier 2|Time 89( 83+6 )ms|Inlined 3Y 0N|IR 281/ 164|CodeSize 644|Addr 0x7f314719fa10|Src n/a
    [engine] opt done Vector>>forEach: <split-6999cd39> |AST 79|Tier 2|Time 469( 320+149 )ms|Inlined 3Y 0N|IR 940/ 3920|CodeSize 15861|Addr 0x7f31471a4510|Src n/a
    [engine] opt done Vector>>forEach: <split-5f462e3b> |AST 79|Tier 2|Time 194( 124+70 )ms|Inlined 5Y 0N|IR 549/ 3057|CodeSize 11633|Addr 0x7f31471ad090|Src n/a
    [engine] opt inv. Vector>>isEmpty |AST 18|Calls/Thres 1850/ 3|CallsAndLoop/Thres 1850/ 1000|Src n/a|Reason Profiled Argument Types
    [engine] opt inv. Vector>>removeFirst |AST 53|Calls/Thres 16541/ 3|CallsAndLoop/Thres 16541/ 1000|Src n/a|Reason Profiled Argument Types
    [engine] opt done Plan>>execute |AST 20|Tier 2|Time 97( 88+9 )ms|Inlined 4Y 0N|IR 364/ 244|CodeSize 821|Addr 0x7f31471b7d10|Src n/a
    [engine] opt done Vector>>removeFirst |AST 53|Tier 2|Time 80( 74+5 )ms|Inlined 1Y 0N|IR 123/ 164|CodeSize 656|Addr 0x7f31471bc190|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: |AST 57|Tier 2|Time 379( 209+170 )ms|Inlined 4Y 0N|IR 1099/ 2304|CodeSize 10320|Addr 0x7f31471bcb10|Src n/a
    [engine] opt inv. Vector class>>new: |AST 29|Calls/Thres 8817/ 3|CallsAndLoop/Thres 8817/ 1000|Src n/a
    [engine] opt done Vector class>>new: |AST 29|Tier 2|Time 199( 186+13 )ms|Inlined 2Y 0N|IR 137/ 460|CodeSize 1363|Addr 0x7f31471c7690|Src n/a
    [engine] opt done Symbol>>= <split-54dcbb9f> |AST 28|Tier 2|Time 43( 40+3 )ms|Inlined 0Y 0N|IR 58/ 73|CodeSize 298|Addr 0x7f31471c8510|Src n/a
    [engine] opt done Symbol>>= <split-4d8539de> |AST 28|Tier 2|Time 43( 40+3 )ms|Inlined 0Y 0N|IR 58/ 73|CodeSize 298|Addr 0x7f31471c8b10|Src n/a
    [engine] opt done Vector class>>with: |AST 43|Tier 2|Time 285( 275+9 )ms|Inlined 4Y 0N|IR 281/ 394|CodeSize 1353|Addr 0x7f31471c9410|Src n/a
    [engine] opt done Variable>>value: |AST 11|Tier 2|Time 31( 29+3 )ms|Inlined 0Y 0N|IR 74/ 88|CodeSize 273|Addr 0x7f31471c9f10|Src n/a
    [engine] opt inv. Vector>>initialize: |AST 30|Calls/Thres 7306/ 3|CallsAndLoop/Thres 7306/ 1000|Src n/a
    [engine] opt done Vector>>initialize: |AST 30|Tier 2|Time 68( 59+9 )ms|Inlined 0Y 0N|IR 139/ 337|CodeSize 959|Addr 0x7f31471ca590|Src n/a
    [engine] opt inv. Behavior>>new <split-3aefae67> |AST 27|Calls/Thres 6371/ 3|CallsAndLoop/Thres 6371/ 1000|Src n/a
    [engine] opt done Behavior>>new <split-3aefae67> |AST 27|Tier 2|Time 55( 49+6 )ms|Inlined 0Y 0N|IR 80/ 141|CodeSize 502|Addr 0x7f31471cb110|Src n/a
    [engine] opt done Vector>>isEmpty |AST 18|Tier 2|Time 38( 36+2 )ms|Inlined 0Y 0N|IR 31/ 46|CodeSize 276|Addr 0x7f31471cb890|Src n/a
    [engine] opt inv. BinaryConstraint>>output |AST 26|Calls/Thres 138443/ 3|CallsAndLoop/Thres 138446/ 1000|Src n/a
    [engine] opt done BinaryConstraint>>output |AST 26|Tier 2|Time 44( 39+5 )ms|Inlined 0Y 0N|IR 64/ 94|CodeSize 449|Addr 0x7f31471cd010|Src n/a
    [engine] opt done Vector>>append: |AST 124|Tier 2|Time 193( 129+64 )ms|Inlined 0Y 0N|IR 638/ 2330|CodeSize 9585|Addr 0x7f31471cda10|Src n/a
    [engine] opt done Vector>>forEach: <split-3d7fa3ae> |AST 79|Tier 2|Time 326( 185+142 )ms|Inlined 3Y 0N|IR 1002/ 3995|CodeSize 16614|Addr 0x7f31471d5610|Src n/a
    [engine] opt inv. BinaryConstraint>>output |AST 26|Calls/Thres 140938/ 3|CallsAndLoop/Thres 140938/ 1000|Src n/a
    [engine] opt done BinaryConstraint>>output |AST 26|Tier 2|Time 41( 36+6 )ms|Inlined 0Y 0N|IR 95/ 141|CodeSize 550|Addr 0x7f31471ddb90|Src n/a
    [engine] opt done Variable>>initialize |AST 56|Tier 2|Time 118( 105+12 )ms|Inlined 4Y 0N|IR 310/ 710|CodeSize 1994|Addr 0x7f31471e2710|Src n/a
    [engine] opt done Vector>>forEach: <split-58065f0c> |AST 79|Tier 2|Time 659( 310+349 )ms|Inlined 15Y 0N|IR 1799/ 5704|CodeSize 21578|Addr 0x7f31471e3c90|Src n/a
    [engine] opt done Variable class>>new |AST 26|Tier 2|Time 183( 160+23 )ms|Inlined 11Y 0N|IR 551/ 1231|CodeSize 3876|Addr 0x7f31471f1090|Src n/a
    [engine] opt done Planner>>addPropagate:mark: <split-378bd86d> |AST 131|Tier 2|Time 858( 575+283 )ms|Inlined 25Y 0N|IR 2235/ 3030|CodeSize 13566|Addr 0x7f31471f3c90|Src n/a
    [engine] opt done Behavior>>new <split-6bff19ff> |AST 28|Tier 2|Time 120( 111+10 )ms|Inlined 5Y 0N|IR 265/ 586|CodeSize 1715|Addr 0x7f3147200c90|Src n/a
    [engine] opt inv. BinaryConstraint>>initializeVar:var:strength:addTo: |AST 34|Calls/Thres 19133/ 3|CallsAndLoop/Thres 19133/ 1000|Src n/a
    [engine] opt done BinaryConstraint>>initializeVar:var:strength:addTo: |AST 34|Tier 2|Time 191( 175+16 )ms|Inlined 8Y 0N|IR 505/ 844|CodeSize 2591|Addr 0x7f3147202190|Src n/a
    [engine] opt done Variable>>addConstraint: |AST 24|Tier 2|Time 247( 140+107 )ms|Inlined 1Y 0N|IR 738/ 3318|CodeSize 11251|Addr 0x7f3147203890|Src n/a
    [engine] opt deopt Vector>>forEach: <split-5f462e3b> |AST 79|Src n/a
    [engine] opt deopt Vector>>forEach: <split-3d7fa3ae> |AST 79|Src n/a
    [engine] opt deopt Vector>>forEach: <split-58065f0c> |AST 79|Src n/a
    [engine] opt deopt BinaryConstraint>>output |AST 26|Src n/a
    [engine] opt inv. BinaryConstraint>>output |AST 26|Calls/Thres 142557/ 3|CallsAndLoop/Thres 142557/ 1000|Src n/a
    [engine] opt done BinaryConstraint>>output |AST 26|Tier 2|Time 41( 35+6 )ms|Inlined 0Y 0N|IR 100/ 145|CodeSize 557|Addr 0x7f314720d710|Src n/a
    [engine] opt done Planner>>addPropagate:mark: <split-7c8326a4> |AST 135|Tier 2|Time 657( 581+77 )ms|Inlined 24Y 0N|IR 1418/ 1143|CodeSize 3592|Addr 0x7f314720e390|Src n/a
    [engine] opt inv. Vector>>forEach: <split-3d7fa3ae> |AST 79|Calls/Thres 12004/ 3|CallsAndLoop/Thres 36010/ 1000|Src n/a
    [engine] opt done Vector>>forEach: <split-3d7fa3ae> |AST 79|Tier 2|Time 325( 176+148 )ms|Inlined 3Y 0N|IR 1077/ 4099|CodeSize 16449|Addr 0x7f3147212990|Src n/a
    [engine] opt done Planner>>removePropagateFrom: |AST 41|Tier 2|Time 212( 148+64 )ms|Inlined 2Y 0N|IR 867/ 1834|CodeSize 8219|Addr 0x7f314721df10|Src n/a
    [engine] opt done BinaryConstraint>>isSatisfied <split-585c13de> |AST 17|Tier 2|Time 38( 34+4 )ms|Inlined 0Y 0N|IR 75/ 112|CodeSize 438|Addr 0x7f3147223090|Src n/a
    [engine] opt inv. Vector>>forEach: <split-58065f0c> |AST 79|Calls/Thres 12004/ 3|CallsAndLoop/Thres 36010/ 1000|Src n/a
    [engine] opt done Vector>>forEach: <split-58065f0c> |AST 79|Tier 2|Time 888( 449+439 )ms|Inlined 25Y 0N|IR 2712/ 6538|CodeSize 24516|Addr 0x7f3147223810|Src n/a
    [engine] opt done Symbol>>= <split-2adddc06> |AST 28|Tier 2|Time 42( 39+3 )ms|Inlined 0Y 0N|IR 58/ 44|CodeSize 326|Addr 0x7f3147234890|Src n/a
    [engine] opt done Vector>>forEach: <split-38499e48> |AST 79|Tier 2|Time 224( 151+73 )ms|Inlined 5Y 0N|IR 657/ 2750|CodeSize 11006|Addr 0x7f3147235390|Src n/a
    [engine] opt done Plan>>execute <split-4a699efa> |AST 20|Tier 2|Time 122( 111+12 )ms|Inlined 4Y 0N|IR 473/ 398|CodeSize 1482|Addr 0x7f314723cd10|Src n/a
    [engine] opt done Planner>>constraintsConsuming:do: |AST 62|Tier 2|Time 679( 486+193 )ms|Inlined 24Y 0N|IR 2473/ 4116|CodeSize 17138|Addr 0x7f314723dd10|Src n/a
    [engine] opt done Vector>>forEach: <split-c3fa05a> |AST 79|Tier 2|Time 331( 188+143 )ms|Inlined 3Y 0N|IR 1054/ 3824|CodeSize 15358|Addr 0x7f314724ab10|Src n/a
    [engine] opt done Vector>>forEach: <split-17ae7628> |AST 79|Tier 2|Time 297( 119+179 )ms|Inlined 1Y 0N|IR 396/ 3529|CodeSize 13138|Addr 0x7f3147255a10|Src n/a
    [engine] opt done Symbol>>= <split-2d7e1102> |AST 28|Tier 2|Time 40( 38+3 )ms|Inlined 0Y 0N|IR 58/ 44|CodeSize 326|Addr 0x7f314725b190|Src n/a
    [engine] opt done Vector>>forEach: <split-6ac97b84> |AST 79|Tier 2|Time 328( 190+138 )ms|Inlined 3Y 0N|IR 1072/ 3893|CodeSize 15078|Addr 0x7f314725f290|Src n/a
    [engine] opt done Planner>>makePlan: |AST 212|Tier 2|Time 1030( 618+412 )ms|Inlined 24Y 0N|IR 2802/ 5081|CodeSize 27133|Addr 0x7f314726c290|Src n/a
    [engine] opt done Vector>>forEach: <split-66434cc8> |AST 79|Tier 2|Time 434( 177+256 )ms|Inlined 3Y 0N|IR 941/ 3920|CodeSize 15308|Addr 0x7f314727e790|Src n/a
    [engine] opt deopt Vector>>forEach: <split-c3fa05a> |AST 79|Src n/a
    [engine] opt deopt Planner>>makePlan: |AST 212|Src n/a
    [engine] opt done Planner>>removePropagateFrom: |AST 211|Tier 2|Time 2622( 970+1653)ms|Inlined 50Y 0N|IR 5815/21473|CodeSize 84366|Addr 0x7f3147291c10|Src n/a
    [engine] opt inv. Vector>>forEach: <split-c3fa05a> |AST 79|Calls/Thres 24004/ 3|CallsAndLoop/Thres 72014/ 1000|Src n/a
    [engine] opt done Vector>>forEach: <split-c3fa05a> |AST 79|Tier 2|Time 485( 322+163 )ms|Inlined 3Y 0N|IR 1128/ 4007|CodeSize 16197|Addr 0x7f31472c7290|Src n/a
    [engine] opt done EqualityConstraint>>initializeVar:var:strength:addTo: |AST 45|Tier 2|Time 2015(1088+927 )ms|Inlined 57Y 0N|IR 4712/ 9798|CodeSize 35008|Addr 0x7f31472d0510|Src n/a
    [engine] opt done AbstractConstraint>>inputsKnown: |AST 37|Tier 2|Time 137( 123+14 )ms|Inlined 5Y 0N|IR 350/ 340|CodeSize 1018|Addr 0x7f31472f2210|Src n/a
    [engine] opt done Symbol>>= <split-70325d20> |AST 28|Tier 2|Time 41( 38+3 )ms|Inlined 0Y 0N|IR 58/ 44|CodeSize 326|Addr 0x7f31472f3b90|Src n/a
    [engine] opt done BinaryConstraint>>inputsHasOne: |AST 59|Tier 2|Time 134( 98+37 )ms|Inlined 3Y 0N|IR 397/ 2273|CodeSize 7176|Addr 0x7f31472f4090|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-35c09b94> |AST 61|Tier 2|Time 225( 159+66 )ms|Inlined 2Y 0N|IR 916/ 1843|CodeSize 7967|Addr 0x7f31472f7210|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-7b44b63d> |AST 57|Tier 2|Time 475( 209+265 )ms|Inlined 4Y 0N|IR 1174/ 2342|CodeSize 9885|Addr 0x7f31472fc090|Src n/a
    [engine] opt done Vector>>forEach: <split-16fe9c29> |AST 79|Tier 2|Time 295( 222+73 )ms|Inlined 5Y 0N|IR 549/ 3057|CodeSize 11632|Addr 0x7f3147304f10|Src n/a
    [engine] opt done BinaryConstraint>>isSatisfied <split-2d0bfb24> |AST 17|Tier 2|Time 54( 49+5 )ms|Inlined 0Y 0N|IR 75/ 112|CodeSize 438|Addr 0x7f3147313d10|Src n/a
    [engine] opt done BinaryConstraint>>isSatisfied <split-6ad11a56> |AST 17|Tier 2|Time 48( 44+4 )ms|Inlined 0Y 0N|IR 75/ 112|CodeSize 438|Addr 0x7f3147314490|Src n/a
    [engine] opt done Plan>>execute <split-2e52fb3e> |AST 20|Tier 2|Time 107( 98+9 )ms|Inlined 4Y 0N|IR 364/ 244|CodeSize 821|Addr 0x7f3147314c10|Src n/a
    [engine] opt done Planner>>incrementalAdd: <split-72ba28ee> |AST 72|Tier 2|Time 3324(1575+1749)ms|Inlined 78Y 3N|IR 7739/18174|CodeSize 71278|Addr 0x7f3147315890|Src n/a
    [engine] opt done Planner>>removePropagateFrom: |AST 49|Tier 2|Time 551( 420+132 )ms|Inlined 22Y 0N|IR 2166/ 3044|CodeSize 11562|Addr 0x7f3147346e10|Src n/a
    [engine] opt deopt Vector>>forEach: <split-66434cc8> |AST 79|Src n/a
    [engine] opt done EqualityConstraint class>>var:var:strength:addTo: |AST 40|Tier 2|Time 2219(1099+1120)ms|Inlined 59Y 0N|IR 4696/10037|CodeSize 38433|Addr 0x7f3147353d10|Src n/a
    [engine] opt done Planner>>incrementalAdd: <split-7808fb9> |AST 72|Tier 2|Time 1769(1173+596 )ms|Inlined 66Y 0N|IR 4180/ 5131|CodeSize 20889|Addr 0x7f314737e210|Src n/a
    [engine] opt done StayConstraint class>>var:strength:addTo: |AST 37|Tier 2|Time 2817(1491+1326)ms|Inlined 79Y 2N|IR 6182/10805|CodeSize 42745|Addr 0x7f3147398210|Src n/a
    [engine] opt done Vector>>forEach: <split-5cbb84b1> |AST 79|Tier 2|Time 139( 96+43 )ms|Inlined 2Y 0N|IR 246/ 2170|CodeSize 7900|Addr 0x7f31473c1a10|Src n/a
    [engine] opt inv. Planner>>makePlan: |AST 212|Calls/Thres 10/ 3|CallsAndLoop/Thres 84025/ 1000|Src n/a
    [engine] opt done Planner>>makePlan: |AST 212|Tier 2|Time 1104( 516+588 )ms|Inlined 24Y 0N|IR 2873/ 5398|CodeSize 29162|Addr 0x7f31473c4f10|Src n/a
    [engine] opt inv. Vector>>forEach: <split-66434cc8> |AST 79|Calls/Thres 12003/ 3|CallsAndLoop/Thres 36010/ 1000|Src n/a
    [engine] opt done Vector>>forEach: <split-66434cc8> |AST 79|Tier 2|Time 330( 186+144 )ms|Inlined 3Y 0N|IR 1121/ 3877|CodeSize 16052|Addr 0x7f31473d9590|Src n/a
    [engine] opt done Planner>>addPropagate:mark: <split-6a84bc2a> |AST 131|Tier 2|Time 620( 428+193 )ms|Inlined 24Y 0N|IR 1428/ 1143|CodeSize 3592|Addr 0x7f31473e5790|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-2c779e5> |AST 41|Tier 2|Time 60( 57+4 )ms|Inlined 1Y 0N|IR 77/ 120|CodeSize 417|Addr 0x7f31473e9e10|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-6579c3d9> |AST 61|Tier 2|Time 219( 157+62 )ms|Inlined 2Y 0N|IR 923/ 1827|CodeSize 7792|Addr 0x7f31473f1290|Src n/a
    [engine] opt done AbstractConstraint>>satisfy:propagate: <split-5183d589> |AST 165|Tier 2|Time 972( 800+172 )ms|Inlined 41Y 0N|IR 2808/ 2937|CodeSize 10915|Addr 0x7f31473f8f10|Src n/a
    [engine] opt done Strength class>>SymDefault |AST 10|Tier 2|Time 25( 23+2 )ms|Inlined 0Y 0N|IR 21/ 27|CodeSize 230|Addr 0x7f3147404310|Src n/a
    [engine] opt done Planner class>>chainTest: |AST 461|Tier 2|Time 3964(2201+1764)ms|Inlined 71Y 5N|IR 5190/15714|CodeSize 64210|Addr 0x7f3147404a90|Src n/a
    [engine] opt done Behavior>>new <split-4565a70a> |AST 26|Tier 2|Time 48( 42+5 )ms|Inlined 0Y 0N|IR 92/ 276|CodeSize 1016|Addr 0x7f314743c210|Src n/a
    [engine] opt done Planner>>incrementalAdd: <split-33db28fa> |AST 72|Tier 2|Time 2149(1284+865 )ms|Inlined 71Y 0N|IR 4947/ 8204|CodeSize 33062|Addr 0x7f314743de10|Src n/a
    [engine] opt done AbstractConstraint>>satisfy:propagate: <split-48bfb884> |AST 212|Tier 2|Time 1077( 847+230 )ms|Inlined 46Y 0N|IR 3516/ 5103|CodeSize 19232|Addr 0x7f3147457c10|Src n/a
    [engine] opt done ScaleConstraint>>initializeSrc:scale:offset:dst:strength:addTo:|AST 55|Tier 2|Time 3053(1294+1759)ms|Inlined 62Y 4N|IR 7601/18842|CodeSize 78766|Addr 0x7f3147468e10|Src n/a
    [engine] opt done ScaleConstraint class>>var:var:var:var:strength:addTo: |AST 46|Tier 2|Time 3650(1508+2142)ms|Inlined 64Y 4N|IR 7582/18896|CodeSize 79892|Addr 0x7f31474a1910|Src n/a
    [engine] opt done Vector>>forEach: <split-68e62ca4> |AST 79|Tier 2|Time 148( 97+50 )ms|Inlined 2Y 0N|IR 324/ 2396|CodeSize 8984|Addr 0x7f31474e2a90|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-5328a9c1> |AST 45|Tier 2|Time 66( 61+5 )ms|Inlined 1Y 0N|IR 136/ 159|CodeSize 555|Addr 0x7f31474e6910|Src n/a
    [engine] opt done BinaryConstraint>>isSatisfied <split-11653e3b> |AST 17|Tier 2|Time 37( 35+3 )ms|Inlined 0Y 0N|IR 32/ 54|CodeSize 356|Addr 0x7f31474e7210|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-715fb77> |AST 57|Tier 2|Time 362( 333+28 )ms|Inlined 3Y 0N|IR 388/ 548|CodeSize 2099|Addr 0x7f31474e7790|Src n/a
    [engine] opt done BinaryConstraint>>isSatisfied <split-1b9c1b51> |AST 17|Tier 2|Time 35( 33+2 )ms|Inlined 0Y 0N|IR 28/ 40|CodeSize 252|Addr 0x7f31474ea110|Src n/a
    [engine] opt done Planner>>addPropagate:mark: <split-5b78fdb1> |AST 131|Tier 2|Time 708( 626+82 )ms|Inlined 24Y 0N|IR 1505/ 1244|CodeSize 3874|Addr 0x7f31474ea610|Src n/a
    [engine] opt done Planner>>addPropagate:mark: <split-baf1bb3> |AST 143|Tier 2|Time 1060( 558+503 )ms|Inlined 28Y 0N|IR 2668/ 4308|CodeSize 20599|Addr 0x7f31474efa10|Src n/a
    [engine] opt done Symbol>>= <split-466d49f0> |AST 28|Tier 2|Time 39( 36+3 )ms|Inlined 0Y 0N|IR 58/ 44|CodeSize 326|Addr 0x7f31474fd590|Src n/a
    [engine] opt done Planner>>addPropagate:mark: <split-67ec8477> |AST 143|Tier 2|Time 1051( 709+342 )ms|Inlined 28Y 0N|IR 2668/ 4308|CodeSize 20599|Addr 0x7f31474fda90|Src n/a
    [engine] opt done Planner class>>projectionTest: |AST 527|Tier 2|Time 2970(2015+955 )ms|Inlined 81Y 6N|IR 3822/17235|CodeSize 72954|Addr 0x7f314750b610|Src n/a
    [engine] opt done Vector>>forEach: <split-286b39c2> |AST 79|Tier 2|Time 114( 85+29 )ms|Inlined 1Y 0N|IR 201/ 1279|CodeSize 4349|Addr 0x7f3147533f10|Src n/a
    [engine] opt done Planner>>addPropagate:mark: <split-693e4d19> |AST 131|Tier 2|Time 496( 409+87 )ms|Inlined 23Y 0N|IR 1350/ 1332|CodeSize 4437|Addr 0x7f3147536110|Src n/a
    [engine] opt done Vector>>forEach: <split-732bb66d> |AST 79|Tier 2|Time 116( 87+29 )ms|Inlined 1Y 0N|IR 201/ 1279|CodeSize 4382|Addr 0x7f314753b010|Src n/a
    [engine] opt done Planner>>addPropagate:mark: <split-61533ae> |AST 131|Tier 2|Time 636( 532+104 )ms|Inlined 23Y 0N|IR 1502/ 1546|CodeSize 5173|Addr 0x7f314753e310|Src n/a
    [engine] opt done Planner>>incrementalAdd: <split-7c28c1> |AST 72|Tier 2|Time 1760(1151+609 )ms|Inlined 66Y 0N|IR 4175/ 4878|CodeSize 20987|Addr 0x7f3147543090|Src n/a
    [engine] opt done ScaleConstraint>>addToGraph |AST 78|Tier 2|Time 1009( 318+691 )ms|Inlined 8Y 0N|IR 2804/12974|CodeSize 45240|Addr 0x7f3147559590|Src n/a
    [engine] opt done Vector>>forEach: <split-3e9803c2> |AST 79|Tier 2|Time 141( 97+43 )ms|Inlined 2Y 0N|IR 246/ 2170|CodeSize 7900|Addr 0x7f3147574a90|Src n/a
    [engine] opt done AbstractConstraint>>satisfy:propagate: <split-1eea9d2d> |AST 165|Tier 2|Time 960( 669+290 )ms|Inlined 41Y 0N|IR 2808/ 2937|CodeSize 10863|Addr 0x7f3147577f90|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-4525d1d3> |AST 41|Tier 2|Time 59( 55+4 )ms|Inlined 1Y 0N|IR 77/ 120|CodeSize 417|Addr 0x7f3147581f10|Src n/a
    [engine] opt done BinaryConstraint>>isSatisfied <split-60921b21> |AST 17|Tier 2|Time 36( 33+3 )ms|Inlined 0Y 0N|IR 32/ 54|CodeSize 356|Addr 0x7f3147582610|Src n/a
    [engine] opt done Planner>>addPropagate:mark: <split-7c974942> |AST 131|Tier 2|Time 610( 535+75 )ms|Inlined 24Y 0N|IR 1428/ 1143|CodeSize 3592|Addr 0x7f3147584c90|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-bd2f5a9> |AST 57|Tier 2|Time 158( 133+25 )ms|Inlined 3Y 0N|IR 310/ 446|CodeSize 1731|Addr 0x7f3147589010|Src n/a
    [engine] opt done BinaryConstraint>>isSatisfied <split-4d4960c8> |AST 17|Tier 2|Time 38( 35+2 )ms|Inlined 0Y 0N|IR 28/ 40|CodeSize 252|Addr 0x7f314758b210|Src n/a
    [engine] opt done AbstractConstraint>>addConstraint: <split-15723761> |AST 35|Tier 2|Time 2482(1117+1365)ms|Inlined 52Y 4N|IR 7044/18018|CodeSize 76029|Addr 0x7f314758b710|Src n/a
    [engine] opt done BinaryConstraint>>isSatisfied <split-3fbfa96> |AST 17|Tier 2|Time 38( 35+3 )ms|Inlined 0Y 0N|IR 32/ 54|CodeSize 356|Addr 0x7f31475bd290|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-301d8120> |AST 57|Tier 2|Time 151( 119+31 )ms|Inlined 2Y 0N|IR 229/ 604|CodeSize 2429|Addr 0x7f31475bd810|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-6d367020> |AST 22|Tier 2|Time 31( 29+2 )ms|Inlined 0Y 0N|IR 27/ 27|CodeSize 221|Addr 0x7f31475bfc90|Src n/a
    [engine] opt done BinaryConstraint>>isSatisfied <split-511d5d04> |AST 17|Tier 2|Time 36( 33+3 )ms|Inlined 0Y 0N|IR 32/ 54|CodeSize 356|Addr 0x7f31475c0410|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-682c1e93> |AST 57|Tier 2|Time 149( 126+23 )ms|Inlined 3Y 0N|IR 310/ 446|CodeSize 1731|Addr 0x7f31475c1710|Src n/a
    [engine] opt done BinaryConstraint>>isSatisfied <split-27068a50> |AST 17|Tier 2|Time 152( 150+2 )ms|Inlined 0Y 0N|IR 28/ 40|CodeSize 252|Addr 0x7f31475c3c10|Src n/a
    [engine] opt done AbstractConstraint>>satisfy:propagate: <split-7b60c3e> |AST 151|Tier 2|Time 1069( 725+344 )ms|Inlined 47Y 0N|IR 3185/ 3488|CodeSize 11601|Addr 0x7f31475c4110|Src n/a
    [engine] opt done Planner>>incrementalAdd: <split-599f571f> |AST 51|Tier 2|Time 1253( 931+322 )ms|Inlined 49Y 0N|IR 3247/ 3742|CodeSize 12261|Addr 0x7f31475cf590|Src n/a
    [engine] opt done BinaryConstraint>>isSatisfied <split-2b87581> |AST 18|Tier 2|Time 38( 35+4 )ms|Inlined 0Y 0N|IR 93/ 100|CodeSize 417|Addr 0x7f31475ddc10|Src n/a
    [engine] opt done BinaryConstraint>>addToGraph |AST 44|Tier 2|Time 475( 202+272 )ms|Inlined 4Y 0N|IR 1470/ 6885|CodeSize 23043|Addr 0x7f31475de710|Src n/a
    [engine] opt done BinaryConstraint>>isSatisfied <split-6d467c87> |AST 17|Tier 2|Time 37( 34+3 )ms|Inlined 0Y 0N|IR 32/ 54|CodeSize 356|Addr 0x7f31475ec810|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-29182679> |AST 57|Tier 2|Time 145( 114+31 )ms|Inlined 2Y 0N|IR 229/ 604|CodeSize 2429|Addr 0x7f31475ecd90|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-57bd802b> |AST 22|Tier 2|Time 32( 30+2 )ms|Inlined 0Y 0N|IR 27/ 27|CodeSize 221|Addr 0x7f31475ef210|Src n/a
    [engine] opt done Planner>>addPropagate:mark: <split-6f8f8a80> |AST 143|Tier 2|Time 892( 550+342 )ms|Inlined 28Y 0N|IR 2846/ 4053|CodeSize 18809|Addr 0x7f31475ef690|Src n/a
    [engine] opt inv. Vector>>initialize: |AST 30|Calls/Thres 7382/ 3|CallsAndLoop/Thres 7382/ 1000|Src n/a
    [engine] opt done Vector>>initialize: |AST 30|Tier 2|Time 132( 121+12 )ms|Inlined 0Y 0N|IR 205/ 442|CodeSize 1376|Addr 0x7f31475fdc90|Src n/a
    [engine] opt inv. Vector class>>new: |AST 29|Calls/Thres 8905/ 3|CallsAndLoop/Thres 8905/ 1000|Src n/a
    [engine] opt done Vector class>>new: |AST 29|Tier 2|Time 173( 154+20 )ms|Inlined 2Y 0N|IR 290/ 606|CodeSize 1886|Addr 0x7f31475fea90|Src n/a
    [engine] opt inv. Behavior>>new <split-3aefae67> |AST 27|Calls/Thres 6447/ 3|CallsAndLoop/Thres 6447/ 1000|Src n/a
    [engine] opt done Behavior>>new <split-3aefae67> |AST 27|Tier 2|Time 53( 46+7 )ms|Inlined 0Y 0N|IR 123/ 206|CodeSize 782|Addr 0x7f3147600590|Src n/a
    [engine] opt done Planner>>newMark |AST 19|Tier 2|Time 43( 38+5 )ms|Inlined 0Y 0N|IR 76/ 151|CodeSize 496|Addr 0x7f3147601510|Src n/a
    [engine] opt done AbstractConstraint>>initialize: |AST 25|Tier 2|Time 172( 160+12 )ms|Inlined 7Y 0N|IR 380/ 688|CodeSize 2155|Addr 0x7f3147602390|Src n/a
    [engine] opt done Strength>>stronger: |AST 27|Tier 2|Time 42( 39+3 )ms|Inlined 0Y 0N|IR 39/ 62|CodeSize 312|Addr 0x7f3147603490|Src n/a
    [engine] opt done BinaryConstraint>>chooseMethod: |AST 241|Tier 2|Time 172( 138+35 )ms|Inlined 4Y 0N|IR 701/ 1312|CodeSize 4849|Addr 0x7f3147603990|Src n/a
    [engine] opt done AbstractConstraint>>satisfy:propagate: <split-1c12f3ee> |AST 151|Tier 2|Time 964( 777+186 )ms|Inlined 39Y 0N|IR 2654/ 2963|CodeSize 10808|Addr 0x7f3147606510|Src n/a
    [engine] opt done AbstractConstraint>>satisfy:propagate: |AST 21|Tier 2|Time 51( 47+4 )ms|Inlined 1Y 0N|IR 115/ 123|CodeSize 276|Addr 0x7f3147610d10|Src n/a
    [engine] opt done Variable>>determinedBy: |AST 11|Tier 2|Time 33( 29+4 )ms|Inlined 0Y 0N|IR 56/ 89|CodeSize 381|Addr 0x7f3147611610|Src n/a
    [engine] opt done BinaryConstraint>>markUnsatisfied |AST 10|Tier 2|Time 32( 27+5 )ms|Inlined 0Y 0N|IR 77/ 273|CodeSize 840|Addr 0x7f3147611d90|Src n/a
    [engine] opt done BinaryConstraint>>inputsDo: |AST 60|Tier 2|Time 124( 91+33 )ms|Inlined 5Y 0N|IR 410/ 2140|CodeSize 7189|Addr 0x7f3147612710|Src n/a
    [engine] opt done AbstractConstraint>>inputsKnown: |AST 52|Tier 2|Time 59( 56+3 )ms|Inlined 0Y 0N|IR 80/ 97|CodeSize 320|Addr 0x7f3147615290|Src n/a
    [engine] opt done UnaryConstraint>>inputsDo: |AST 6|Tier 2|Time 18( 16+1 )ms|Inlined 0Y 0N|IR 19/ 20|CodeSize 181|Addr 0x7f3147615910|Src n/a
    [engine] opt done UnaryConstraint>>chooseMethod: |AST 60|Tier 2|Time 87( 77+10 )ms|Inlined 1Y 0N|IR 229/ 327|CodeSize 1195|Addr 0x7f3147615d10|Src n/a
    [engine] opt done Variable class>>value: |AST 41|Tier 2|Time 223( 196+27 )ms|Inlined 13Y 0N|IR 655/ 1310|CodeSize 4107|Addr 0x7f3147617690|Src n/a
    [engine] opt done UnaryConstraint>>addToGraph |AST 27|Tier 2|Time 288( 148+140 )ms|Inlined 2Y 0N|IR 858/ 3539|CodeSize 11213|Addr 0x7f314761a090|Src n/a
    [engine] opt done ScaleConstraint>>inputsDo: |AST 136|Tier 2|Time 348( 253+95 )ms|Inlined 13Y 0N|IR 887/ 5969|CodeSize 19282|Addr 0x7f3147621c90|Src n/a
    [engine] opt done ScaleConstraint>>recalculate |AST 181|Tier 2|Time 211( 180+30 )ms|Inlined 9Y 0N|IR 757/ 789|CodeSize 2527|Addr 0x7f3147628e90|Src n/a
    [engine] opt done ScaleConstraint>>execute |AST 152|Tier 2|Time 113( 103+11 )ms|Inlined 3Y 0N|IR 388/ 409|CodeSize 1384|Addr 0x7f314762ab90|Src n/a
    [engine] opt done Planner>>addConstraintsConsuming:to: <split-4917d36b> |AST 57|Tier 2|Time 361( 210+151 )ms|Inlined 4Y 0N|IR 1118/ 2210|CodeSize 9467|Addr 0x7f314762bc90|Src n/a
    [engine] opt done Vector>>at: |AST 39|Tier 2|Time 52( 48+4 )ms|Inlined 0Y 0N|IR 74/ 109|CodeSize 559|Addr 0x7f3147634590|Src n/a
    [engine] opt done Integer>>timesRepeat: |AST 46|Tier 2|Time 512( 226+286 )ms|Inlined 9Y 0N|IR 901/ 3172|CodeSize 11886|Addr 0x7f3147635410|Src n/a
    [engine] opt done AbstractConstraint>>addConstraint: <split-4463d9d3> |AST 35|Tier 2|Time 3364(1599+1765)ms|Inlined 72Y 4N|IR 7892/13721|CodeSize 60961|Addr 0x7f314763db10|Src n/a
    [engine] opt done UnaryConstraint>>initializeVar:strength:addTo: |AST 45|Tier 2|Time 4051(1833+2218)ms|Inlined 79Y 6N|IR 8305/14379|CodeSize 64375|Addr 0x7f314767ae90|Src n/a
    [engine] opt done Vector>>remove: |AST 97|Tier 2|Time 376( 294+82 )ms|Inlined 3Y 0N|IR 597/ 1589|CodeSize 6390|Addr 0x7f31476c4e10|Src n/a
    [engine] opt done Variable>>removeConstraint: |AST 39|Tier 2|Time 384( 288+96 )ms|Inlined 4Y 0N|IR 649/ 1832|CodeSize 7549|Addr 0x7f31476c9410|Src n/a
    [engine] opt done UnaryConstraint>>removeFromGraph |AST 37|Tier 2|Time 424( 289+136 )ms|Inlined 5Y 0N|IR 734/ 1774|CodeSize 7072|Addr 0x7f31476cef10|Src n/a
    [engine] opt done Vector>>forEach: <split-27470188> |AST 79|Tier 2|Time 396( 244+151 )ms|Inlined 2Y 0N|IR 890/ 2939|CodeSize 11485|Addr 0x7f31476d4610|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 122( 106+15 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f31476db890|Src n/a
    [engine] opt done UnaryConstraint>>markUnsatisfied |AST 10|Tier 2|Time 32( 29+4 )ms|Inlined 0Y 0N|IR 92/ 106|CodeSize 404|Addr 0x7f31476dd010|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 272( 248+24 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7f31476dde90|Src n/a
    [engine] opt done Vector>>forEach: <split-ddf20fd> |AST 79|Tier 2|Time 362( 201+161 )ms|Inlined 3Y 0N|IR 1054/ 3847|CodeSize 15984|Addr 0x7f31476dfd90|Src n/a
    [engine] opt done Vector class>>new |AST 20|Tier 2|Time 125( 104+22 )ms|Inlined 3Y 0N|IR 317/ 487|CodeSize 1198|Addr 0x7f31476e9010|Src n/a
    [engine] opt done Vector>>forEach: <split-4b1abd11> |AST 79|Tier 2|Time 342( 196+146 )ms|Inlined 3Y 0N|IR 941/ 3837|CodeSize 15103|Addr 0x7f31476ed290|Src n/a
    [engine] opt done Planner>>extractPlanFromConstraints: |AST 59|Tier 2|Time 1427( 751+676 )ms|Inlined 32Y 0N|IR 3589/ 6877|CodeSize 35731|Addr 0x7f31476f5210|Src n/a
    [engine] opt done Strength class>>SymPreferred |AST 10|Tier 2|Time 26( 24+2 )ms|Inlined 0Y 0N|IR 21/ 27|CodeSize 230|Addr 0x7f3147713790|Src n/a
    [engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 215( 185+30 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f3147714e10|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 187
    Success : 177
    Temporary Bailouts : 6
    org.graalvm.compiler.core.common.RetryableBailoutException: Assumption invalidated while compiling code: Object[Instance<org.graalvm.compiler.truffle.runtime.OptimizedAssumption>]: 6
    Permanent Bailouts : 0
    Failed : 0
    Interrupted : 4
    Invalidated : 23
    null : 15
    frame version : 3
    Profiled Argument Types : 2
    Queues : 317
    Dequeues : 148
    Target inlined into only caller : 123
    null : 15
    Split call node : 7
    validRootAssumption Split call node : 2
    frame version : 1
    Splits : 482
    Compilation Accuracy : 0.877005
    Queue Accuracy : 0.533123
    Compilation Utilization : 1.267826
    Remaining Compilation Queue : 0
    Time to queue : count= 317, sum= 1677710, min= 2, average= 5292.46, max= 72839 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 187, sum= 805862, min= 0, average= 4309.43, max= 26477 (milliseconds), maxTarget=Variable>>determinedBy:
    Time for compilation : count= 183, sum= 92490, min= 18, average= 505.41, max= 4051 (milliseconds), maxTarget=UnaryConstraint>>initializeVar:strength:addTo:
    Truffle Tier : count= 177, sum= 51359, min= 16, average= 290.17, max= 2200 (milliseconds), maxTarget=Planner class>>chainTest:
    Graal Tier : count= 177, sum= 22901, min= 1, average= 129.39, max= 1520 (milliseconds), maxTarget=UnaryConstraint>>initializeVar:strength:addTo:
    Code Installation : count= 177, sum= 10737, min= 0, average= 60.67, max= 746 (milliseconds), maxTarget=ScaleConstraint class>>var:var:var:var:strength:addTo:
    Truffle node count : count= 183, sum= 190142, min= 7, average= 1039.03, max= 6387, maxTarget=UnaryConstraint>>initializeVar:strength:addTo:
    Trivial : count= 183, sum= 74815, min= 1, average= 408.83, max= 2512, maxTarget=UnaryConstraint>>initializeVar:strength:addTo:
    Non Trivial : count= 183, sum= 115327, min= 6, average= 630.20, max= 3875, maxTarget=UnaryConstraint>>initializeVar:strength:addTo:
    Monomorphic : count= 183, sum= 111521, min= 6, average= 609.40, max= 3742, maxTarget=EqualityConstraint class>>var:var:strength:addTo:
    Polymorphic : count= 183, sum= 3806, min= 0, average= 20.80, max= 171, maxTarget=AbstractConstraint>>addConstraint:
    Megamorphic : count= 183, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
    Truffle call count : count= 183, sum= 2306, min= 0, average= 12.60, max= 87, maxTarget=Planner class>>projectionTest:
    Indirect : count= 183, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
    Direct : count= 183, sum= 2306, min= 0, average= 12.60, max= 87, maxTarget=Planner class>>projectionTest:
    Dispatched : count= 183, sum= 53, min= 0, average= 0.29, max= 6, maxTarget=Planner class>>projectionTest:
    Inlined : count= 183, sum= 2253, min= 0, average= 12.31, max= 81, maxTarget=Planner class>>projectionTest:
    ---------- :
    Cloned : count= 183, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
    Not Cloned : count= 183, sum= 2318, min= 0, average= 12.67, max= 87, maxTarget=Planner class>>projectionTest:
    Truffle loops : count= 183, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
    Graal node count :
    After Truffle Tier : count= 183, sum= 214765, min= 5, average= 1173.58, max= 8305, maxTarget=UnaryConstraint>>initializeVar:strength:addTo:
    After Graal Tier : count= 183, sum= 481275, min= 5, average= 2629.92, max= 21473, maxTarget=Planner>>removePropagateFrom:
    Graal compilation result :
    Code size : count= 177, sum= 1759500, min= 120, average= 9940.68, max= 84366, maxTarget=Planner>>removePropagateFrom:
    Total frame size : count= 177, sum= 37776, min= 32, average= 213.42, max= 1040, maxTarget=ScaleConstraint>>initializeSrc:scale:offset:dst:strength:addTo:
    Exception handlers : count= 177, sum= 173, min= 0, average= 0.98, max= 16, maxTarget=Planner class>>projectionTest:
    Infopoints : count= 177, sum= 17417, min= 4, average= 98.40, max= 752, maxTarget=Planner>>incrementalAdd:
    CALL : count= 177, sum= 13370, min= 4, average= 75.54, max= 579, maxTarget=ScaleConstraint>>initializeSrc:scale:offset:dst:strength:addTo:
    IMPLICIT_EXCEPTION : count= 177, sum= 3675, min= 0, average= 20.76, max= 178, maxTarget=Planner>>incrementalAdd:
    SAFEPOINT : count= 177, sum= 372, min= 0, average= 2.10, max= 23, maxTarget=Planner>>removePropagateFrom:
    Marks : count= 177, sum= 1840, min= 5, average= 10.40, max= 34, maxTarget=Planner class>>chainTest:
    Data references : count= 177, sum= 14055, min= 0, average= 79.41, max= 1328, maxTarget=Planner class>>projectionTest:
    306 changes: 306 additions & 0 deletions 5d99b29f-Havlak.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,306 @@
    # Havlak (iterations: 250, problem size: 1500) on Thu May 27 21:35:27 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Havlak.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'Havlak' 250 1500)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done Behavior>>new <split-41e1455d> |AST 26|Tier 2|Time 154( 136+18 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fd30b918e90|Src n/a
    [engine] opt done Vector class>>new: |AST 29|Tier 2|Time 181( 166+16 )ms|Inlined 2Y 0N|IR 57/ 364|CodeSize 1232|Addr 0x7fd30b91e490|Src n/a
    [engine] opt done Vector>>at: |AST 39|Tier 2|Time 90( 83+7 )ms|Inlined 0Y 0N|IR 138/ 217|CodeSize 843|Addr 0x7fd30b92b410|Src n/a
    [engine] opt done Vector>>append: |AST 163|Tier 2|Time 174( 126+48 )ms|Inlined 0Y 0N|IR 452/ 1711|CodeSize 7565|Addr 0x7fd30b94a390|Src n/a
    [engine] opt done Vector>>forEach: <split-61e45f87> |AST 79|Tier 2|Time 1272( 642+630 )ms|Inlined 22Y 0N|IR 2475/ 8346|CodeSize 35865|Addr 0x7fd30b973790|Src n/a
    [engine] opt done Vector>>forEach: <split-4d8539de> |AST 79|Tier 2|Time 311( 227+84 )ms|Inlined 10Y 0N|IR 616/ 3045|CodeSize 11695|Addr 0x7fd30b99a310|Src n/a
    [engine] opt done Integer>>>> |AST 31|Tier 2|Time 36( 33+3 )ms|Inlined 0Y 0N|IR 39/ 111|CodeSize 462|Addr 0x7fd30b99fb90|Src n/a
    [engine] opt done HavlakLoopFinder>>identifyEdges: |AST 128|Tier 2|Time 1484( 601+883 )ms|Inlined 22Y 0N|IR 2415/ 6632|CodeSize 33310|Addr 0x7fd30b9a0110|Src n/a
    [engine] opt done Object>>~= <split-45394b31> |AST 26|Tier 2|Time 49( 46+2 )ms|Inlined 1Y 0N|IR 27/ 34|CodeSize 250|Addr 0x7fd30b9bea10|Src n/a
    [engine] opt done Vector>>hasSome: <split-6ecd665> |AST 81|Tier 2|Time 113( 85+28 )ms|Inlined 1Y 0N|IR 239/ 1284|CodeSize 4744|Addr 0x7fd30b9c0810|Src n/a
    [engine] opt done SomDictionary>>bucket: |AST 33|Tier 2|Time 75( 70+5 )ms|Inlined 1Y 0N|IR 155/ 115|CodeSize 599|Addr 0x7fd30b9c2e10|Src n/a
    [engine] opt done Vector>>forEach: <split-3b0ca5e1> |AST 37|Tier 2|Time 40( 38+2 )ms|Inlined 0Y 0N|IR 36/ 56|CodeSize 288|Addr 0x7fd30b9c3590|Src n/a
    [engine] opt done SomSet>>hasSome: <split-585ac855> |AST 23|Tier 2|Time 211( 91+120 )ms|Inlined 2Y 0N|IR 290/ 1347|CodeSize 4821|Addr 0x7fd30b9c8a10|Src n/a
    [engine] opt done UnionFindNode>>findSet |AST 139|Tier 2|Time 286( 276+10 )ms|Inlined 9Y 0N|IR 363/ 238|CodeSize 755|Addr 0x7fd30b9cf990|Src n/a
    [engine] opt done Vector>>size |AST 18|Tier 2|Time 33( 30+3 )ms|Inlined 0Y 0N|IR 32/ 110|CodeSize 451|Addr 0x7fd30b9d0690|Src n/a
    [engine] opt done SomDictionary>>hash: |AST 60|Tier 2|Time 69( 66+3 )ms|Inlined 1Y 0N|IR 33/ 106|CodeSize 436|Addr 0x7fd30b9d0c10|Src n/a
    [engine] opt done SomDictionary>>bucketIdx: |AST 40|Tier 2|Time 58( 52+6 )ms|Inlined 0Y 0N|IR 91/ 211|CodeSize 770|Addr 0x7fd30b9d1f10|Src n/a
    [engine] opt done Vector class>>new |AST 20|Tier 2|Time 90( 85+5 )ms|Inlined 3Y 0N|IR 49/ 290|CodeSize 1040|Addr 0x7fd30b9d4a90|Src n/a
    [engine] opt done HavlakLoopFinder>>Unvisited |AST 8|Tier 2|Time 22( 20+2 )ms|Inlined 0Y 0N|IR 18/ 52|CodeSize 277|Addr 0x7fd30b9d5990|Src n/a
    [engine] opt deopt Vector>>at: |AST 39|Src n/a
    [engine] opt done Integer>>timesRepeat: |AST 46|Tier 2|Time 100( 67+33 )ms|Inlined 0Y 0N|IR 162/ 1819|CodeSize 5843|Addr 0x7fd30b9dd790|Src n/a
    [engine] opt inv. Vector>>at: |AST 41|Calls/Thres 17145/ 3|CallsAndLoop/Thres 17152/ 1000|Src n/a
    [engine] opt done Vector>>at: |AST 41|Tier 2|Time 95( 83+12 )ms|Inlined 0Y 0N|IR 149/ 275|CodeSize 1032|Addr 0x7fd30b9e5090|Src n/a
    [engine] opt inv. Vector>>forEach: <split-4d8539de> |AST 79|Calls/Thres 856/ 3|CallsAndLoop/Thres 10272/ 1000|Src n/a|Reason Latest layout assumption Layout no longer valid
    [engine] opt inv. HavlakLoopFinder>>identifyEdges: |AST 128|Calls/Thres 903/ 3|CallsAndLoop/Thres 10836/ 1000|Src n/a|Reason Latest layout assumption Layout no longer valid
    [engine] opt done Vector>>at:put: |AST 201|Tier 2|Time 177( 122+55 )ms|Inlined 0Y 0N|IR 483/ 1891|CodeSize 8279|Addr 0x7fd30b9ea290|Src n/a
    [engine] opt done DictIdEntry class>>new:key:value:next: |AST 40|Tier 2|Time 77( 73+3 )ms|Inlined 2Y 0N|IR 50/ 110|CodeSize 449|Addr 0x7fd30b9fa590|Src n/a
    [engine] opt deopt Vector>>forEach: <split-4d8539de> |AST 79|Src n/a
    [engine] opt done Behavior>>new <split-bcb09a6> |AST 26|Tier 2|Time 45( 42+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fd30b9fd610|Src n/a
    [engine] opt done DictEntry>>init:key:value:next: |AST 26|Tier 2|Time 36( 32+4 )ms|Inlined 0Y 0N|IR 136/ 281|CodeSize 756|Addr 0x7fd30ba02890|Src n/a
    [engine] opt done Vector>>forEach: <split-5f78de22> |AST 79|Tier 2|Time 965( 389+576 )ms|Inlined 17Y 0N|IR 2103/ 6802|CodeSize 29091|Addr 0x7fd30ba03110|Src n/a
    [engine] opt deopt SomSet>>hasSome: <split-585ac855> |AST 23|Src n/a
    [engine] opt done SomDictionary>>at:put: <split-5173200b> |AST 179|Tier 2|Time 188( 186+2 )ms|Inlined 3Y 0N|IR 5/ 5|CodeSize 120|Addr 0x7fd30ba19e90|Src n/a
    [engine] opt deopt Vector>>forEach: <split-5f78de22> |AST 79|Src n/a
    [engine] opt done SomDictionary>>transferEntries: |AST 194|Tier 2|Time 348( 281+66 )ms|Inlined 3Y 0N|IR 814/ 1706|CodeSize 7718|Addr 0x7fd30ba23090|Src n/a
    [engine] opt done Vector>>hasSome: <split-6fe46b62> |AST 79|Tier 2|Time 159( 82+76 )ms|Inlined 1Y 0N|IR 215/ 4160|CodeSize 14039|Addr 0x7fd30ba2b510|Src n/a
    [engine] opt deopt Vector>>forEach: <split-61e45f87> |AST 79|Src n/a
    [engine] opt deopt Vector>>hasSome: <split-6fe46b62> |AST 79|Src n/a
    [engine] opt deopt Vector>>hasSome: <split-6ecd665> |AST 81|Src n/a
    [engine] opt deopt UnionFindNode>>findSet |AST 139|Src n/a
    [engine] opt done Vector>>forEach: <split-4b6ac111> |AST 79|Tier 2|Time 946( 415+531 )ms|Inlined 18Y 0N|IR 2168/ 6724|CodeSize 29305|Addr 0x7fd30ba34090|Src n/a
    [engine] opt inv. Vector>>hasSome: <split-6fe46b62> |AST 81|Calls/Thres 26401/ 3|CallsAndLoop/Thres 62433/ 1000|Src n/a
    [engine] opt done Vector>>hasSome: <split-6fe46b62> |AST 81|Tier 2|Time 165( 82+83 )ms|Inlined 1Y 0N|IR 245/ 4397|CodeSize 15123|Addr 0x7fd30ba52090|Src n/a
    [engine] opt done SomSet>>hasSome: <split-516ebdf8> |AST 23|Tier 2|Time 189( 89+100 )ms|Inlined 2Y 0N|IR 296/ 4482|CodeSize 15074|Addr 0x7fd30ba58b90|Src n/a
    [engine] opt inv. Vector>>hasSome: <split-6ecd665> |AST 81|Calls/Thres 18614/ 3|CallsAndLoop/Thres 22325/ 1000|Src n/a
    [engine] opt done Vector>>hasSome: <split-6ecd665> |AST 81|Tier 2|Time 108( 79+30 )ms|Inlined 1Y 0N|IR 250/ 1284|CodeSize 4781|Addr 0x7fd30ba5ff90|Src n/a
    [engine] opt inv. Vector>>forEach: <split-5f78de22> |AST 79|Calls/Thres 7699/ 3|CallsAndLoop/Thres 31620/ 1000|Src n/a
    [engine] opt done Vector>>forEach: <split-5f78de22> |AST 79|Tier 2|Time 1061( 524+537 )ms|Inlined 17Y 0N|IR 2173/ 6754|CodeSize 29491|Addr 0x7fd30ba62510|Src n/a
    [engine] opt done HavlakLoopFinder>>findLoops |AST 760|Tier 2|Time 5185(1890+3295)ms|Inlined 61Y 11N|IR 11412/41700|CodeSize 178109|Addr 0x7fd30ba78610|Src n/a
    [engine] opt done Behavior>>new <split-17ca8b92> |AST 27|Tier 2|Time 50( 44+6 )ms|Inlined 0Y 0N|IR 123/ 206|CodeSize 782|Addr 0x7fd30bac9610|Src n/a
    [engine] opt done SomSet>>initialize: |AST 25|Tier 2|Time 97( 86+11 )ms|Inlined 3Y 0N|IR 123/ 870|CodeSize 2779|Addr 0x7fd30baca310|Src n/a
    [engine] opt done HavlakLoopFinder>>setLoopAttribute:nodePool:loop: |AST 137|Tier 2|Time 775( 447+329 )ms|Inlined 16Y 0N|IR 1946/ 4453|CodeSize 18427|Addr 0x7fd30bacc690|Src n/a
    [engine] opt done UnionFindNode class>>new |AST 26|Tier 2|Time 75( 72+3 )ms|Inlined 3Y 0N|IR 33/ 98|CodeSize 433|Addr 0x7fd30bade410|Src n/a
    [engine] opt done Behavior>>new <split-3eba57a7> |AST 28|Tier 2|Time 66( 63+3 )ms|Inlined 1Y 0N|IR 33/ 98|CodeSize 433|Addr 0x7fd30badea90|Src n/a
    [engine] opt done Vector>>forEach: <split-74fef3f7> |AST 79|Tier 2|Time 814( 387+427 )ms|Inlined 15Y 0N|IR 1642/ 4956|CodeSize 23090|Addr 0x7fd30badf110|Src n/a
    [engine] opt done HavlakLoopFinder>>stepD:nodePool: |AST 45|Tier 2|Time 908( 546+363 )ms|Inlined 17Y 0N|IR 1816/ 4334|CodeSize 21225|Addr 0x7fd30baef390|Src n/a
    [engine] opt done Vector>>removeFirst |AST 53|Tier 2|Time 81( 76+5 )ms|Inlined 1Y 0N|IR 124/ 164|CodeSize 656|Addr 0x7fd30bb02e10|Src n/a
    [engine] opt done SomSet>>size |AST 20|Tier 2|Time 51( 47+3 )ms|Inlined 1Y 0N|IR 46/ 128|CodeSize 536|Addr 0x7fd30bb04690|Src n/a
    [engine] opt done HavlakLoopFinder>>MaxNonBackPreds |AST 14|Tier 2|Time 25( 24+2 )ms|Inlined 0Y 0N|IR 18/ 52|CodeSize 277|Addr 0x7fd30bb05410|Src n/a
    [engine] opt inv. Vector>>forEach: <split-61e45f87> |AST 79|Calls/Thres 37372/ 3|CallsAndLoop/Thres 82769/ 1000|Src n/a
    [engine] opt done Vector>>forEach: <split-61e45f87> |AST 79|Tier 2|Time 1654( 660+994 )ms|Inlined 26Y 0N|IR 3590/11739|CodeSize 56808|Addr 0x7fd30bb06210|Src n/a
    [engine] opt done HavlakLoopFinder>>stepEProcessNonBackPreds:nodePool:workList:x:|AST 58|Tier 2|Time 2408( 878+1530)ms|Inlined 29Y 0N|IR 4000/13391|CodeSize 64564|Addr 0x7fd30bb2c290|Src n/a
    [engine] opt done UnionFindNode>>union: |AST 11|Tier 2|Time 28( 25+3 )ms|Inlined 0Y 0N|IR 60/ 164|CodeSize 445|Addr 0x7fd30bb5a290|Src n/a
    [engine] opt inv. UnionFindNode>>findSet |AST 156|Calls/Thres 54079/ 3|CallsAndLoop/Thres 65112/ 1000|Src n/a
    [engine] opt done UnionFindNode>>findSet |AST 156|Tier 2|Time 370( 277+92 )ms|Inlined 12Y 0N|IR 954/ 2136|CodeSize 9207|Addr 0x7fd30bb5cf10|Src n/a
    [engine] opt inv. SomSet>>hasSome: <split-585ac855> |AST 23|Calls/Thres 24841/ 3|CallsAndLoop/Thres 24841/ 1000|Src n/a
    [engine] opt done SomSet>>hasSome: <split-585ac855> |AST 23|Tier 2|Time 124( 87+37 )ms|Inlined 2Y 0N|IR 301/ 1347|CodeSize 4763|Addr 0x7fd30bb63a90|Src n/a
    [engine] opt done SomSet>>forEach: |AST 24|Tier 2|Time 1948( 812+1136)ms|Inlined 27Y 0N|IR 3635/11812|CodeSize 57731|Addr 0x7fd30bb66590|Src n/a
    [engine] opt done SomSet>>add: <split-5bb8f9e2> |AST 40|Tier 2|Time 285( 197+88 )ms|Inlined 5Y 0N|IR 804/ 2093|CodeSize 8631|Addr 0x7fd30bb91590|Src n/a
    [engine] opt inv. Vector>>forEach: <split-3b0ca5e1> |AST 79|Calls/Thres 53362/ 3|CallsAndLoop/Thres 53373/ 1000|Src n/a
    [engine] opt done Vector>>forEach: <split-3b0ca5e1> |AST 79|Tier 2|Time 126( 95+31 )ms|Inlined 2Y 0N|IR 266/ 1382|CodeSize 5065|Addr 0x7fd30bb97f10|Src n/a
    [engine] opt done SimpleLoop>>addNode: |AST 24|Tier 2|Time 450( 331+119 )ms|Inlined 6Y 0N|IR 856/ 1987|CodeSize 8841|Addr 0x7fd30bb9a890|Src n/a
    [engine] opt done SomSet>>add: <split-4d847d32> |AST 40|Tier 2|Time 281( 189+92 )ms|Inlined 5Y 0N|IR 801/ 1938|CodeSize 8213|Addr 0x7fd30bba1810|Src n/a
    [engine] opt done HavlakLoopFinder>>findLoops <split-65327f5> |AST 760|Tier 2|Time 5134(2242+2892)ms|Inlined 63Y 7N|IR 10458/37939|CodeSize 167244|Addr 0x7fd30bba7a10|Src n/a
    [engine] opt done Vector>>hasSome: <split-5bb3131b> |AST 81|Tier 2|Time 124( 84+40 )ms|Inlined 1Y 0N|IR 245/ 2212|CodeSize 7302|Addr 0x7fd30bbfe890|Src n/a
    [engine] opt done Vector>>forEach: <split-6569dded> |AST 79|Tier 2|Time 281( 156+125 )ms|Inlined 2Y 0N|IR 686/ 2829|CodeSize 11102|Addr 0x7fd30bc01910|Src n/a
    [engine] opt done Symbol>>= <split-466d49f0> |AST 26|Tier 2|Time 38( 36+2 )ms|Inlined 0Y 0N|IR 27/ 37|CodeSize 240|Addr 0x7fd30bc08590|Src n/a
    [engine] opt done Object>>~= <split-710d7aff> |AST 26|Tier 2|Time 52( 49+3 )ms|Inlined 1Y 0N|IR 95/ 53|CodeSize 341|Addr 0x7fd30bc08d10|Src n/a
    [engine] opt done HavlakLoopFinder>>identifyEdges: |AST 128|Tier 2|Time 1446( 637+809 )ms|Inlined 22Y 0N|IR 2505/ 6926|CodeSize 32118|Addr 0x7fd30bc09610|Src n/a
    [engine] opt done Symbol>>= <split-2d7e1102> |AST 28|Tier 2|Time 99( 96+3 )ms|Inlined 0Y 0N|IR 58/ 44|CodeSize 324|Addr 0x7fd30bc24610|Src n/a
    [engine] opt done BasicBlock>>numPred |AST 20|Tier 2|Time 52( 48+4 )ms|Inlined 1Y 0N|IR 46/ 128|CodeSize 536|Addr 0x7fd30bc24f10|Src n/a
    [engine] opt done Vector>>forEach: <split-2adddc06> |AST 79|Tier 2|Time 988( 493+495 )ms|Inlined 23Y 0N|IR 1921/ 7065|CodeSize 33820|Addr 0x7fd30bc25b90|Src n/a
    [engine] opt done HavlakLoopFinder>>findLoops |AST 23|Tier 2|Time 236( 145+91 )ms|Inlined 1Y 0N|IR 527/ 1769|CodeSize 7909|Addr 0x7fd30bc3a690|Src n/a
    [engine] opt done DictEntry>>value: |AST 11|Tier 2|Time 30( 27+3 )ms|Inlined 0Y 0N|IR 73/ 88|CodeSize 273|Addr 0x7fd30bc3f810|Src n/a
    [engine] opt done HavlakLoopFinder>>stepD:nodePool: |AST 55|Tier 2|Time 612( 396+217 )ms|Inlined 14Y 0N|IR 1455/ 3876|CodeSize 18528|Addr 0x7fd30bc3fe90|Src n/a
    [engine] opt done HavlakLoopFinder>>processEdges:w: |AST 57|Tier 2|Time 1042( 489+553 )ms|Inlined 21Y 0N|IR 2233/ 5285|CodeSize 23910|Addr 0x7fd30bc4cc90|Src n/a
    [engine] opt done UnionFindNode>>loop: |AST 11|Tier 2|Time 97( 94+3 )ms|Inlined 0Y 0N|IR 60/ 165|CodeSize 445|Addr 0x7fd30bc65f90|Src n/a
    [engine] opt done LoopStructureGraph>>createNewLoop:reducible: |AST 80|Tier 2|Time 832( 532+301 )ms|Inlined 23Y 0N|IR 1891/ 5149|CodeSize 21974|Addr 0x7fd30bc6f190|Src n/a
    [engine] opt deopt LoopStructureGraph>>createNewLoop:reducible: |AST 80|Src n/a
    [engine] opt done Behavior>>new <split-6ad11a56> |AST 26|Tier 2|Time 48( 42+6 )ms|Inlined 0Y 0N|IR 94/ 374|CodeSize 1320|Addr 0x7fd30bc7e690|Src n/a
    [engine] opt deopt SimpleLoop class>>basicBlock:reducible: <split-726a6b94> |AST 34|Src n/a
    [engine] opt done SimpleLoop class>>basicBlock:reducible: <split-726a6b94> |AST 34|Tier 2|Time 518( 344+174 )ms|Inlined 20Y 0N|IR 1310/ 3370|CodeSize 13395|Addr 0x7fd30bc7f090|Src n/a
    [engine] opt done HavlakLoopFinder>>setLoopAttribute:nodePool:loop: |AST 60|Tier 2|Time 1150( 509+641 )ms|Inlined 19Y 0N|IR 2285/ 5910|CodeSize 25926|Addr 0x7fd30bc88910|Src n/a
    [engine] opt done SomSet>>add: <split-3ff57625> |AST 40|Tier 2|Time 284( 198+86 )ms|Inlined 5Y 0N|IR 793/ 1884|CodeSize 8268|Addr 0x7fd30bca1e90|Src n/a
    [engine] opt inv. LoopStructureGraph>>createNewLoop:reducible: |AST 80|Calls/Thres 52529/ 3|CallsAndLoop/Thres 52529/ 1000|Src n/a
    [engine] opt done LoopStructureGraph>>createNewLoop:reducible: |AST 80|Tier 2|Time 797( 422+375 )ms|Inlined 23Y 0N|IR 1891/ 5295|CodeSize 23687|Addr 0x7fd30bcb0590|Src n/a
    [engine] opt inv. SimpleLoop class>>basicBlock:reducible: <split-726a6b94> |AST 34|Calls/Thres 52527/ 3|CallsAndLoop/Thres 52527/ 1000|Src n/a
    [engine] opt done SimpleLoop class>>basicBlock:reducible: <split-726a6b94> |AST 34|Tier 2|Time 597( 410+187 )ms|Inlined 20Y 0N|IR 1310/ 3522|CodeSize 14179|Addr 0x7fd30bcc1810|Src n/a
    [engine] opt done SimpleLoop>>init:reducible: <split-522b2631> |AST 93|Tier 2|Time 522( 387+135 )ms|Inlined 18Y 0N|IR 1231/ 3021|CodeSize 12873|Addr 0x7fd30bccb910|Src n/a
    [engine] opt inv. SomSet>>add: <split-3ff57625> |AST 40|Calls/Thres 52528/ 3|CallsAndLoop/Thres 52528/ 1000|Src n/a
    [engine] opt done SomSet>>add: <split-3ff57625> |AST 40|Tier 2|Time 290( 197+93 )ms|Inlined 5Y 0N|IR 793/ 2036|CodeSize 8803|Addr 0x7fd30bcd3c10|Src n/a
    [engine] opt done SimpleLoop>>parent: |AST 28|Tier 2|Time 350( 212+139 )ms|Inlined 7Y 0N|IR 913/ 2061|CodeSize 8428|Addr 0x7fd30bcda010|Src n/a
    [engine] opt done SimpleLoop>>addChildLoop: |AST 24|Tier 2|Time 311( 200+110 )ms|Inlined 6Y 0N|IR 848/ 1933|CodeSize 8101|Addr 0x7fd30bce1710|Src n/a
    [engine] opt done SomDictionary>>removeAll |AST 33|Tier 2|Time 182( 176+6 )ms|Inlined 0Y 0N|IR 129/ 305|CodeSize 939|Addr 0x7fd30bce8010|Src n/a
    [engine] opt done Object>>~= <split-34004818> |AST 26|Tier 2|Time 46( 43+2 )ms|Inlined 1Y 0N|IR 27/ 34|CodeSize 250|Addr 0x7fd30bce8b10|Src n/a
    [engine] opt done DictIdEntry>>match:key: |AST 30|Tier 2|Time 40( 36+4 )ms|Inlined 0Y 0N|IR 75/ 77|CodeSize 468|Addr 0x7fd30bcef990|Src n/a
    [engine] opt done SomSet>>add: <split-77128dab> |AST 40|Tier 2|Time 401( 309+92 )ms|Inlined 5Y 0N|IR 793/ 2036|CodeSize 8803|Addr 0x7fd30bce9590|Src n/a
    [engine] opt done Vector>>isEmpty |AST 18|Tier 2|Time 36( 33+2 )ms|Inlined 0Y 0N|IR 31/ 46|CodeSize 276|Addr 0x7fd30bceff90|Src n/a
    [engine] opt done HavlakLoopFinder>>isAncestor:v: |AST 41|Tier 2|Time 54( 50+4 )ms|Inlined 0Y 0N|IR 103/ 108|CodeSize 545|Addr 0x7fd30bcf0410|Src n/a
    [engine] opt done SomDictionary>>at: |AST 86|Tier 2|Time 147( 140+7 )ms|Inlined 5Y 0N|IR 287/ 243|CodeSize 1027|Addr 0x7fd30bcf0a90|Src n/a
    [engine] opt done UnionFindNode>>initialize |AST 10|Tier 2|Time 29( 26+2 )ms|Inlined 0Y 0N|IR 68/ 77|CodeSize 255|Addr 0x7fd30bcf1710|Src n/a
    [engine] opt done Object>>= |AST 14|Tier 2|Time 29( 25+4 )ms|Inlined 0Y 0N|IR 76/ 131|CodeSize 513|Addr 0x7fd30bcf1d90|Src n/a
    [engine] opt done SomSet class>>new |AST 28|Tier 2|Time 124( 107+17 )ms|Inlined 5Y 0N|IR 261/ 632|CodeSize 1834|Addr 0x7fd30bcf2c90|Src n/a
    [engine] opt done HavlakLoopFinder>>stepEProcessNonBackPreds:nodePool:workList:x:|AST 213|Tier 2|Time 1248( 732+516 )ms|Inlined 25Y 0N|IR 3323/10925|CodeSize 53330|Addr 0x7fd30bcf4110|Src n/a
    [engine] opt done SomSet>>contains: |AST 25|Tier 2|Time 135( 112+23 )ms|Inlined 3Y 0N|IR 318/ 452|CodeSize 1435|Addr 0x7fd30bd14f10|Src n/a
    [engine] opt done SomIdentitySet>>contains: |AST 14|Tier 2|Time 28( 26+2 )ms|Inlined 0Y 0N|IR 25/ 25|CodeSize 205|Addr 0x7fd30bd16f90|Src n/a
    [engine] opt done SomIdentitySet>>contains: |AST 25|Tier 2|Time 218( 109+109 )ms|Inlined 3Y 0N|IR 315/ 456|CodeSize 1656|Addr 0x7fd30bd17390|Src n/a
    [engine] opt deopt SomIdentitySet>>contains: |AST 25|Src n/a
    [engine] opt done HavlakLoopFinder>>initAllNodes |AST 34|Tier 2|Time 120( 118+2 )ms|Inlined 5Y 0N|IR 5/ 5|CodeSize 120|Addr 0x7fd30bd19590|Src n/a
    [engine] opt done HavlakLoopFinder>>processEdges:w: |AST 125|Tier 2|Time 721( 395+326 )ms|Inlined 17Y 0N|IR 1991/ 4682|CodeSize 21259|Addr 0x7fd30bd19a10|Src n/a
    [engine] opt inv. SomIdentitySet>>contains: |AST 25|Calls/Thres 130850/ 3|CallsAndLoop/Thres 130850/ 1000|Src n/a
    [engine] opt done SomIdentitySet>>contains: |AST 25|Tier 2|Time 138( 108+29 )ms|Inlined 3Y 0N|IR 315/ 442|CodeSize 1718|Addr 0x7fd30bd29410|Src n/a
    [engine] opt done UnionFindNode>>initNode:dfs: |AST 20|Tier 2|Time 36( 31+5 )ms|Inlined 0Y 0N|IR 105/ 202|CodeSize 719|Addr 0x7fd30bd2b610|Src n/a
    [engine] opt done SomIdentityDictionary>>newEntry:value:hash: |AST 31|Tier 2|Time 91( 87+3 )ms|Inlined 3Y 0N|IR 51/ 110|CodeSize 462|Addr 0x7fd30bd2c010|Src n/a
    [engine] opt done SomDictionary>>insertBucketEntry:value:hash:head: |AST 122|Tier 2|Time 154( 143+11 )ms|Inlined 7Y 0N|IR 317/ 480|CodeSize 1272|Addr 0x7fd30b775910|Src n/a
    [engine] opt deopt Vector>>forEach: <split-61e45f87> |AST 79|Src n/a
    [engine] opt inv. HavlakLoopFinder>>findLoops <split-65327f5> |AST 760|Calls/Thres 14/ 3|CallsAndLoop/Thres 218974/ 1000|Src n/a|Reason Profiled Argument Types
    [engine] opt inv. HavlakLoopFinder>>findLoops |AST 760|Calls/Thres 1501/ 3|CallsAndLoop/Thres 63641/ 1000|Src n/a|Reason Profiled Argument Types
    [engine] opt deopt HavlakLoopFinder>>setLoopAttribute:nodePool:loop: |AST 60|Src n/a
    [engine] opt done SomDictionary>>at:put: <split-1813f3e9> |AST 115|Tier 2|Time 251( 230+21 )ms|Inlined 11Y 0N|IR 508/ 743|CodeSize 2380|Addr 0x7fd30b76b090|Src n/a
    [engine] opt done HavlakLoopFinder>>doDFS:current: |AST 226|Tier 2|Time 2088(1084+1004)ms|Inlined 68Y 1N|IR 3671/ 9249|CodeSize 48381|Addr 0x7fd30bd2cc10|Src n/a
    [engine] opt inv. HavlakLoopFinder>>setLoopAttribute:nodePool:loop: |AST 60|Calls/Thres 53985/ 3|CallsAndLoop/Thres 53985/ 1000|Src n/a
    [engine] opt done HavlakLoopFinder>>setLoopAttribute:nodePool:loop: |AST 60|Tier 2|Time 1229( 576+654 )ms|Inlined 19Y 0N|IR 2285/ 6068|CodeSize 27822|Addr 0x7fd30bd56510|Src n/a
    [engine] opt inv. Vector>>forEach: <split-61e45f87> |AST 80|Calls/Thres 37375/ 3|CallsAndLoop/Thres 84275/ 1000|Src n/a
    [engine] opt done Vector>>forEach: <split-61e45f87> |AST 80|Tier 2|Time 2688(1010+1678)ms|Inlined 46Y 1N|IR 4842/18949|CodeSize 83147|Addr 0x7fd30bd71710|Src n/a
    [engine] opt inv. SimpleLoop>>parent: |AST 28|Calls/Thres 7700/ 3|CallsAndLoop/Thres 7700/ 1000|Src n/a
    [engine] opt done SimpleLoop>>parent: |AST 28|Tier 2|Time 358( 205+153 )ms|Inlined 7Y 0N|IR 913/ 2213|CodeSize 8979|Addr 0x7fd30b82f110|Src n/a
    [engine] opt inv. SomSet>>forEach: |AST 24|Calls/Thres 65643/ 3|CallsAndLoop/Thres 65643/ 1000|Src n/a
    [engine] opt done SomSet>>forEach: |AST 24|Tier 2|Time 2979(1016+1963)ms|Inlined 47Y 1N|IR 4906/19278|CodeSize 81609|Addr 0x7fd30bdaeb90|Src n/a
    [engine] opt done LoopTesterApp>>addDummyLoops: |AST 21|Tier 2|Time 230( 207+22 )ms|Inlined 16Y 1N|IR 382/ 1411|CodeSize 5007|Addr 0x7fd30b82c990|Src n/a
    [engine] opt inv. SimpleLoop>>addChildLoop: |AST 24|Calls/Thres 7701/ 3|CallsAndLoop/Thres 7701/ 1000|Src n/a
    [engine] opt done SimpleLoop>>addChildLoop: |AST 24|Tier 2|Time 326( 206+120 )ms|Inlined 6Y 0N|IR 848/ 2085|CodeSize 8802|Addr 0x7fd30bdf2010|Src n/a
    [engine] opt done Behavior>>new <split-6f012914> |AST 26|Tier 2|Time 50( 45+6 )ms|Inlined 0Y 0N|IR 93/ 288|CodeSize 1058|Addr 0x7fd30b82c090|Src n/a
    [engine] opt done HavlakLoopFinder>>init:lsg: |AST 68|Tier 2|Time 199( 179+20 )ms|Inlined 12Y 0N|IR 238/ 1296|CodeSize 3743|Addr 0x7fd30b82a110|Src n/a
    [engine] opt done SomIdentityDictionary class>>new |AST 18|Tier 2|Time 238( 233+5 )ms|Inlined 3Y 0N|IR 45/ 289|CodeSize 1042|Addr 0x7fd30b829790|Src n/a
    [engine] opt done SomDictionary class>>new: |AST 29|Tier 2|Time 85( 80+5 )ms|Inlined 2Y 0N|IR 59/ 318|CodeSize 1097|Addr 0x7fd30b828e10|Src n/a
    [engine] opt done Behavior>>new <split-61533ae> |AST 26|Tier 2|Time 44( 41+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fd30b828810|Src n/a
    [engine] opt done SomDictionary>>initialize: |AST 26|Tier 2|Time 55( 50+5 )ms|Inlined 0Y 0N|IR 116/ 268|CodeSize 761|Addr 0x7fd30bdf8f10|Src n/a
    [engine] opt done Vector>>forEach: <split-4ebadd3d> |AST 79|Tier 2|Time 313( 227+85 )ms|Inlined 10Y 0N|IR 616/ 3066|CodeSize 12130|Addr 0x7fd30bdf9890|Src n/a
    [engine] opt done LoopTesterApp>>buildStraight:n: <split-38499e48> |AST 95|Tier 2|Time 2020( 712+1308)ms|Inlined 30Y 0N|IR 3070/ 9356|CodeSize 44822|Addr 0x7fd30be00e90|Src n/a
    [engine] opt done HavlakLoopFinder>>findLoops <split-65327f5> |AST 760|Tier 2|Time 4736(2162+2575)ms|Inlined 59Y 7N|IR 9876/35991|CodeSize 156892|Addr 0x7fd30be2d510|Src n/a
    [engine] opt done SimpleLoop>>depthLevel: |AST 11|Tier 2|Time 29( 26+3 )ms|Inlined 0Y 0N|IR 74/ 88|CodeSize 273|Addr 0x7fd30be7b810|Src n/a
    [engine] opt done HavlakLoopFinder>>findLoops <split-72ba28ee> |AST 760|Tier 2|Time 3625(1799+1826)ms|Inlined 47Y 7N|IR 8476/32313|CodeSize 138852|Addr 0x7fd30be7be90|Src n/a
    [engine] opt done Vector>>forEach: <split-6d367020> |AST 79|Tier 2|Time 676( 352+323 )ms|Inlined 20Y 1N|IR 1376/ 2801|CodeSize 10290|Addr 0x7fd30beba390|Src n/a
    [engine] opt done SomSet>>forEach: <split-3e134896> |AST 24|Tier 2|Time 872( 392+480 )ms|Inlined 21Y 1N|IR 1414/ 2841|CodeSize 10277|Addr 0x7fd30bec7b10|Src n/a
    [engine] opt done Integer>>timesRepeat: <split-4a03bb68> |AST 46|Tier 2|Time 944( 878+66 )ms|Inlined 1Y 1N|IR 242/ 2796|CodeSize 10209|Addr 0x7fd30bed5c90|Src n/a
    [engine] opt done Behavior>>new <split-6f6962ba> |AST 26|Tier 2|Time 47( 44+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fd30bed9e90|Src n/a
    [engine] opt done BasicBlock>>init: |AST 47|Tier 2|Time 127( 115+11 )ms|Inlined 6Y 0N|IR 151/ 762|CodeSize 2330|Addr 0x7fd30bedaa90|Src n/a
    [engine] opt done LoopTesterApp>>buildStraight:n: <split-4905c46b> |AST 95|Tier 2|Time 1761( 573+1188)ms|Inlined 30Y 0N|IR 3070/ 9356|CodeSize 44822|Addr 0x7fd30bedc310|Src n/a
    [engine] opt done Vector>>forEach: <split-4e868ef5> |AST 79|Tier 2|Time 664( 382+282 )ms|Inlined 9Y 0N|IR 1206/ 5175|CodeSize 21443|Addr 0x7fd30bf0a990|Src n/a
    [engine] opt done LoopTesterApp>>buildStraight:n: <split-17ae7628> |AST 95|Tier 2|Time 1759( 601+1158)ms|Inlined 29Y 0N|IR 2843/ 9090|CodeSize 43589|Addr 0x7fd30bf18690|Src n/a
    [engine] opt done Integer>>timesRepeat: <split-71c905a3> |AST 46|Tier 2|Time 308( 243+65 )ms|Inlined 17Y 1N|IR 505/ 2683|CodeSize 10976|Addr 0x7fd30bf42210|Src n/a
    [engine] opt done Vector>>forEach: <split-67a056f1> |AST 79|Tier 2|Time 1046( 482+564 )ms|Inlined 23Y 0N|IR 1921/ 7065|CodeSize 35007|Addr 0x7fd30bf46b10|Src n/a
    [engine] opt done HavlakLoopFinder>>stepEProcessNonBackPreds:nodePool:workList:x:|AST 14|Tier 2|Time 29( 27+2 )ms|Inlined 0Y 0N|IR 25/ 25|CodeSize 205|Addr 0x7fd30bf5be90|Src n/a
    [engine] opt done SomSet>>contains: |AST 15|Tier 2|Time 28( 26+2 )ms|Inlined 0Y 0N|IR 29/ 29|CodeSize 221|Addr 0x7fd30bf5c310|Src n/a
    [engine] opt done SimpleLoop>>counter: |AST 11|Tier 2|Time 29( 26+3 )ms|Inlined 0Y 0N|IR 74/ 88|CodeSize 273|Addr 0x7fd30bf5c710|Src n/a
    [engine] opt done Vector>>removeAll |AST 37|Tier 2|Time 65( 58+7 )ms|Inlined 0Y 0N|IR 154/ 327|CodeSize 969|Addr 0x7fd30bf5d010|Src n/a
    [engine] opt done ControlFlowGraph>>numNodes |AST 20|Tier 2|Time 50( 46+3 )ms|Inlined 1Y 0N|IR 46/ 128|CodeSize 536|Addr 0x7fd30bf5dc10|Src n/a
    [engine] opt done LoopTesterApp>>findLoops: |AST 44|Tier 2|Time 306( 285+21 )ms|Inlined 15Y 1N|IR 344/ 1363|CodeSize 4859|Addr 0x7fd30bf5e290|Src n/a
    [engine] opt done HavlakLoopFinder class>>new:lsg: |AST 34|Tier 2|Time 201( 186+15 )ms|Inlined 14Y 0N|IR 273/ 1069|CodeSize 3690|Addr 0x7fd30bf60190|Src n/a
    [engine] opt done LoopTesterApp>>buildStraight:n: <split-1136b469> |AST 95|Tier 2|Time 1822( 740+1082)ms|Inlined 29Y 0N|IR 2843/ 9090|CodeSize 43589|Addr 0x7fd30bf61810|Src n/a
    [engine] opt done HavlakLoopFinder>>initAllNodes |AST 64|Tier 2|Time 507( 468+39 )ms|Inlined 0Y 2N|IR 566/ 2172|CodeSize 7539|Addr 0x7fd30bf8b390|Src n/a
    [engine] opt done BasicBlock>>addOutEdge: |AST 24|Tier 2|Time 199( 137+61 )ms|Inlined 1Y 0N|IR 524/ 1763|CodeSize 7818|Addr 0x7fd30bf8e390|Src n/a
    [engine] opt done BasicBlock>>addInEdge: |AST 24|Tier 2|Time 199( 137+63 )ms|Inlined 1Y 0N|IR 524/ 1763|CodeSize 7818|Addr 0x7fd30bf92910|Src n/a
    [engine] opt done ControlFlowGraph>>addEdge: |AST 24|Tier 2|Time 289( 131+159 )ms|Inlined 1Y 0N|IR 524/ 1763|CodeSize 7818|Addr 0x7fd30bf96e90|Src n/a
    [engine] opt done BasicBlock class>>new: |AST 31|Tier 2|Time 240( 231+9 )ms|Inlined 8Y 0N|IR 76/ 687|CodeSize 2383|Addr 0x7fd30bf9ba10|Src n/a
    [engine] opt done HavlakLoopFinder>>findLoops <split-30af7377> |AST 760|Tier 2|Time 4568(2214+2354)ms|Inlined 59Y 7N|IR 9876/35991|CodeSize 156816|Addr 0x7fd30bf9ca10|Src n/a
    [engine] opt done HavlakLoopFinder>>initAllNodes <split-15723761> |AST 34|Tier 2|Time 710( 548+162 )ms|Inlined 22Y 0N|IR 1662/ 2889|CodeSize 12745|Addr 0x7fd30bfead90|Src n/a
    [engine] opt done SimpleLoop>>nestingLevel: |AST 34|Tier 2|Time 57( 53+4 )ms|Inlined 1Y 0N|IR 158/ 159|CodeSize 381|Addr 0x7fd30bff5d10|Src n/a
    [engine] opt done Magnitude>>max: |AST 21|Tier 2|Time 29( 27+2 )ms|Inlined 0Y 0N|IR 29/ 34|CodeSize 206|Addr 0x7fd30bff6790|Src n/a
    [engine] opt done LoopTesterApp>>buildStraight:n: <split-1dab9dd6> |AST 95|Tier 2|Time 1721( 573+1148)ms|Inlined 30Y 0N|IR 3070/ 9356|CodeSize 44822|Addr 0x7fd30bff6b90|Src n/a
    [engine] opt done LoopTesterApp>>buildStraight:n: <split-247667dd> |AST 95|Tier 2|Time 1703( 591+1112)ms|Inlined 29Y 0N|IR 2843/ 9090|CodeSize 43589|Addr 0x7fd30c022e90|Src n/a
    [engine] opt done LoopStructureGraph>>calculateNestingLevelRec:depth: |AST 58|Tier 2|Time 766( 351+415 )ms|Inlined 23Y 1N|IR 1482/ 1950|CodeSize 7514|Addr 0x7fd30c04ca10|Src n/a
    [engine] opt done LoopTesterApp>>constructCFG:p:p: |AST 26|Tier 2|Time 511( 397+114 )ms|Inlined 0Y 1N|IR 107/ 481|CodeSize 1748|Addr 0x7fd30c05c310|Src n/a
    [engine] opt done LoopStructureGraph>>calculateNestingLevelRec:depth: |AST 85|Tier 2|Time 1254( 363+891 )ms|Inlined 23Y 1N|IR 1645/ 4111|CodeSize 15329|Addr 0x7fd30c05da90|Src n/a
    [engine] opt done LoopTesterApp>>buildBaseLoop: <split-75f2099> |AST 181|Tier 2|Time 2566(2160+405 )ms|Inlined 25Y 9N|IR 1351/ 4453|CodeSize 18737|Addr 0x7fd30c070590|Src n/a
    [engine] opt done HavlakLoopFinder>>initAllNodes <split-4a699efa> |AST 64|Tier 2|Time 3657(1334+2322)ms|Inlined 76Y 2N|IR 4351/14935|CodeSize 76841|Addr 0x7fd30c07b910|Src n/a
    [engine] opt done Integer>>timesRepeat: <split-7fedfe27> |AST 46|Tier 2|Time 614( 576+38 )ms|Inlined 0Y 1N|IR 185/ 1687|CodeSize 5334|Addr 0x7fd30c0bfc10|Src n/a
    [engine] opt done Behavior>>new <split-29182679> |AST 26|Tier 2|Time 44( 41+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fd30c0c2310|Src n/a
    [engine] opt done BasicBlockEdge class>>for:from:to: <split-6d467c87> |AST 37|Tier 2|Time 1297( 559+738 )ms|Inlined 28Y 0N|IR 2917/ 9107|CodeSize 44533|Addr 0x7fd30c0c3210|Src n/a
    [engine] opt done BasicBlockEdge>>init:from:to: <split-57bd802b> |AST 96|Tier 2|Time 1096( 615+481 )ms|Inlined 26Y 0N|IR 2888/ 9364|CodeSize 44898|Addr 0x7fd30c0e4910|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-5e742e4> |AST 76|Tier 2|Time 125( 105+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fd30c100290|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-175acfb2> |AST 94|Tier 2|Time 506( 262+244 )ms|Inlined 13Y 0N|IR 787/ 3402|CodeSize 14222|Addr 0x7fd30c103810|Src n/a
    [engine] opt done LoopTesterApp>>buildDiamond: <split-1c12f3ee> |AST 157|Tier 2|Time 4659(1697+2962)ms|Inlined 66Y 4N|IR 8891/26180|CodeSize 131084|Addr 0x7fd30c10bd10|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-3703bf3c> |AST 76|Tier 2|Time 129( 109+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fd30c17dc10|Src n/a
    [engine] opt done BasicBlockEdge>>init:from:to: <split-55ea2d70> |AST 96|Tier 2|Time 1102( 529+573 )ms|Inlined 25Y 0N|IR 2659/ 8987|CodeSize 42303|Addr 0x7fd30c17f990|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-34cf5a97> |AST 94|Tier 2|Time 402( 268+134 )ms|Inlined 13Y 0N|IR 787/ 3402|CodeSize 14222|Addr 0x7fd30c199990|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-bd2f5a9> |AST 76|Tier 2|Time 125( 105+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fd30c1a1e90|Src n/a
    [engine] opt done BasicBlockEdge>>init:from:to: <split-4482469c> |AST 96|Tier 2|Time 960( 503+457 )ms|Inlined 25Y 0N|IR 2659/ 8987|CodeSize 42303|Addr 0x7fd30c1a3c10|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-4d4960c8> |AST 115|Tier 2|Time 475( 333+142 )ms|Inlined 14Y 0N|IR 996/ 3505|CodeSize 15092|Addr 0x7fd30c1bdc10|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-57705d35> |AST 76|Tier 2|Time 126( 105+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fd30c1c7190|Src n/a
    [engine] opt done BasicBlockEdge>>init:from:to: <split-60921b21> |AST 96|Tier 2|Time 1082( 544+538 )ms|Inlined 26Y 0N|IR 2888/ 9364|CodeSize 44898|Addr 0x7fd30c1c8f10|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-5dc5c625> |AST 115|Tier 2|Time 431( 290+141 )ms|Inlined 14Y 0N|IR 996/ 3505|CodeSize 15092|Addr 0x7fd30c1e4890|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-27068a50> |AST 115|Tier 2|Time 449( 304+145 )ms|Inlined 14Y 0N|IR 996/ 3505|CodeSize 15092|Addr 0x7fd30c1ee810|Src n/a
    [engine] opt done BasicBlockEdge>>init:from:to: <split-6ffc5e28> |AST 96|Tier 2|Time 1072( 567+505 )ms|Inlined 26Y 0N|IR 2888/ 9364|CodeSize 44898|Addr 0x7fd30c1f7d90|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-11653e3b> |AST 115|Tier 2|Time 552( 312+240 )ms|Inlined 14Y 0N|IR 996/ 3505|CodeSize 15092|Addr 0x7fd30c214290|Src n/a
    [engine] opt done Behavior>>new <split-6b580b88> |AST 26|Tier 2|Time 44( 42+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fd30c21dd90|Src n/a
    [engine] opt done BasicBlockEdge class>>for:from:to: <split-773bd77b> |AST 37|Tier 2|Time 1430( 638+792 )ms|Inlined 28Y 0N|IR 2917/ 9107|CodeSize 44533|Addr 0x7fd30c21ff90|Src n/a
    [engine] opt done BasicBlockEdge>>init:from:to: <split-6d91790b> |AST 96|Tier 2|Time 1158( 517+641 )ms|Inlined 26Y 0N|IR 2888/ 9364|CodeSize 44898|Addr 0x7fd30c241410|Src n/a
    [engine] opt done Behavior>>new <split-a567e72> |AST 26|Tier 2|Time 46( 43+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fd30c25cd90|Src n/a
    [engine] opt done BasicBlockEdge>>init:from:to: <split-1a5b8489> |AST 96|Tier 2|Time 1053( 504+549 )ms|Inlined 25Y 0N|IR 2659/ 8987|CodeSize 42303|Addr 0x7fd30c25d390|Src n/a
    [engine] opt done BasicBlockEdge class>>for:from:to: <split-6ce90bc5> |AST 37|Tier 2|Time 1218( 518+701 )ms|Inlined 27Y 0N|IR 2685/ 8840|CodeSize 41857|Addr 0x7fd30c277390|Src n/a
    [engine] opt done Behavior>>new <split-34b9fc7d> |AST 26|Tier 2|Time 45( 42+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fd30c297810|Src n/a
    [engine] opt done BasicBlockEdge>>init:from:to: <split-27f1bbe0> |AST 96|Tier 2|Time 1060( 494+566 )ms|Inlined 25Y 0N|IR 2659/ 8987|CodeSize 42303|Addr 0x7fd30c298110|Src n/a
    [engine] opt done BasicBlockEdge class>>for:from:to: <split-72805168> |AST 37|Tier 2|Time 1221( 517+704 )ms|Inlined 27Y 0N|IR 2685/ 8840|CodeSize 41857|Addr 0x7fd30c2b2110|Src n/a
    [engine] opt done Behavior>>new <split-2d84cb86> |AST 26|Tier 2|Time 44( 41+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fd30c2d2290|Src n/a
    [engine] opt done LoopTesterApp>>buildDiamond: <split-7808fb9> |AST 157|Tier 2|Time 4581(1855+2726)ms|Inlined 66Y 3N|IR 8762/25670|CodeSize 128866|Addr 0x7fd30c2d2c10|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-4b1abd11> |AST 76|Tier 2|Time 134( 114+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fd30c343290|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-3f36b447> |AST 76|Tier 2|Time 135( 115+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fd30c345010|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-332f25c8> |AST 76|Tier 2|Time 130( 109+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fd30c346d90|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-1b32cd16> |AST 76|Tier 2|Time 202( 181+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fd30c349f10|Src n/a
    [engine] opt done BasicBlockEdge>>init:from:to: <split-695a69a1> |AST 96|Tier 2|Time 766( 465+301 )ms|Inlined 16Y 0N|IR 2265/ 6131|CodeSize 28656|Addr 0x7fd30c34bc90|Src n/a
    [engine] opt done BasicBlockEdge>>init:from:to: <split-4a1c0752> |AST 96|Tier 2|Time 740( 443+297 )ms|Inlined 16Y 0N|IR 2265/ 6131|CodeSize 28656|Addr 0x7fd30c35dd90|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-7c211fd0> |AST 94|Tier 2|Time 393( 259+134 )ms|Inlined 13Y 0N|IR 787/ 3402|CodeSize 14222|Addr 0x7fd30c370290|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-847f3e7> |AST 76|Tier 2|Time 131( 110+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fd30c378e10|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-69cac930> |AST 76|Tier 2|Time 125( 104+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fd30c37ab90|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-47c64cfe> |AST 115|Tier 2|Time 444( 299+145 )ms|Inlined 14Y 0N|IR 996/ 3505|CodeSize 15092|Addr 0x7fd30c37c910|Src n/a
    [engine] opt done SimpleLoop class>>basicBlock:reducible: <split-afb5821> |AST 34|Tier 2|Time 324( 291+33 )ms|Inlined 14Y 0N|IR 523/ 1565|CodeSize 5677|Addr 0x7fd30c385e90|Src n/a
    [engine] opt done BasicBlockEdge>>init:from:to: <split-264c5d07> |AST 96|Tier 2|Time 732( 370+362 )ms|Inlined 16Y 0N|IR 2265/ 6131|CodeSize 28656|Addr 0x7fd30c388890|Src n/a
    [engine] opt done LoopStructureGraph>>initialize |AST 113|Tier 2|Time 548( 427+120 )ms|Inlined 23Y 0N|IR 1340/ 3925|CodeSize 15409|Addr 0x7fd30c39a990|Src n/a
    [engine] opt done LoopTesterApp>>buildConnect:end: <split-6f0c74a4> |AST 31|Tier 2|Time 1033( 412+621 )ms|Inlined 19Y 0N|IR 2356/ 6039|CodeSize 26796|Addr 0x7fd30c3a3510|Src n/a
    [engine] opt done BasicBlockEdge class>>for:from:to: <split-aeac777> |AST 37|Tier 2|Time 946( 420+525 )ms|Inlined 18Y 0N|IR 2296/ 5984|CodeSize 27047|Addr 0x7fd30c3bce10|Src n/a
    [engine] opt done Behavior>>new <split-1d4664d7> |AST 28|Tier 2|Time 465( 385+79 )ms|Inlined 24Y 0N|IR 925/ 2541|CodeSize 7811|Addr 0x7fd30c3d3490|Src n/a
    [engine] opt done LoopStructureGraph class>>new |AST 26|Tier 2|Time 800( 633+167 )ms|Inlined 49Y 0N|IR 1668/ 4513|CodeSize 15876|Addr 0x7fd30c3d7c10|Src n/a
    [engine] opt done LoopTesterApp>>main:loop:p:p:p: |AST 31|Tier 2|Time 1383( 934+449 )ms|Inlined 66Y 1N|IR 2026/ 5861|CodeSize 23132|Addr 0x7fd30c3e0310|Src n/a
    [engine] opt done Integer>>timesRepeat: <split-458544e0> |AST 46|Tier 2|Time 1786(1005+780 )ms|Inlined 67Y 1N|IR 2148/10522|CodeSize 39938|Addr 0x7fd30c3ebd10|Src n/a
    [engine] opt done LoopTesterApp>>constructCFG:p:p: <split-6a1e63e3> |AST 106|Tier 2|Time 5701(2231+3470)ms|Inlined 71Y 3N|IR 8637/26138|CodeSize 127158|Addr 0x7fd30c400310|Src n/a
    [engine] opt done HavlakLoopFinder>>initAllNodes <split-32fd5cd1> |AST 64|Tier 2|Time 3799(1358+2441)ms|Inlined 88Y 3N|IR 5594/17901|CodeSize 92897|Addr 0x7fd30c476790|Src n/a
    [engine] opt done Integer>>timesRepeat: <split-2d66530f> |AST 46|Tier 2|Time 719( 664+55 )ms|Inlined 0Y 1N|IR 192/ 1707|CodeSize 5422|Addr 0x7fd30c4cca90|Src n/a
    [engine] opt done ControlFlowGraph>>createNode: <split-2f1a253a> |AST 115|Tier 2|Time 498( 335+163 )ms|Inlined 14Y 0N|IR 982/ 3540|CodeSize 15491|Addr 0x7fd30c4cf210|Src n/a
    [engine] opt done LoopTesterApp>>buildConnect:end: <split-16bac21a> |AST 31|Tier 2|Time 1132( 493+638 )ms|Inlined 19Y 0N|IR 2356/ 6039|CodeSize 26796|Addr 0x7fd30c4dad10|Src n/a
    [engine] opt done LoopTesterApp>>buildConnect:end: <split-3ad72cfe> |AST 31|Tier 2|Time 1100( 433+667 )ms|Inlined 19Y 0N|IR 2356/ 6039|CodeSize 26796|Addr 0x7fd30c4f4610|Src n/a
    [engine] opt done BasicBlockEdge class>>for:from:to: <split-10e35d36> |AST 37|Tier 2|Time 967( 406+561 )ms|Inlined 18Y 0N|IR 2296/ 5984|CodeSize 27047|Addr 0x7fd30c50df10|Src n/a
    [engine] opt done LoopTesterApp>>constructCFG:p:p: <split-50c94974> |AST 115|Tier 2|Time 3741(1836+1905)ms|Inlined 55Y 1N|IR 6023/21034|CodeSize 86985|Addr 0x7fd30c524910|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 160( 140+19 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7fd30c56b110|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 233( 213+20 )ms|Inlined 4Y 1N|IR 312/ 383|CodeSize 1330|Addr 0x7fd30c56c210|Src n/a
    [engine] opt done ControlFlowGraph>>initialize |AST 38|Tier 2|Time 222( 205+17 )ms|Inlined 8Y 0N|IR 129/ 750|CodeSize 2292|Addr 0x7fd30c579110|Src n/a
    [engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 269( 233+36 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7fd30c57c390|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 220
    Success : 214
    Temporary Bailouts : 4
    org.graalvm.compiler.core.common.CancellationBailoutException: Compilation cancelled.: 3
    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 : 2
    Invalidated : 21
    null : 17
    Latest layout assumption Layout no longer valid: 2
    Queues : 377
    Dequeues : 182
    Target inlined into only caller : 164
    null : 17
    Split call node : 1
    Splits : 654
    Compilation Accuracy : 0.904545
    Queue Accuracy : 0.517241
    Compilation Utilization : 0.534531
    Remaining Compilation Queue : 0
    Time to queue : count= 377, sum= 6361407, min= 4, average= 16873.76, max= 290486 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 220, sum= 1527489, min= 0, average= 6943.14, max= 26033 (milliseconds), maxTarget=HavlakLoopFinder>>stepEProcessNonBackPreds:nodePool:workList:x:
    Time for compilation : count= 218, sum= 155720, min= 23, average= 714.32, max= 5701 (milliseconds), maxTarget=LoopTesterApp>>constructCFG:p:p:
    Truffle Tier : count= 214, sum= 77824, min= 20, average= 363.67, max= 2242 (milliseconds), maxTarget=HavlakLoopFinder>>findLoops
    Graal Tier : count= 214, sum= 51356, min= 1, average= 239.99, max= 2633 (milliseconds), maxTarget=HavlakLoopFinder>>findLoops
    Code Installation : count= 214, sum= 24286, min= 1, average= 113.49, max= 1221 (milliseconds), maxTarget=LoopTesterApp>>constructCFG:p:p:
    Truffle node count : count= 218, sum= 262564, min= 12, average= 1204.42, max= 7460, maxTarget=HavlakLoopFinder>>initAllNodes
    Trivial : count= 218, sum= 100416, min= 4, average= 460.62, max= 2819, maxTarget=LoopTesterApp>>buildDiamond:
    Non Trivial : count= 218, sum= 162148, min= 8, average= 743.80, max= 4716, maxTarget=HavlakLoopFinder>>initAllNodes
    Monomorphic : count= 218, sum= 159506, min= 8, average= 731.68, max= 4677, maxTarget=HavlakLoopFinder>>initAllNodes
    Polymorphic : count= 218, sum= 2642, min= 0, average= 12.12, max= 101, maxTarget=LoopTesterApp>>buildDiamond:
    Megamorphic : count= 218, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
    Truffle call count : count= 218, sum= 3007, min= 0, average= 13.79, max= 91, maxTarget=HavlakLoopFinder>>initAllNodes
    Indirect : count= 218, sum= 1, min= 0, average= 0.00, max= 1, maxTarget=Integer>>timesRepeat:
    Direct : count= 218, sum= 3006, min= 0, average= 13.79, max= 91, maxTarget=HavlakLoopFinder>>initAllNodes
    Dispatched : count= 218, sum= 85, min= 0, average= 0.39, max= 11, maxTarget=HavlakLoopFinder>>findLoops
    Inlined : count= 218, sum= 2921, min= 0, average= 13.40, max= 88, maxTarget=HavlakLoopFinder>>initAllNodes
    ---------- :
    Cloned : count= 218, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
    Not Cloned : count= 218, sum= 3012, min= 0, average= 13.82, max= 91, maxTarget=HavlakLoopFinder>>initAllNodes
    Truffle loops : count= 218, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
    Graal node count :
    After Truffle Tier : count= 218, sum= 297430, min= 5, average= 1364.36, max= 11412, maxTarget=HavlakLoopFinder>>findLoops
    After Graal Tier : count= 215, sum= 932044, min= 5, average= 4335.09, max= 41700, maxTarget=HavlakLoopFinder>>findLoops
    Graal compilation result :
    Code size : count= 214, sum= 4164260, min= 120, average= 19459.16, max= 178109, maxTarget=HavlakLoopFinder>>findLoops
    Total frame size : count= 214, sum= 68432, min= 32, average= 319.78, max= 1840, maxTarget=LoopTesterApp>>buildDiamond:
    Exception handlers : count= 214, sum= 137, min= 0, average= 0.64, max= 17, maxTarget=HavlakLoopFinder>>initAllNodes
    Infopoints : count= 214, sum= 37029, min= 4, average= 173.03, max= 1547, maxTarget=HavlakLoopFinder>>findLoops
    CALL : count= 214, sum= 28662, min= 4, average= 133.93, max= 1239, maxTarget=HavlakLoopFinder>>findLoops
    IMPLICIT_EXCEPTION : count= 214, sum= 7507, min= 0, average= 35.08, max= 289, maxTarget=HavlakLoopFinder>>findLoops
    SAFEPOINT : count= 214, sum= 860, min= 0, average= 4.02, max= 27, maxTarget=LoopTesterApp>>buildDiamond:
    Marks : count= 214, sum= 2593, min= 5, average= 12.12, max= 42, maxTarget=HavlakLoopFinder>>findLoops
    Data references : count= 214, sum= 28420, min= 0, average= 132.80, max= 1081, maxTarget=HavlakLoopFinder>>findLoops
    148 changes: 148 additions & 0 deletions 5d99b29f-Json.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,148 @@
    # Json (iterations: 250, problem size: 100) on Thu May 27 21:34:15 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Json.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'Json' 250 100)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done SequenceableCollection>>atAllPut: |AST 72|Tier 2|Time 209( 177+32 )ms|Inlined 0Y 0N|IR 184/ 407|CodeSize 1641|Addr 0x7fcdff8f0d90|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 191( 174+17 )ms|Inlined 2Y 1N|IR 213/ 526|CodeSize 1925|Addr 0x7fcdff8fdd90|Src n/a
    [engine] opt done Character>>asString |AST 22|Tier 2|Time 251( 241+10 )ms|Inlined 4Y 1N|IR 191/ 259|CodeSize 920|Addr 0x7fcdff908e90|Src n/a
    [engine] opt done String>>compareWith: <split-6719a5b8> |AST 25|Tier 2|Time 99( 90+9 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fcdff924990|Src n/a
    [engine] opt done String>>= <split-2e1792e7> |AST 69|Tier 2|Time 173( 158+15 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdff926c10|Src n/a
    [engine] opt done String>>= <split-6bff19ff> |AST 48|Tier 2|Time 66( 62+4 )ms|Inlined 0Y 0N|IR 43/ 72|CodeSize 381|Addr 0x7fcdff932990|Src n/a
    [engine] opt done Vector>>append: |AST 163|Tier 2|Time 188( 142+46 )ms|Inlined 0Y 0N|IR 456/ 1671|CodeSize 7519|Addr 0x7fcdff93b910|Src n/a
    [engine] opt deopt Vector>>append: |AST 163|Src n/a
    [engine] opt done JsonParser>>readStringInternal |AST 111|Tier 2|Time 1089( 936+153 )ms|Inlined 36Y 4N|IR 2128/ 2851|CodeSize 10085|Addr 0x7fcdff950510|Src n/a
    [engine] opt done String>>compareWith:collated: <split-516ebdf8> |AST 33|Tier 2|Time 73( 66+7 )ms|Inlined 1Y 0N|IR 171/ 213|CodeSize 607|Addr 0x7fcdff959d90|Src n/a
    [engine] opt done SequenceableCollection>>copyFrom:to: <split-3eba57a7> |AST 68|Tier 2|Time 152( 129+23 )ms|Inlined 3Y 1N|IR 325/ 831|CodeSize 3402|Addr 0x7fcdff95b790|Src n/a
    [engine] opt done String>>compare:with:collated: <split-4d8539de> |AST 51|Tier 2|Time 68( 61+6 )ms|Inlined 0Y 0N|IR 137/ 181|CodeSize 607|Addr 0x7fcdff95dc90|Src n/a
    [engine] opt done String>>compareWith: <split-5f78de22> |AST 25|Tier 2|Time 76( 68+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fcdff960190|Src n/a
    [engine] opt done String>>= <split-6a933be2> |AST 69|Tier 2|Time 260( 250+10 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdff963010|Src n/a
    [engine] opt done Vector class>>new: |AST 29|Tier 2|Time 85( 79+6 )ms|Inlined 2Y 0N|IR 60/ 319|CodeSize 1095|Addr 0x7fcdff966290|Src n/a
    [engine] opt done JsonParser>>readArrayElement: |AST 58|Tier 2|Time 622( 375+247 )ms|Inlined 20Y 1N|IR 1469/ 4631|CodeSize 13736|Addr 0x7fcdff966f10|Src n/a
    [engine] opt done String>>= <split-4d6f197e> |AST 69|Tier 2|Time 107( 98+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdff970a10|Src n/a
    [engine] opt done String>>compareWith: <split-6ef7623> |AST 25|Tier 2|Time 77( 70+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fcdff971790|Src n/a
    [engine] opt done String>>compare:with:collated: <split-5c089b2f> |AST 51|Tier 2|Time 53( 46+7 )ms|Inlined 0Y 0N|IR 137/ 181|CodeSize 607|Addr 0x7fcdff972610|Src n/a
    [engine] opt done String>>compareWith:collated: <split-64e1dd11> |AST 33|Tier 2|Time 71( 64+7 )ms|Inlined 1Y 0N|IR 171/ 213|CodeSize 607|Addr 0x7fcdff972f10|Src n/a
    [engine] opt done String>>= <split-6fe46b62> |AST 48|Tier 2|Time 235( 232+3 )ms|Inlined 0Y 0N|IR 43/ 72|CodeSize 381|Addr 0x7fcdff974910|Src n/a
    [engine] opt done JsonParser>>readNumber |AST 136|Tier 2|Time 2479(2110+369 )ms|Inlined 67Y 7N|IR 3750/ 3576|CodeSize 9247|Addr 0x7fcdff977c90|Src n/a
    [engine] opt done JsonParser>>read <split-4b6ac111> |AST 109|Tier 2|Time 401( 386+15 )ms|Inlined 6Y 1N|IR 431/ 677|CodeSize 2152|Addr 0x7fcdff97fa10|Src n/a
    [engine] opt done Behavior>>new <split-5f462e3b> |AST 26|Tier 2|Time 49( 46+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fcdff980e10|Src n/a
    [engine] opt done Vector>>initialize: |AST 30|Tier 2|Time 62( 56+6 )ms|Inlined 0Y 0N|IR 142/ 292|CodeSize 804|Addr 0x7fcdff981710|Src n/a
    [engine] opt inv. Vector>>append: |AST 163|Calls/Thres 17609/ 3|CallsAndLoop/Thres 18209/ 1000|Src n/a
    [engine] opt done Vector>>append: |AST 163|Tier 2|Time 172( 121+51 )ms|Inlined 0Y 0N|IR 453/ 1711|CodeSize 7559|Addr 0x7fcdff982490|Src n/a
    [engine] opt done String>>= <split-2dce08ff> |AST 48|Tier 2|Time 54( 51+3 )ms|Inlined 0Y 0N|IR 43/ 72|CodeSize 381|Addr 0x7fcdff986e90|Src n/a
    [engine] opt done JsonParser>>read <split-6db93db1> |AST 105|Tier 2|Time 211( 197+15 )ms|Inlined 6Y 1N|IR 400/ 564|CodeSize 1792|Addr 0x7fcdff987410|Src n/a
    [engine] opt done Behavior>>new <split-305de394> |AST 28|Tier 2|Time 112( 105+6 )ms|Inlined 5Y 0N|IR 63/ 445|CodeSize 1572|Addr 0x7fcdff988810|Src n/a
    [engine] opt done JsonArray class>>new |AST 26|Tier 2|Time 157( 151+7 )ms|Inlined 11Y 0N|IR 73/ 445|CodeSize 1572|Addr 0x7fcdff989b90|Src n/a
    [engine] opt done JsonParser>>skipWhiteSpace |AST 19|Tier 2|Time 209( 187+22 )ms|Inlined 12Y 0N|IR 650/ 492|CodeSize 1606|Addr 0x7fcdff98d190|Src n/a
    [engine] opt done JsonParser>>readChar: |AST 39|Tier 2|Time 409( 254+155 )ms|Inlined 11Y 1N|IR 731/ 889|CodeSize 2815|Addr 0x7fcdff98e890|Src n/a
    [engine] opt done String>>= <split-7c9b78e3> |AST 69|Tier 2|Time 105( 96+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdff995e90|Src n/a
    [engine] opt done String>>= <split-736ac09a> |AST 69|Tier 2|Time 107( 98+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdff997610|Src n/a
    [engine] opt done String>>= <split-3b0ca5e1> |AST 69|Tier 2|Time 105( 96+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdff999290|Src n/a
    [engine] opt done String>>= <split-2a037324> |AST 69|Tier 2|Time 106( 97+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdff99b090|Src n/a
    [engine] opt done JsonParser>>startCapture |AST 12|Tier 2|Time 34( 31+3 )ms|Inlined 0Y 0N|IR 74/ 87|CodeSize 271|Addr 0x7fcdff99c090|Src n/a
    [engine] opt done JsonParser>>endCapture |AST 64|Tier 2|Time 281( 210+71 )ms|Inlined 8Y 1N|IR 667/ 1170|CodeSize 4091|Addr 0x7fcdff99c710|Src n/a
    [engine] opt done JsonParser>>readArray |AST 135|Tier 2|Time 2018(1619+399 )ms|Inlined 62Y 6N|IR 2902/ 4808|CodeSize 15431|Addr 0x7fcdff9a0410|Src n/a
    [engine] opt done JsonParser>>isDigit |AST 196|Tier 2|Time 644( 546+98 )ms|Inlined 40Y 0N|IR 2517/ 1877|CodeSize 2724|Addr 0x7fcdff9ac690|Src n/a
    [engine] opt done JsonParser>>readDigit |AST 34|Tier 2|Time 1003( 866+137 )ms|Inlined 48Y 1N|IR 2977/ 2513|CodeSize 4016|Addr 0x7fcdff9b1710|Src n/a
    [engine] opt done Vector class>>new |AST 20|Tier 2|Time 275( 270+5 )ms|Inlined 3Y 0N|IR 49/ 290|CodeSize 1040|Addr 0x7fcdff9b8990|Src n/a
    [engine] opt done String>>= <split-d02f8d> |AST 69|Tier 2|Time 106( 97+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdff9b9d90|Src n/a
    [engine] opt done JsonParser>>readRequiredChar: |AST 22|Tier 2|Time 308( 259+49 )ms|Inlined 12Y 1N|IR 768/ 971|CodeSize 2613|Addr 0x7fcdff9bab10|Src n/a
    [engine] opt done JsonString class>>new: |AST 31|Tier 2|Time 65( 62+3 )ms|Inlined 2Y 0N|IR 39/ 99|CodeSize 433|Addr 0x7fcdff9bed10|Src n/a
    [engine] opt done JsonParser>>readValue |AST 531|Tier 2|Time 2611(1954+657 )ms|Inlined 74Y 28N|IR 5279/ 8114|CodeSize 24251|Addr 0x7fcdff9bf310|Src n/a
    [engine] opt done JsonArray>>initialize |AST 22|Tier 2|Time 101( 95+7 )ms|Inlined 4Y 0N|IR 95/ 433|CodeSize 1305|Addr 0x7fcdff9d3d10|Src n/a
    [engine] opt done HashIndexTable>>initialize |AST 26|Tier 2|Time 140( 112+27 )ms|Inlined 2Y 0N|IR 274/ 534|CodeSize 1577|Addr 0x7fcdff9d4990|Src n/a
    [engine] opt done HashIndexTable>>stringHash: |AST 21|Tier 2|Time 43( 40+3 )ms|Inlined 0Y 0N|IR 32/ 108|CodeSize 467|Addr 0x7fcdff9d6b90|Src n/a
    [engine] opt done HashIndexTable>>hashSlotFor: |AST 52|Tier 2|Time 80( 75+4 )ms|Inlined 1Y 0N|IR 60/ 167|CodeSize 714|Addr 0x7fcdff9d7190|Src n/a
    [engine] opt done String>>= <split-1136b469> |AST 69|Tier 2|Time 189( 179+10 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdff9d7c10|Src n/a
    [engine] opt done Vector>>size |AST 18|Tier 2|Time 33( 30+3 )ms|Inlined 0Y 0N|IR 32/ 110|CodeSize 451|Addr 0x7fcdff9d8d90|Src n/a
    [engine] opt done JsonParser>>readName |AST 35|Tier 2|Time 985( 785+200 )ms|Inlined 41Y 4N|IR 2410/ 3086|CodeSize 10475|Addr 0x7fcdff9d9590|Src n/a
    [engine] opt done JsonObject>>add:with: |AST 98|Tier 2|Time 601( 245+356 )ms|Inlined 6Y 0N|IR 1133/ 3571|CodeSize 16720|Addr 0x7fcdff9e3b10|Src n/a
    [engine] opt done JsonParser>>readObjectKeyValuePair: |AST 117|Tier 2|Time 2591(1781+810 )ms|Inlined 94Y 6N|IR 5951/ 9649|CodeSize 35986|Addr 0x7fcdff9f5f90|Src n/a
    [engine] opt done JsonParser>>readNull |AST 78|Tier 2|Time 1038( 924+114 )ms|Inlined 47Y 4N|IR 2427/ 2530|CodeSize 7091|Addr 0x7fcdffa0fd90|Src n/a
    [engine] opt done String>>= <split-57bd802b> |AST 69|Tier 2|Time 107( 98+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdffa17590|Src n/a
    [engine] opt done HashIndexTable class>>new |AST 26|Tier 2|Time 234( 168+66 )ms|Inlined 7Y 0N|IR 529/ 1015|CodeSize 2761|Addr 0x7fcdffa21390|Src n/a
    [engine] opt done JsonObject>>initialize |AST 54|Tier 2|Time 330( 240+90 )ms|Inlined 16Y 0N|IR 663/ 1786|CodeSize 5551|Addr 0x7fcdffa25710|Src n/a
    [engine] opt done JsonParser>>readObject |AST 130|Tier 2|Time 2680(2290+390 )ms|Inlined 78Y 7N|IR 3593/ 5387|CodeSize 15613|Addr 0x7fcdffa2b190|Src n/a
    [engine] opt done String>>= <split-ddf20fd> |AST 69|Tier 2|Time 104( 95+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdffa38b10|Src n/a
    [engine] opt done String>>= <split-3f36b447> |AST 69|Tier 2|Time 214( 204+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdffa3c790|Src n/a
    [engine] opt done String>>compareWith:collated: <split-4a03bb68> |AST 33|Tier 2|Time 77( 69+7 )ms|Inlined 1Y 0N|IR 171/ 213|CodeSize 607|Addr 0x7fcdffa41490|Src n/a
    [engine] opt done String>>compareWith: <split-175acfb2> |AST 25|Tier 2|Time 85( 77+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fcdffa41f10|Src n/a
    [engine] opt done String>>= <split-5e742e4> |AST 69|Tier 2|Time 119( 109+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdffa43710|Src n/a
    [engine] opt done String>>compareWith: <split-71c905a3> |AST 25|Tier 2|Time 81( 73+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fcdffa44790|Src n/a
    [engine] opt done String>>= <split-59ab43ad> |AST 69|Tier 2|Time 114( 105+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdffa45390|Src n/a
    [engine] opt done String>>compareWith: <split-1dab9dd6> |AST 25|Tier 2|Time 83( 76+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fcdffa4a810|Src n/a
    [engine] opt done String>>= <split-7710e2ab> |AST 69|Tier 2|Time 112( 103+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdffa4b410|Src n/a
    [engine] opt done String>>compareWith: <split-afb5821> |AST 25|Tier 2|Time 83( 75+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fcdffa4c190|Src n/a
    [engine] opt done String>>= <split-602371d9> |AST 69|Tier 2|Time 118( 108+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdffa4d190|Src n/a
    [engine] opt done String>>= <split-2f879bab> |AST 48|Tier 2|Time 61( 58+3 )ms|Inlined 0Y 0N|IR 43/ 72|CodeSize 381|Addr 0x7fcdffa4df10|Src n/a
    [engine] opt done JsonLiteral class>>TRUE |AST 10|Tier 2|Time 38( 36+2 )ms|Inlined 0Y 0N|IR 21/ 27|CodeSize 230|Addr 0x7fcdffa4e490|Src n/a
    [engine] opt done JsonParser>>read <split-7fedfe27> |AST 105|Tier 2|Time 226( 213+13 )ms|Inlined 6Y 1N|IR 400/ 564|CodeSize 1792|Addr 0x7fcdffa4ec10|Src n/a
    [engine] opt done String>>= <split-1f25d52f> |AST 69|Tier 2|Time 126( 116+10 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fcdffa4fd10|Src n/a
    [engine] opt done Vector>>at: |AST 39|Tier 2|Time 59( 55+4 )ms|Inlined 0Y 0N|IR 69/ 101|CodeSize 514|Addr 0x7fcdffa50a90|Src n/a
    [engine] opt done Object>>= |AST 14|Tier 2|Time 41( 36+4 )ms|Inlined 0Y 0N|IR 76/ 131|CodeSize 513|Addr 0x7fcdffa51110|Src n/a
    [engine] opt done JsonParser>>read <split-2d66530f> |AST 105|Tier 2|Time 298( 285+13 )ms|Inlined 6Y 1N|IR 400/ 564|CodeSize 1792|Addr 0x7fcdffa53f90|Src n/a
    [engine] opt done JsonLiteral class>>FALSE |AST 10|Tier 2|Time 26( 25+2 )ms|Inlined 0Y 0N|IR 21/ 27|CodeSize 230|Addr 0x7fcdffa55410|Src n/a
    [engine] opt done JsonParser>>readTrue |AST 78|Tier 2|Time 1005( 883+122 )ms|Inlined 47Y 4N|IR 2428/ 2562|CodeSize 7037|Addr 0x7fcdffa55e10|Src n/a
    [engine] opt done JsonObject>>at: |AST 60|Tier 2|Time 250( 204+47 )ms|Inlined 10Y 0N|IR 543/ 617|CodeSize 1867|Addr 0x7fcdffa5ba10|Src n/a
    [engine] opt done JsonParser>>readFalse |AST 93|Tier 2|Time 1210(1040+170 )ms|Inlined 58Y 5N|IR 3063/ 3163|CodeSize 8306|Addr 0x7fcdffa5e190|Src n/a
    [engine] opt done Json class>>RapBenchmarkMinified |AST 8|Tier 2|Time 26( 24+2 )ms|Inlined 0Y 0N|IR 17/ 18|CodeSize 179|Addr 0x7fcdffa66610|Src n/a
    [engine] opt done JsonParser class>>with: |AST 31|Tier 2|Time 100( 93+7 )ms|Inlined 2Y 0N|IR 186/ 374|CodeSize 1299|Addr 0x7fcdffa66a10|Src n/a
    [engine] opt done JsonParser>>parse |AST 82|Tier 2|Time 638( 526+112 )ms|Inlined 23Y 2N|IR 1821/ 3794|CodeSize 11628|Addr 0x7fcdffa67b90|Src n/a
    [engine] opt done Json>>benchmark |AST 44|Tier 2|Time 808( 550+258 )ms|Inlined 28Y 2N|IR 1528/ 3275|CodeSize 10463|Addr 0x7fcdffa6d190|Src n/a
    [engine] opt done JsonArray>>size |AST 20|Tier 2|Time 53( 50+4 )ms|Inlined 1Y 0N|IR 46/ 128|CodeSize 536|Addr 0x7fcdffa72510|Src n/a
    [engine] opt done Json>>verifyResult: |AST 126|Tier 2|Time 676( 541+134 )ms|Inlined 35Y 0N|IR 1534/ 1269|CodeSize 3432|Addr 0x7fcdffa72b90|Src n/a
    [engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 1697(1037+660 )ms|Inlined 65Y 2N|IR 3151/ 6182|CodeSize 20644|Addr 0x7fcdffa77390|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 281( 257+23 )ms|Inlined 4Y 1N|IR 361/ 419|CodeSize 1240|Addr 0x7fcdffa8df10|Src n/a
    [engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 305( 249+55 )ms|Inlined 3Y 1N|IR 474/ 1460|CodeSize 6553|Addr 0x7fcdffa91e10|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 106
    Success : 90
    Temporary Bailouts : 3
    org.graalvm.compiler.core.common.CancellationBailoutException: Compilation cancelled.: 3
    Permanent Bailouts : 0
    Failed : 0
    Interrupted : 13
    Invalidated : 1
    null : 1
    Queues : 342
    Dequeues : 252
    Target inlined into only caller : 248
    Split call node : 3
    null : 1
    Splits : 459
    Compilation Accuracy : 0.990566
    Queue Accuracy : 0.263158
    Compilation Utilization : 0.522466
    Remaining Compilation Queue : 0
    Time to queue : count= 342, sum= 1040187, min= 121, average= 3041.48, max= 66743 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 106, sum= 289700, min= 0, average= 2733.02, max= 7732 (milliseconds), maxTarget=JsonParser>>read
    Time for compilation : count= 93, sum= 34924, min= 26, average= 375.53, max= 2680 (milliseconds), maxTarget=JsonParser>>readObject
    Truffle Tier : count= 90, sum= 27918, min= 24, average= 310.21, max= 2290 (milliseconds), maxTarget=JsonParser>>readObject
    Graal Tier : count= 90, sum= 4841, min= 1, average= 53.79, max= 614 (milliseconds), maxTarget=JsonParser>>readObjectKeyValuePair:
    Code Installation : count= 90, sum= 1841, min= 1, average= 20.46, max= 196 (milliseconds), maxTarget=JsonParser>>readObjectKeyValuePair:
    Truffle node count : count= 93, sum= 90030, min= 12, average= 968.06, max= 8014, maxTarget=JsonParser>>readObjectKeyValuePair:
    Trivial : count= 93, sum= 33405, min= 4, average= 359.19, max= 3001, maxTarget=JsonParser>>readObjectKeyValuePair:
    Non Trivial : count= 93, sum= 56625, min= 8, average= 608.87, max= 5013, maxTarget=JsonParser>>readObjectKeyValuePair:
    Monomorphic : count= 93, sum= 56068, min= 8, average= 602.88, max= 4967, maxTarget=JsonParser>>readObjectKeyValuePair:
    Polymorphic : count= 93, sum= 557, min= 0, average= 5.99, max= 46, maxTarget=JsonParser>>readObjectKeyValuePair:
    Megamorphic : count= 93, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=SequenceableCollection>>atAllPut:
    Truffle call count : count= 93, sum= 1185, min= 0, average= 12.74, max= 102, maxTarget=JsonParser>>readValue
    Indirect : count= 93, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=SequenceableCollection>>atAllPut:
    Direct : count= 93, sum= 1185, min= 0, average= 12.74, max= 102, maxTarget=JsonParser>>readValue
    Dispatched : count= 93, sum= 95, min= 0, average= 1.02, max= 28, maxTarget=JsonParser>>readValue
    Inlined : count= 93, sum= 1090, min= 0, average= 11.72, max= 94, maxTarget=JsonParser>>readObjectKeyValuePair:
    ---------- :
    Cloned : count= 93, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=SequenceableCollection>>atAllPut:
    Not Cloned : count= 93, sum= 1185, min= 0, average= 12.74, max= 102, maxTarget=JsonParser>>readValue
    Truffle loops : count= 93, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=SequenceableCollection>>atAllPut:
    Graal node count :
    After Truffle Tier : count= 93, sum= 67706, min= 17, average= 728.02, max= 5951, maxTarget=JsonParser>>readObjectKeyValuePair:
    After Graal Tier : count= 90, sum= 101305, min= 18, average= 1125.61, max= 9649, maxTarget=JsonParser>>readObjectKeyValuePair:
    Graal compilation result :
    Code size : count= 90, sum= 320770, min= 179, average= 3564.11, max= 35986, maxTarget=JsonParser>>readObjectKeyValuePair:
    Total frame size : count= 90, sum= 7680, min= 32, average= 85.33, max= 576, maxTarget=JsonParser>>readObjectKeyValuePair:
    Exception handlers : count= 90, sum= 38, min= 0, average= 0.42, max= 24, maxTarget=JsonParser>>readValue
    Infopoints : count= 90, sum= 3490, min= 4, average= 38.78, max= 303, maxTarget=JsonParser>>readValue
    CALL : count= 90, sum= 2653, min= 4, average= 29.48, max= 228, maxTarget=JsonParser>>readValue
    IMPLICIT_EXCEPTION : count= 90, sum= 795, min= 0, average= 8.83, max= 74, maxTarget=JsonParser>>readValue
    SAFEPOINT : count= 90, sum= 42, min= 0, average= 0.47, max= 8, maxTarget=JsonParser>>readObjectKeyValuePair:
    Marks : count= 90, sum= 738, min= 7, average= 8.20, max= 32, maxTarget=JsonParser>>readValue
    Data references : count= 90, sum= 3889, min= 2, average= 43.21, max= 303, maxTarget=JsonParser>>readValue
    203 changes: 203 additions & 0 deletions 5d99b29f-List.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,203 @@
    # List (iterations: 250, problem size: 1500) on Thu May 27 21:17:54 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/List.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'List' 250 1500)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done List>>isShorter:than: <split-577f9109> |AST 75|Tier 2|Time 160( 127+33 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f43578f1890|Src n/a
    [engine] opt done List>>isShorter:than: <split-779de014> |AST 75|Tier 2|Time 103( 68+35 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f43578f2410|Src n/a
    [engine] opt done List>>isShorter:than: <split-757529a4> |AST 75|Tier 2|Time 105( 70+35 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f43578f2f90|Src n/a
    [engine] opt done List>>isShorter:than: <split-1450078a> |AST 75|Tier 2|Time 76( 65+11 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357903910|Src n/a
    [engine] opt done List>>isShorter:than: <split-3aefae67> |AST 75|Tier 2|Time 78( 65+13 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357904490|Src n/a
    [engine] opt done List>>isShorter:than: <split-69c6161d> |AST 75|Tier 2|Time 85( 73+12 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357907410|Src n/a
    [engine] opt done List>>isShorter:than: <split-796d3c9f> |AST 72|Tier 2|Time 69( 61+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f435790f390|Src n/a
    [engine] opt done List>>isShorter:than: <split-2e1792e7> |AST 75|Tier 2|Time 72( 61+11 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435790ff90|Src n/a
    [engine] opt done List>>isShorter:than: <split-6bff19ff> |AST 75|Tier 2|Time 72( 59+12 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357910e10|Src n/a
    [engine] opt done List>>isShorter:than: <split-29a23c3d> |AST 75|Tier 2|Time 67( 57+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357912590|Src n/a
    [engine] opt done List>>isShorter:than: <split-41e1455d> |AST 72|Tier 2|Time 65( 55+9 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357913110|Src n/a
    [engine] opt done List>>isShorter:than: <split-4d6f197e> |AST 75|Tier 2|Time 69( 56+13 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357913a90|Src n/a
    [engine] opt done List>>isShorter:than: <split-41477a6d> |AST 75|Tier 2|Time 95( 85+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357919b10|Src n/a
    [engine] opt done List>>isShorter:than: <split-534ca02b> |AST 75|Tier 2|Time 93( 82+11 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435791b010|Src n/a
    [engine] opt done List>>isShorter:than: <split-272a179c> |AST 72|Tier 2|Time 85( 77+9 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f435791a690|Src n/a
    [engine] opt done List>>isShorter:than: <split-6fe46b62> |AST 72|Tier 2|Time 69( 59+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f435791f090|Src n/a
    [engine] opt done List>>isShorter:than: <split-a619c2> |AST 72|Tier 2|Time 72( 63+9 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f435791e710|Src n/a
    [engine] opt done List>>isShorter:than: <split-61e45f87> |AST 72|Tier 2|Time 68( 59+10 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357923190|Src n/a
    [engine] opt done List>>isShorter:than: <split-54dcbb9f> |AST 72|Tier 2|Time 60( 53+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357929610|Src n/a
    [engine] opt done List>>isShorter:than: <split-5bb3131b> |AST 72|Tier 2|Time 63( 55+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357928c90|Src n/a
    [engine] opt done List>>isShorter:than: <split-3b0ca5e1> |AST 72|Tier 2|Time 65( 57+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357929f90|Src n/a
    [engine] opt done List>>isShorter:than: <split-69eb86b4> |AST 72|Tier 2|Time 68( 59+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f435792df90|Src n/a
    [engine] opt done List>>isShorter:than: <split-516ebdf8> |AST 75|Tier 2|Time 70( 60+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435792e910|Src n/a
    [engine] opt done List>>isShorter:than: <split-bcb09a6> |AST 75|Tier 2|Time 71( 61+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435792f490|Src n/a
    [engine] opt done List>>isShorter:than: <split-7c2a69b4> |AST 72|Tier 2|Time 63( 55+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357930010|Src n/a
    [engine] opt done List>>isShorter:than: <split-375b5b7f> |AST 72|Tier 2|Time 64( 55+10 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357931410|Src n/a
    [engine] opt done List>>isShorter:than: <split-1813f3e9> |AST 72|Tier 2|Time 65( 55+10 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357932090|Src n/a
    [engine] opt done List>>isShorter:than: <split-7c2327fa> |AST 72|Tier 2|Time 64( 55+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f4357934a10|Src n/a
    [engine] opt done List>>isShorter:than: <split-4e558728> |AST 72|Tier 2|Time 64( 56+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357935490|Src n/a
    [engine] opt done List>>isShorter:than: <split-c68a5f8> |AST 75|Tier 2|Time 67( 57+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357935e10|Src n/a
    [engine] opt done List>>isShorter:than: <split-6ef7623> |AST 75|Tier 2|Time 66( 56+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435793b110|Src n/a
    [engine] opt done List>>isShorter:than: <split-7ed9ae94> |AST 72|Tier 2|Time 66( 57+10 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f435793bc90|Src n/a
    [engine] opt done List>>isShorter:than: <split-66908383> |AST 75|Tier 2|Time 68( 56+12 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435793c710|Src n/a
    [engine] opt done List>>isShorter:than: <split-4463d9d3> |AST 72|Tier 2|Time 62( 54+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f435793f610|Src n/a
    [engine] opt done List>>isShorter:than: <split-3068b369> |AST 72|Tier 2|Time 65( 57+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357940410|Src n/a
    [engine] opt done List>>isShorter:than: <split-17ca8b92> |AST 75|Tier 2|Time 67( 57+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357940d90|Src n/a
    [engine] opt done List>>isShorter:than: <split-5491f68b> |AST 75|Tier 2|Time 65( 55+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357941c10|Src n/a
    [engine] opt done List>>isShorter:than: <split-1ec7d8b3> |AST 75|Tier 2|Time 114( 56+58 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357943310|Src n/a
    [engine] opt done List>>isShorter:than: <split-736ac09a> |AST 75|Tier 2|Time 115( 57+58 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357942790|Src n/a
    [engine] opt done List>>isShorter:than: <split-74fef3f7> |AST 72|Tier 2|Time 117( 109+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357944810|Src n/a
    [engine] opt done List>>isShorter:than: <split-2a037324> |AST 72|Tier 2|Time 82( 74+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357945a90|Src n/a
    [engine] opt done List>>isShorter:than: <split-648ee871> |AST 75|Tier 2|Time 83( 72+11 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357946410|Src n/a
    [engine] opt done List>>isShorter:than: <split-585c13de> |AST 75|Tier 2|Time 84( 73+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357949590|Src n/a
    [engine] opt done List>>isShorter:than: <split-5c41d037> |AST 75|Tier 2|Time 65( 55+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435794b310|Src n/a
    [engine] opt done List>>isShorter:than: <split-3eb631b8> |AST 75|Tier 2|Time 65( 55+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435794be90|Src n/a
    [engine] opt done List>>isShorter:than: <split-5eccd3b9> |AST 75|Tier 2|Time 65( 55+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435794ca10|Src n/a
    [engine] opt done List>>isShorter:than: <split-2bc12da> |AST 75|Tier 2|Time 66( 56+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435794d990|Src n/a
    [engine] opt done List>>isShorter:than: <split-3122b117> |AST 75|Tier 2|Time 67( 55+12 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435794e510|Src n/a
    [engine] opt done List>>isShorter:than: <split-591fd34d> |AST 72|Tier 2|Time 63( 55+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357951790|Src n/a
    [engine] opt done List>>isShorter:than: <split-13d186db> |AST 72|Tier 2|Time 70( 56+14 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f4357952110|Src n/a
    [engine] opt done List>>isShorter:than: <split-6f6962ba> |AST 72|Tier 2|Time 69( 60+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f4357952b90|Src n/a
    [engine] opt done List>>isShorter:than: <split-4565a70a> |AST 72|Tier 2|Time 67( 58+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f4357953610|Src n/a
    [engine] opt done List>>isShorter:than: <split-6ecd665> |AST 72|Tier 2|Time 63( 54+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f4357954490|Src n/a
    [engine] opt done List>>isShorter:than: <split-7c9b78e3> |AST 75|Tier 2|Time 66( 56+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357954f10|Src n/a
    [engine] opt done List>>isShorter:than: <split-45394b31> |AST 72|Tier 2|Time 61( 52+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f4357955a90|Src n/a
    [engine] opt done List>>isShorter:than: <split-4d8539de> |AST 75|Tier 2|Time 65( 55+11 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357956410|Src n/a
    [engine] opt done List>>isShorter:than: <split-3eba57a7> |AST 75|Tier 2|Time 66( 55+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357956f90|Src n/a
    [engine] opt done List>>isShorter:than: <split-67207d8a> |AST 75|Tier 2|Time 67( 56+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357958d10|Src n/a
    [engine] opt done List>>isShorter:than: <split-a0a9fa5> |AST 72|Tier 2|Time 62( 54+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f4357959b90|Src n/a
    [engine] opt done List>>isShorter:than: <split-4d847d32> |AST 75|Tier 2|Time 66( 56+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435795a610|Src n/a
    [engine] opt done List>>isShorter:than: <split-2234078> |AST 75|Tier 2|Time 65( 55+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f435795b410|Src n/a
    [engine] opt done List>>isShorter:than: <split-72458efc> |AST 72|Tier 2|Time 64( 56+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f435795c290|Src n/a
    [engine] opt done List>>isShorter:than: <split-6d367020> |AST 72|Tier 2|Time 65( 56+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f435795cc10|Src n/a
    [engine] opt done List>>isShorter:than: <split-36bc415e> |AST 72|Tier 2|Time 63( 55+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f435795df10|Src n/a
    [engine] opt done List>>isShorter:than: <split-5ec77191> |AST 75|Tier 2|Time 67( 57+11 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357962a10|Src n/a
    [engine] opt done List>>isShorter:than: <split-6719a5b8> |AST 75|Tier 2|Time 65( 55+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f4357963b90|Src n/a
    [engine] opt done List>>isShorter:than: <split-6a74d228> |AST 72|Tier 2|Time 61( 52+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f4357965f90|Src n/a
    [engine] opt done List>>isShorter:than: <split-349d0836> |AST 72|Tier 2|Time 62( 53+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f4357967010|Src n/a
    [engine] opt done List>>isShorter:than: <split-6a714237> |AST 72|Tier 2|Time 72( 53+19 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f4357968d90|Src n/a
    [engine] opt done List>>isShorter:than: <split-3e134896> |AST 72|Tier 2|Time 71( 63+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f435796b310|Src n/a
    [engine] opt done List>>isShorter:than: <split-72ba28ee> |AST 72|Tier 2|Time 59( 51+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f435796bc90|Src n/a
    [engine] opt done List>>isShorter:than: <split-2e3a5237> |AST 72|Tier 2|Time 60( 52+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7f435796c610|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-64e1dd11> |AST 135|Tier 2|Time 1199( 782+417 )ms|Inlined 17Y 8N|IR 1996/ 3085|CodeSize 11087|Addr 0x7f4357978090|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-5c089b2f> |AST 135|Tier 2|Time 1363( 779+584 )ms|Inlined 27Y 15N|IR 3254/ 4815|CodeSize 18120|Addr 0x7f4357984310|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: |AST 135|Tier 2|Time 1950(1072+877 )ms|Inlined 33Y 32N|IR 4815/ 7925|CodeSize 31950|Addr 0x7f435799a090|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-6999cd39> |AST 135|Tier 2|Time 531( 365+166 )ms|Inlined 15Y 5N|IR 1640/ 2267|CodeSize 7699|Addr 0x7f43579bd590|Src n/a
    [engine] opt done List>>isShorter:than: <split-4b6ac111> |AST 75|Tier 2|Time 60( 50+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7f43579c5e90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-69ce2f62> |AST 28|Tier 2|Time 73( 62+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f43579c6a10|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-c9d82f9> |AST 28|Tier 2|Time 72( 61+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f43579c7710|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-5f462e3b> |AST 135|Tier 2|Time 1895(1048+847 )ms|Inlined 23Y 33N|IR 3808/ 6974|CodeSize 29527|Addr 0x7f43579c9d90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-6f012914> |AST 135|Tier 2|Time 2942(1523+1419)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54155|Addr 0x7f43579ef690|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-585ac855> |AST 135|Tier 2|Time 2460(1354+1106)ms|Inlined 31Y 49N|IR 5353/ 9864|CodeSize 42409|Addr 0x7f4357a28e90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-14bae047> |AST 135|Tier 2|Time 1768(1148+620 )ms|Inlined 31Y 29N|IR 4442/ 7378|CodeSize 29415|Addr 0x7f4357a53b10|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-3b152928> |AST 135|Tier 2|Time 2740(1355+1384)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54155|Addr 0x7f4357a87010|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-56781d96> |AST 135|Tier 2|Time 2750(1365+1384)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54155|Addr 0x7f4357ac0310|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-5173200b> |AST 135|Tier 2|Time 2902(1508+1394)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54155|Addr 0x7f4357af9090|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-5f78de22> |AST 135|Tier 2|Time 464( 411+53 )ms|Inlined 7Y 1N|IR 738/ 1037|CodeSize 2843|Addr 0x7f4357b31f10|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-5bb8f9e2> |AST 135|Tier 2|Time 1359(1033+325 )ms|Inlined 13Y 18N|IR 2196/ 3868|CodeSize 16385|Addr 0x7f4357b35110|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-720653c2> |AST 28|Tier 2|Time 72( 61+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357b45b10|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-6a933be2> |AST 135|Tier 2|Time 1770(1062+707 )ms|Inlined 23Y 33N|IR 3808/ 6868|CodeSize 29042|Addr 0x7f4357b46810|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-60baef24> |AST 28|Tier 2|Time 76( 65+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357b64c90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-732bb66d> |AST 135|Tier 2|Time 2673(1251+1422)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54155|Addr 0x7f4357b67c10|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-d02f8d> |AST 135|Tier 2|Time 2825(1452+1373)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54155|Addr 0x7f4357ba0a10|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-378bd86d> |AST 28|Tier 2|Time 72( 61+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357bda090|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-2189e7a7> |AST 28|Tier 2|Time 71( 60+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357bdad90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-69b2f8e5> |AST 28|Tier 2|Time 71( 60+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357bdba90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-61533ae> |AST 135|Tier 2|Time 2722(1347+1375)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54155|Addr 0x7f4357bdc790|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-58065f0c> |AST 28|Tier 2|Time 72( 61+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357c15290|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-25c5e994> |AST 135|Tier 2|Time 1132( 802+330 )ms|Inlined 15Y 17N|IR 2263/ 3971|CodeSize 16061|Addr 0x7f4357c15f90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-3605c4d3> |AST 135|Tier 2|Time 236( 185+52 )ms|Inlined 9Y 0N|IR 841/ 897|CodeSize 2221|Addr 0x7f4357c26490|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-599f571f> |AST 28|Tier 2|Time 72( 62+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357c29410|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-3d7fa3ae> |AST 135|Tier 2|Time 1333(1008+325 )ms|Inlined 13Y 18N|IR 2196/ 3868|CodeSize 16385|Addr 0x7f4357c2b010|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-77128dab> |AST 135|Tier 2|Time 468( 409+59 )ms|Inlined 7Y 1N|IR 738/ 1213|CodeSize 3540|Addr 0x7f4357c3ba10|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-187eb9a8> |AST 135|Tier 2|Time 1493(1026+467 )ms|Inlined 13Y 18N|IR 2196/ 3868|CodeSize 16385|Addr 0x7f4357c40b90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-312afbc7> |AST 135|Tier 2|Time 2830(1466+1364)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54155|Addr 0x7f4357c51b90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-726a6b94> |AST 28|Tier 2|Time 70( 60+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357c8a690|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-6569dded> |AST 28|Tier 2|Time 74( 63+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357c8b390|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-466d49f0> |AST 28|Tier 2|Time 73( 62+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357c8c390|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-7b60c3e> |AST 135|Tier 2|Time 2827(1463+1364)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54155|Addr 0x7f4357c8d090|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-710d7aff> |AST 28|Tier 2|Time 76( 65+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357cc5b90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-5395ea39> |AST 28|Tier 2|Time 77( 66+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357cc6890|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-1517f633> |AST 28|Tier 2|Time 76( 65+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357cc7590|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-4fe01803> |AST 28|Tier 2|Time 77( 66+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357cc8290|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-65327f5> |AST 28|Tier 2|Time 76( 65+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357cc9a90|Src n/a
    [engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 580( 567+13 )ms|Inlined 1Y 1N|IR 136/ 441|CodeSize 1755|Addr 0x7f4357ccdd90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-503c29ff> |AST 28|Tier 2|Time 73( 62+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7f4357ccef90|Src n/a
    [engine] opt done List>>verifyResult: |AST 15|Tier 2|Time 153( 151+2 )ms|Inlined 0Y 0N|IR 25/ 26|CodeSize 213|Addr 0x7f4357ccfc90|Src n/a
    [engine] opt done List>>isShorter:than: <split-30feffc> |AST 72|Tier 2|Time 57( 49+8 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7f4357cd0090|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-2d7e1102> |AST 135|Tier 2|Time 2696(1292+1404)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54155|Addr 0x7f4357cd1790|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-5449095d> |AST 135|Tier 2|Time 2697(1288+1409)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54155|Addr 0x7f4357d0a290|Src n/a
    [engine] opt done ListElement class>>new: |AST 31|Tier 2|Time 80( 77+4 )ms|Inlined 2Y 0N|IR 40/ 102|CodeSize 441|Addr 0x7f4357d43110|Src n/a
    [engine] opt done ListElement>>next: |AST 11|Tier 2|Time 26( 23+3 )ms|Inlined 0Y 0N|IR 57/ 89|CodeSize 381|Addr 0x7f4357d43790|Src n/a
    [engine] opt done List>>makeList: |AST 76|Tier 2|Time 246( 196+51 )ms|Inlined 14Y 1N|IR 378/ 1090|CodeSize 4131|Addr 0x7f4357d43f10|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-28cb9120> |AST 135|Tier 2|Time 2727(1324+1403)ms|Inlined 41Y 64N|IR 7013/12657|CodeSize 54688|Addr 0x7f4357d47e10|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-6ad11a56> |AST 130|Tier 2|Time 1799(1056+743 )ms|Inlined 23Y 33N|IR 3739/ 6930|CodeSize 29637|Addr 0x7f4357d82890|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-522b2631> |AST 135|Tier 2|Time 2857(1323+1534)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54682|Addr 0x7f4357da1e90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-63429932> |AST 135|Tier 2|Time 2739(1339+1400)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54634|Addr 0x7f4357ddc990|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-18fdb6cf> |AST 135|Tier 2|Time 2746(1345+1401)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54682|Addr 0x7f4357e15a10|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-45f24169> |AST 130|Tier 2|Time 2714(1316+1398)ms|Inlined 41Y 64N|IR 6948/12652|CodeSize 54600|Addr 0x7f4357e51a10|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-6ad5923a> |AST 135|Tier 2|Time 2727(1324+1402)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54682|Addr 0x7f4357e94910|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-43b0ade> |AST 130|Tier 2|Time 2723(1333+1391)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7f4357eccf90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-15723761> |AST 135|Tier 2|Time 2678(1317+1361)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54682|Addr 0x7f4357f06690|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-3fbfa96> |AST 135|Tier 2|Time 2691(1288+1403)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54682|Addr 0x7f4357f3fe90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-2adddc06> |AST 130|Tier 2|Time 2871(1470+1402)ms|Inlined 41Y 64N|IR 6948/12652|CodeSize 54600|Addr 0x7f4357f78510|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-301d8120> |AST 135|Tier 2|Time 2715(1341+1374)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54682|Addr 0x7f4357fb0a10|Src n/a
    [engine] opt done ListElement>>length |AST 43|Tier 2|Time 90( 72+18 )ms|Inlined 2Y 1N|IR 321/ 517|CodeSize 1799|Addr 0x7f4357fe9590|Src n/a
    [engine] opt done List>>benchmark |AST 76|Tier 2|Time 1343(1112+231 )ms|Inlined 54Y 6N|IR 1619/ 3515|CodeSize 11116|Addr 0x7f4357fec110|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-5a0d3466> |AST 130|Tier 2|Time 2810(1299+1511)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7f4357ff9810|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-5cc7be79> |AST 135|Tier 2|Time 2681(1289+1392)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54682|Addr 0x7f4358031f10|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-7b44b63d> |AST 130|Tier 2|Time 1057(1013+44 )ms|Inlined 3Y 3N|IR 440/ 1012|CodeSize 3262|Addr 0x7f435806b410|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-4a699efa> |AST 130|Tier 2|Time 2745(1356+1389)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7f4358070890|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-38499e48> |AST 130|Tier 2|Time 2735(1340+1394)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7f43580a8f90|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-1136b469> |AST 130|Tier 2|Time 668( 616+52 )ms|Inlined 5Y 2N|IR 554/ 1075|CodeSize 3202|Addr 0x7f43580e1690|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-17ae7628> |AST 130|Tier 2|Time 2721(1499+1221)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7f43580e4a90|Src n/a
    [engine] opt done ListElement>>length <split-6d467c87> |AST 38|Tier 2|Time 88( 71+17 )ms|Inlined 2Y 1N|IR 267/ 500|CodeSize 1653|Addr 0x7f435811d190|Src n/a
    [engine] opt done ListElement>>length <split-4917d36b> |AST 43|Tier 2|Time 204( 184+20 )ms|Inlined 2Y 1N|IR 321/ 593|CodeSize 2132|Addr 0x7f435811e590|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-6579c3d9> |AST 130|Tier 2|Time 2647(1256+1390)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7f4358120110|Src n/a
    [engine] opt done List>>talkWithX:withY:withZ: <split-66434cc8> |AST 130|Tier 2|Time 2653(1263+1390)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7f4358158810|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 166( 147+18 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f4358198410|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 243( 220+23 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7f435819b190|Src n/a
    [engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 270( 230+40 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f43581a1d90|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 154
    Success : 151
    Temporary Bailouts : 0
    Permanent Bailouts : 0
    Failed : 0
    Interrupted : 3
    Invalidated : 0
    Queues : 210
    Dequeues : 59
    Target inlined into only caller : 59
    Splits : 353
    Compilation Accuracy : 1.000000
    Queue Accuracy : 0.719048
    Compilation Utilization : 0.826126
    Remaining Compilation Queue : 0
    Time to queue : count= 210, sum= 954598, min= 48, average= 4545.71, max= 136537 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 154, sum= 1024944, min= 0, average= 6655.48, max= 32069 (milliseconds), maxTarget=ListElement>>length
    Time for compilation : count= 151, sum= 113135, min= 27, average= 749.24, max= 2943 (milliseconds), maxTarget=List>>talkWithX:withY:withZ:
    Truffle Tier : count= 151, sum= 63142, min= 23, average= 418.16, max= 1523 (milliseconds), maxTarget=List>>talkWithX:withY:withZ:
    Graal Tier : count= 151, sum= 26374, min= 1, average= 174.67, max= 816 (milliseconds), maxTarget=List>>talkWithX:withY:withZ:
    Code Installation : count= 151, sum= 23618, min= 1, average= 156.42, max= 793 (milliseconds), maxTarget=List>>talkWithX:withY:withZ:
    Truffle node count : count= 151, sum= 257224, min= 17, average= 1703.47, max= 6741, maxTarget=List>>talkWithX:withY:withZ:
    Trivial : count= 151, sum= 89357, min= 6, average= 591.77, max= 2331, maxTarget=List>>talkWithX:withY:withZ:
    Non Trivial : count= 151, sum= 167867, min= 11, average= 1111.70, max= 4410, maxTarget=List>>talkWithX:withY:withZ:
    Monomorphic : count= 151, sum= 162975, min= 11, average= 1079.30, max= 4284, maxTarget=List>>talkWithX:withY:withZ:
    Polymorphic : count= 151, sum= 4892, min= 0, average= 32.40, max= 126, maxTarget=List>>talkWithX:withY:withZ:
    Megamorphic : count= 151, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=List>>isShorter:than:
    Truffle call count : count= 151, sum= 3786, min= 0, average= 25.07, max= 105, maxTarget=List>>talkWithX:withY:withZ:
    Indirect : count= 151, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=List>>isShorter:than:
    Direct : count= 151, sum= 3786, min= 0, average= 25.07, max= 105, maxTarget=List>>talkWithX:withY:withZ:
    Dispatched : count= 151, sum= 2185, min= 0, average= 14.47, max= 64, maxTarget=List>>talkWithX:withY:withZ:
    Inlined : count= 151, sum= 1601, min= 0, average= 10.60, max= 54, maxTarget=List>>benchmark
    ---------- :
    Cloned : count= 151, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=List>>isShorter:than:
    Not Cloned : count= 151, sum= 3786, min= 0, average= 25.07, max= 105, maxTarget=List>>talkWithX:withY:withZ:
    Truffle loops : count= 151, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=List>>isShorter:than:
    Graal node count :
    After Truffle Tier : count= 151, sum= 267551, min= 25, average= 1771.86, max= 7013, maxTarget=List>>talkWithX:withY:withZ:
    After Graal Tier : count= 151, sum= 471764, min= 26, average= 3124.26, max= 12657, maxTarget=List>>talkWithX:withY:withZ:
    Graal compilation result :
    Code size : count= 151, sum= 1989692, min= 213, average= 13176.77, max= 54688, maxTarget=List>>talkWithX:withY:withZ:
    Total frame size : count= 151, sum= 70656, min= 32, average= 467.92, max= 1904, maxTarget=List>>talkWithX:withY:withZ:
    Exception handlers : count= 151, sum= 2199, min= 0, average= 14.56, max= 64, maxTarget=List>>talkWithX:withY:withZ:
    Infopoints : count= 151, sum= 29153, min= 4, average= 193.07, max= 793, maxTarget=List>>talkWithX:withY:withZ:
    CALL : count= 151, sum= 20918, min= 4, average= 138.53, max= 569, maxTarget=List>>talkWithX:withY:withZ:
    IMPLICIT_EXCEPTION : count= 151, sum= 7365, min= 0, average= 48.77, max= 203, maxTarget=List>>talkWithX:withY:withZ:
    SAFEPOINT : count= 151, sum= 870, min= 0, average= 5.76, max= 21, maxTarget=List>>talkWithX:withY:withZ:
    Marks : count= 151, sum= 4222, min= 7, average= 27.96, max= 92, maxTarget=List>>talkWithX:withY:withZ:
    Data references : count= 151, sum= 22523, min= 2, average= 149.16, max= 591, maxTarget=List>>talkWithX:withY:withZ:
    55 changes: 55 additions & 0 deletions 5d99b29f-Mandelbrot.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,55 @@
    # Mandelbrot (iterations: 250, problem size: 500) on Thu May 27 21:22:57 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Mandelbrot.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'Mandelbrot' 250 500)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done Integer>><< |AST 25|Tier 2|Time 94( 79+15 )ms|Inlined 0Y 0N|IR 76/ 112|CodeSize 461|Addr 0x7f9a6f90b290|Src n/a
    [engine] opt done Mandelbrot>>mandelbrot: |AST 500|Tier 2|Time 391( 270+121 )ms|Inlined 2Y 0N|IR 550/ 1809|CodeSize 13398|Addr 0x7f9a6f928990|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 181( 160+21 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f9a6f94d390|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 268( 245+22 )ms|Inlined 4Y 1N|IR 361/ 419|CodeSize 1240|Addr 0x7f9a6f954a90|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 6
    Success : 4
    Temporary Bailouts : 0
    Permanent Bailouts : 0
    Failed : 0
    Interrupted : 2
    Invalidated : 0
    Queues : 6
    Dequeues : 0
    Splits : 191
    Compilation Accuracy : 1.000000
    Queue Accuracy : 1.000000
    Compilation Utilization : 0.008507
    Remaining Compilation Queue : 0
    Time to queue : count= 6, sum= 413228, min= 142, average= 68871.42, max= 111866 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 6, sum= 49, min= 1, average= 8.23, max= 17 (milliseconds), maxTarget=String class>>new:
    Time for compilation : count= 4, sum= 952, min= 105, average= 238.07, max= 393 (milliseconds), maxTarget=Mandelbrot>>mandelbrot:
    Truffle Tier : count= 4, sum= 753, min= 78, average= 188.48, max= 269 (milliseconds), maxTarget=Mandelbrot>>mandelbrot:
    Graal Tier : count= 4, sum= 129, min= 11, average= 32.25, max= 84 (milliseconds), maxTarget=Mandelbrot>>mandelbrot:
    Code Installation : count= 4, sum= 69, min= 6, average= 17.33, max= 39 (milliseconds), maxTarget=Mandelbrot>>mandelbrot:
    Truffle node count : count= 4, sum= 1777, min= 40, average= 444.25, max= 892, maxTarget=Mandelbrot>>mandelbrot:
    Trivial : count= 4, sum= 687, min= 15, average= 171.75, max= 342, maxTarget=Mandelbrot>>mandelbrot:
    Non Trivial : count= 4, sum= 1090, min= 25, average= 272.50, max= 550, maxTarget=Mandelbrot>>mandelbrot:
    Monomorphic : count= 4, sum= 1072, min= 25, average= 268.00, max= 550, maxTarget=Mandelbrot>>mandelbrot:
    Polymorphic : count= 4, sum= 18, min= 0, average= 4.50, max= 9, maxTarget=String class>>new:
    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=String class>>new:
    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= 1200, min= 76, average= 300.00, max= 550, maxTarget=Mandelbrot>>mandelbrot:
    After Graal Tier : count= 4, sum= 2812, min= 112, average= 703.00, max= 1809, maxTarget=Mandelbrot>>mandelbrot:
    Graal compilation result :
    Code size : count= 4, sum= 16998, min= 461, average= 4249.50, max= 13398, maxTarget=Mandelbrot>>mandelbrot:
    Total frame size : count= 4, sum= 784, min= 32, average= 196.00, max= 640, maxTarget=Mandelbrot>>mandelbrot:
    Exception handlers : count= 4, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Integer>><<
    Infopoints : count= 4, sum= 147, min= 8, average= 36.75, max= 101, maxTarget=Mandelbrot>>mandelbrot:
    CALL : count= 4, sum= 110, min= 7, average= 27.50, max= 73, maxTarget=Mandelbrot>>mandelbrot:
    IMPLICIT_EXCEPTION : count= 4, sum= 30, min= 1, average= 7.50, max= 22, maxTarget=Mandelbrot>>mandelbrot:
    SAFEPOINT : count= 4, sum= 7, min= 0, average= 1.75, max= 6, maxTarget=Mandelbrot>>mandelbrot:
    Marks : count= 4, sum= 35, min= 7, average= 8.75, max= 13, maxTarget=Mandelbrot>>mandelbrot:
    Data references : count= 4, sum= 155, min= 4, average= 38.75, max= 108, maxTarget=Mandelbrot>>mandelbrot:
    62 changes: 62 additions & 0 deletions 5d99b29f-NBody.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,62 @@
    # NBody (iterations: 250, problem size: 250000) on Thu May 27 21:21:55 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/NBody.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'NBody' 250 250000)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done Body>>vz: |AST 11|Tier 2|Time 121( 100+21 )ms|Inlined 0Y 0N|IR 76/ 91|CodeSize 286|Addr 0x7f087b8f6510|Src n/a
    [engine] opt done Body>>vy: |AST 11|Tier 2|Time 121( 97+25 )ms|Inlined 0Y 0N|IR 76/ 91|CodeSize 286|Addr 0x7f087b8f5e90|Src n/a
    [engine] opt done Body>>vx: |AST 11|Tier 2|Time 122( 101+21 )ms|Inlined 0Y 0N|IR 76/ 91|CodeSize 286|Addr 0x7f087b8f5810|Src n/a
    [engine] opt done NBodySystem>>advance: |AST 187|Tier 2|Time 150( 140+11 )ms|Inlined 3Y 0N|IR 310/ 304|CodeSize 658|Addr 0x7f087b918690|Src n/a
    [engine] opt done SequenceableCollection>>do: <split-14bae047> |AST 73|Tier 2|Time 282( 231+52 )ms|Inlined 4Y 0N|IR 493/ 1700|CodeSize 5618|Addr 0x7f087b92c790|Src n/a
    [engine] opt done NBodySystem>>advance: |AST 816|Tier 2|Time 716( 579+137 )ms|Inlined 11Y 0N|IR 1341/ 2268|CodeSize 9276|Addr 0x7f087b940510|Src n/a
    [engine] opt done NBody>>innerBenchmarkLoop: |AST 95|Tier 2|Time 2780(1854+926 )ms|Inlined 98Y 1N|IR 6158/11947|CodeSize 55373|Addr 0x7f087b96d190|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 165( 146+19 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f087b99e790|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 246( 221+24 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7f087b9a9e90|Src n/a
    [engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 278( 239+39 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f087b9afc10|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 11
    Success : 10
    Temporary Bailouts : 0
    Permanent Bailouts : 0
    Failed : 0
    Interrupted : 1
    Invalidated : 0
    Queues : 14
    Dequeues : 3
    Target inlined into only caller : 3
    Splits : 199
    Compilation Accuracy : 1.000000
    Queue Accuracy : 0.785714
    Compilation Utilization : 0.090229
    Remaining Compilation Queue : 0
    Time to queue : count= 14, sum= 176536, min= 90, average= 12609.76, max= 55949 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 11, sum= 219, min= 1, average= 19.98, max= 128 (milliseconds), maxTarget=NBodySystem>>advance:
    Time for compilation : count= 10, sum= 5058, min= 140, average= 505.89, max= 2782 (milliseconds), maxTarget=NBody>>innerBenchmarkLoop:
    Truffle Tier : count= 10, sum= 3707, min= 96, average= 370.76, max= 1854 (milliseconds), maxTarget=NBody>>innerBenchmarkLoop:
    Graal Tier : count= 10, sum= 814, min= 6, average= 81.47, max= 601 (milliseconds), maxTarget=NBody>>innerBenchmarkLoop:
    Code Installation : count= 10, sum= 536, min= 4, average= 53.66, max= 326 (milliseconds), maxTarget=NBody>>innerBenchmarkLoop:
    Truffle node count : count= 10, sum= 12639, min= 19, average= 1263.90, max= 8572, maxTarget=NBody>>innerBenchmarkLoop:
    Trivial : count= 10, sum= 4673, min= 8, average= 467.30, max= 3172, maxTarget=NBody>>innerBenchmarkLoop:
    Non Trivial : count= 10, sum= 7966, min= 11, average= 796.60, max= 5400, maxTarget=NBody>>innerBenchmarkLoop:
    Monomorphic : count= 10, sum= 7937, min= 11, average= 793.70, max= 5400, maxTarget=NBody>>innerBenchmarkLoop:
    Polymorphic : count= 10, sum= 29, min= 0, average= 2.90, max= 11, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Megamorphic : count= 10, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Body>>vy:
    Truffle call count : count= 10, sum= 129, min= 0, average= 12.90, max= 99, maxTarget=NBody>>innerBenchmarkLoop:
    Indirect : count= 10, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Body>>vy:
    Direct : count= 10, sum= 129, min= 0, average= 12.90, max= 99, maxTarget=NBody>>innerBenchmarkLoop:
    Dispatched : count= 10, sum= 4, min= 0, average= 0.40, max= 1, maxTarget=NBody>>innerBenchmarkLoop:
    Inlined : count= 10, sum= 125, min= 0, average= 12.50, max= 98, maxTarget=NBody>>innerBenchmarkLoop:
    ---------- :
    Cloned : count= 10, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Body>>vy:
    Not Cloned : count= 10, sum= 129, min= 0, average= 12.90, max= 99, maxTarget=NBody>>innerBenchmarkLoop:
    Truffle loops : count= 10, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Body>>vy:
    Graal node count :
    After Truffle Tier : count= 10, sum= 9578, min= 76, average= 957.80, max= 6158, maxTarget=NBody>>innerBenchmarkLoop:
    After Graal Tier : count= 10, sum= 18442, min= 91, average= 1844.20, max= 11947, maxTarget=NBody>>innerBenchmarkLoop:
    Graal compilation result :
    Code size : count= 10, sum= 79895, min= 286, average= 7989.50, max= 55373, maxTarget=NBody>>innerBenchmarkLoop:
    Total frame size : count= 10, sum= 1696, min= 32, average= 169.60, max= 656, maxTarget=NBody>>innerBenchmarkLoop:
    Exception handlers : count= 10, sum= 1, min= 0, average= 0.10, max= 1, maxTarget=NBody>>innerBenchmarkLoop:
    Infopoints : count= 10, sum= 640, min= 5, average= 64.00, max= 385, maxTarget=NBody>>innerBenchmarkLoop:
    CALL : count= 10, sum= 482, min= 5, average= 48.20, max= 287, maxTarget=NBody>>innerBenchmarkLoop:
    IMPLICIT_EXCEPTION : count= 10, sum= 140, min= 0, average= 14.00, max= 88, maxTarget=NBody>>innerBenchmarkLoop:
    SAFEPOINT : count= 10, sum= 18, min= 0, average= 1.80, max= 10, maxTarget=NBody>>innerBenchmarkLoop:
    Marks : count= 10, sum= 93, min= 7, average= 9.30, max= 18, maxTarget=NBody>>innerBenchmarkLoop:
    Data references : count= 10, sum= 1618, min= 2, average= 161.80, max= 1384, maxTarget=NBody>>innerBenchmarkLoop:
    61 changes: 61 additions & 0 deletions 5d99b29f-Permute.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,61 @@
    # Permute (iterations: 250, problem size: 1000) on Thu May 27 21:33:14 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Permute.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'Permute' 250 1000)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done Permute>>swap:with: |AST 74|Tier 2|Time 171( 152+19 )ms|Inlined 0Y 0N|IR 173/ 156|CodeSize 488|Addr 0x7ff123915a10|Src n/a
    [engine] opt done Permute>>permute: |AST 138|Tier 2|Time 1028( 710+318 )ms|Inlined 20Y 8N|IR 2982/ 4177|CodeSize 20610|Addr 0x7ff123941910|Src n/a
    [engine] opt done SequenceableCollection>>atAllPut: |AST 72|Tier 2|Time 115( 97+17 )ms|Inlined 0Y 0N|IR 184/ 407|CodeSize 1641|Addr 0x7ff123957410|Src n/a
    [engine] opt done Permute>>verifyResult: |AST 15|Tier 2|Time 36( 33+2 )ms|Inlined 0Y 0N|IR 25/ 26|CodeSize 216|Addr 0x7ff12395b290|Src n/a
    [engine] opt done ArrayedCollection class>>new:withAll: |AST 31|Tier 2|Time 131( 119+12 )ms|Inlined 1Y 0N|IR 237/ 289|CodeSize 977|Addr 0x7ff12395e390|Src n/a
    [engine] opt done Permute>>benchmark |AST 49|Tier 2|Time 1020( 754+266 )ms|Inlined 23Y 8N|IR 3024/ 2967|CodeSize 11974|Addr 0x7ff123965010|Src n/a
    [engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 1085( 688+397 )ms|Inlined 25Y 8N|IR 3120/ 3754|CodeSize 15175|Addr 0x7ff123973910|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 169( 151+18 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7ff123993a10|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 245( 221+23 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7ff123997790|Src n/a
    [engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 278( 238+40 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7ff1239a7890|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 11
    Success : 10
    Temporary Bailouts : 0
    Permanent Bailouts : 0
    Failed : 0
    Interrupted : 1
    Invalidated : 0
    Queues : 11
    Dequeues : 0
    Splits : 191
    Compilation Accuracy : 1.000000
    Queue Accuracy : 1.000000
    Compilation Utilization : 0.077869
    Remaining Compilation Queue : 0
    Time to queue : count= 11, sum= 175366, min= 36, average= 15942.40, max= 55079 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 11, sum= 45, min= 1, average= 4.14, max= 16 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time for compilation : count= 10, sum= 4303, min= 37, average= 430.35, max= 1086 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle Tier : count= 10, sum= 3162, min= 33, average= 316.28, max= 754 (milliseconds), maxTarget=Permute>>benchmark
    Graal Tier : count= 10, sum= 724, min= 1, average= 72.47, max= 262 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Code Installation : count= 10, sum= 415, min= 1, average= 41.60, max= 135 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle node count : count= 10, sum= 12334, min= 23, average= 1233.40, max= 3662, maxTarget=Benchmark>>innerBenchmarkLoop:
    Trivial : count= 10, sum= 4841, min= 8, average= 484.10, max= 1434, maxTarget=Benchmark>>innerBenchmarkLoop:
    Non Trivial : count= 10, sum= 7493, min= 15, average= 749.30, max= 2228, maxTarget=Benchmark>>innerBenchmarkLoop:
    Monomorphic : count= 10, sum= 7456, min= 15, average= 745.60, max= 2226, maxTarget=Benchmark>>innerBenchmarkLoop:
    Polymorphic : count= 10, sum= 37, min= 0, average= 3.70, max= 11, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Megamorphic : count= 10, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Permute>>swap:with:
    Truffle call count : count= 10, sum= 105, min= 0, average= 10.50, max= 33, maxTarget=Benchmark>>innerBenchmarkLoop:
    Indirect : count= 10, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Permute>>swap:with:
    Direct : count= 10, sum= 105, min= 0, average= 10.50, max= 33, maxTarget=Benchmark>>innerBenchmarkLoop:
    Dispatched : count= 10, sum= 27, min= 0, average= 2.70, max= 8, maxTarget=Permute>>permute:
    Inlined : count= 10, sum= 78, min= 0, average= 7.80, max= 25, maxTarget=Benchmark>>innerBenchmarkLoop:
    ---------- :
    Cloned : count= 10, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Permute>>swap:with:
    Not Cloned : count= 10, sum= 105, min= 0, average= 10.50, max= 33, maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle loops : count= 10, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Permute>>swap:with:
    Graal node count :
    After Truffle Tier : count= 10, sum= 10793, min= 25, average= 1079.30, max= 3120, maxTarget=Benchmark>>innerBenchmarkLoop:
    After Graal Tier : count= 10, sum= 13726, min= 26, average= 1372.60, max= 4177, maxTarget=Permute>>permute:
    Graal compilation result :
    Code size : count= 10, sum= 59193, min= 216, average= 5919.30, max= 20610, maxTarget=Permute>>permute:
    Total frame size : count= 10, sum= 1616, min= 32, average= 161.60, max= 544, maxTarget=Permute>>permute:
    Exception handlers : count= 10, sum= 25, min= 0, average= 2.50, max= 9, maxTarget=Benchmark>>innerBenchmarkLoop:
    Infopoints : count= 10, sum= 630, min= 4, average= 63.00, max= 215, maxTarget=Permute>>permute:
    CALL : count= 10, sum= 455, min= 4, average= 45.50, max= 151, maxTarget=Permute>>permute:
    IMPLICIT_EXCEPTION : count= 10, sum= 162, min= 0, average= 16.20, max= 57, maxTarget=Permute>>permute:
    SAFEPOINT : count= 10, sum= 13, min= 0, average= 1.30, max= 7, maxTarget=Permute>>permute:
    Marks : count= 10, sum= 110, min= 7, average= 11.00, max= 22, maxTarget=Permute>>permute:
    Data references : count= 10, sum= 526, min= 3, average= 52.60, max= 148, maxTarget=Permute>>permute:
    63 changes: 63 additions & 0 deletions 5d99b29f-Queens.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,63 @@
    # Queens (iterations: 250, problem size: 1000) on Thu May 27 21:40:24 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Queens.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'Queens' 250 1000)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done Queens>>row:column:put: |AST 83|Tier 2|Time 134( 108+27 )ms|Inlined 0Y 0N|IR 188/ 289|CodeSize 1130|Addr 0x7f097f8e8b10|Src n/a
    [engine] opt done Queens>>row:column: |AST 77|Tier 2|Time 193( 167+26 )ms|Inlined 0Y 0N|IR 216/ 257|CodeSize 1117|Addr 0x7f097f8e8090|Src n/a
    [engine] opt done SequenceableCollection>>atAllPut: |AST 72|Tier 2|Time 111( 79+33 )ms|Inlined 0Y 0N|IR 252/ 717|CodeSize 2826|Addr 0x7f097f900d10|Src n/a
    [engine] opt done ArrayedCollection class>>new:withAll: |AST 31|Tier 2|Time 149( 110+39 )ms|Inlined 1Y 0N|IR 302/ 682|CodeSize 2303|Addr 0x7f097f91e090|Src n/a
    [engine] opt done Queens>>placeQueen: |AST 149|Tier 2|Time 793( 536+256 )ms|Inlined 11Y 1N|IR 2084/ 2683|CodeSize 14517|Addr 0x7f097f920890|Src n/a
    [engine] opt done True>>and: |AST 17|Tier 2|Time 40( 38+2 )ms|Inlined 0Y 0N|IR 23/ 28|CodeSize 213|Addr 0x7f097f92c610|Src n/a
    [engine] opt done Queens>>verifyResult: |AST 9|Tier 2|Time 31( 29+2 )ms|Inlined 0Y 0N|IR 19/ 20|CodeSize 181|Addr 0x7f097f931f90|Src n/a
    [engine] opt done Queens>>queens |AST 100|Tier 2|Time 1010( 574+436 )ms|Inlined 20Y 1N|IR 2848/ 3478|CodeSize 16209|Addr 0x7f097f93eb10|Src n/a
    [engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 622( 609+13 )ms|Inlined 1Y 1N|IR 138/ 441|CodeSize 1738|Addr 0x7f097f94a710|Src n/a
    [engine] opt done Queens>>benchmark |AST 68|Tier 2|Time 1251( 675+576 )ms|Inlined 22Y 1N|IR 2949/ 4831|CodeSize 23569|Addr 0x7f097f94bc10|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 178( 160+18 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f097f96af10|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 246( 223+23 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7f097f973390|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 14
    Success : 12
    Temporary Bailouts : 0
    Permanent Bailouts : 0
    Failed : 0
    Interrupted : 2
    Invalidated : 0
    Queues : 14
    Dequeues : 0
    Splits : 191
    Compilation Accuracy : 1.000000
    Queue Accuracy : 1.000000
    Compilation Utilization : 0.102359
    Remaining Compilation Queue : 0
    Time to queue : count= 14, sum= 149351, min= 44, average= 10667.93, max= 46768 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 14, sum= 70, min= 1, average= 5.00, max= 17 (milliseconds), maxTarget=String class>>new:
    Time for compilation : count= 12, sum= 4802, min= 32, average= 400.23, max= 1252 (milliseconds), maxTarget=Queens>>benchmark
    Truffle Tier : count= 12, sum= 3308, min= 29, average= 275.67, max= 675 (milliseconds), maxTarget=Queens>>benchmark
    Graal Tier : count= 12, sum= 1007, min= 1, average= 83.97, max= 396 (milliseconds), maxTarget=Queens>>benchmark
    Code Installation : count= 12, sum= 487, min= 1, average= 40.59, max= 180 (milliseconds), maxTarget=Queens>>benchmark
    Truffle node count : count= 13, sum= 9652, min= 13, average= 742.46, max= 2885, maxTarget=Queens>>benchmark
    Trivial : count= 13, sum= 3741, min= 4, average= 287.77, max= 1112, maxTarget=Queens>>benchmark
    Non Trivial : count= 13, sum= 5911, min= 9, average= 454.69, max= 1773, maxTarget=Queens>>benchmark
    Monomorphic : count= 13, sum= 5862, min= 9, average= 450.92, max= 1765, maxTarget=Queens>>benchmark
    Polymorphic : count= 13, sum= 49, min= 0, average= 3.77, max= 11, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Megamorphic : count= 13, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Queens>>row:column:
    Truffle call count : count= 13, sum= 71, min= 0, average= 5.46, max= 23, maxTarget=Queens>>benchmark
    Indirect : count= 13, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Queens>>row:column:
    Direct : count= 13, sum= 71, min= 0, average= 5.46, max= 23, maxTarget=Queens>>benchmark
    Dispatched : count= 13, sum= 7, min= 0, average= 0.54, max= 1, maxTarget=Queens>>placeQueen:
    Inlined : count= 13, sum= 64, min= 0, average= 4.92, max= 22, maxTarget=Queens>>benchmark
    ---------- :
    Cloned : count= 13, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Queens>>row:column:
    Not Cloned : count= 13, sum= 71, min= 0, average= 5.46, max= 23, maxTarget=Queens>>benchmark
    Truffle loops : count= 13, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Queens>>row:column:
    Graal node count :
    After Truffle Tier : count= 13, sum= 10067, min= 19, average= 774.38, max= 2949, maxTarget=Queens>>benchmark
    After Graal Tier : count= 13, sum= 15376, min= 20, average= 1182.77, max= 4831, maxTarget=Queens>>benchmark
    Graal compilation result :
    Code size : count= 12, sum= 67070, min= 181, average= 5589.17, max= 23569, maxTarget=Queens>>benchmark
    Total frame size : count= 12, sum= 1920, min= 32, average= 160.00, max= 480, maxTarget=Queens>>placeQueen:
    Exception handlers : count= 12, sum= 5, min= 0, average= 0.42, max= 2, maxTarget=Benchmark>>innerBenchmarkLoop:
    Infopoints : count= 12, sum= 844, min= 4, average= 70.33, max= 264, maxTarget=Queens>>benchmark
    CALL : count= 12, sum= 557, min= 4, average= 46.42, max= 173, maxTarget=Queens>>benchmark
    IMPLICIT_EXCEPTION : count= 12, sum= 222, min= 0, average= 18.50, max= 73, maxTarget=Queens>>benchmark
    SAFEPOINT : count= 12, sum= 65, min= 0, average= 5.42, max= 18, maxTarget=Queens>>placeQueen:
    Marks : count= 12, sum= 158, min= 7, average= 13.17, max= 28, maxTarget=Queens>>queens
    Data references : count= 12, sum= 766, min= 1, average= 63.83, max= 281, maxTarget=Queens>>benchmark
    122 changes: 122 additions & 0 deletions 5d99b29f-Richards.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,122 @@
    # Richards (iterations: 250, problem size: 100) on Thu May 27 21:29:28 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Richards.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'Richards' 250 100)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done TaskState>>isTaskHoldingOrWaiting |AST 32|Tier 2|Time 136( 122+14 )ms|Inlined 0Y 0N|IR 125/ 98|CodeSize 353|Addr 0x7f0197900d10|Src n/a
    [engine] opt done TaskState>>isWaitingWithPacket |AST 31|Tier 2|Time 99( 77+21 )ms|Inlined 0Y 0N|IR 84/ 101|CodeSize 362|Addr 0x7f0197900710|Src n/a
    [engine] opt done Packet>>link: |AST 11|Tier 2|Time 43( 39+4 )ms|Inlined 0Y 0N|IR 61/ 181|CodeSize 476|Addr 0x7f0197909810|Src n/a
    [engine] opt done Scheduler>>findTask: |AST 45|Tier 2|Time 113( 104+9 )ms|Inlined 0Y 0N|IR 70/ 131|CodeSize 564|Addr 0x7f019791ba10|Src n/a
    [engine] opt done TaskControlBlock>>runTask |AST 121|Tier 2|Time 289( 233+56 )ms|Inlined 3Y 0N|IR 537/ 1469|CodeSize 4589|Addr 0x7f019791c910|Src n/a
    [engine] opt done Packet>>identity: |AST 11|Tier 2|Time 37( 34+3 )ms|Inlined 0Y 0N|IR 74/ 88|CodeSize 273|Addr 0x7f0197928c90|Src n/a
    [engine] opt done TaskState>>taskWaiting: |AST 11|Tier 2|Time 33( 31+3 )ms|Inlined 0Y 0N|IR 76/ 87|CodeSize 277|Addr 0x7f019792f290|Src n/a
    [engine] opt done Scheduler>>createDevice:priority:work:state: |AST 157|Tier 2|Time 362( 318+44 )ms|Inlined 15Y 0N|IR 1140/ 1276|CodeSize 3687|Addr 0x7f0197951a10|Src n/a
    [engine] opt done Scheduler>>wait |AST 27|Tier 2|Time 57( 53+4 )ms|Inlined 1Y 0N|IR 126/ 137|CodeSize 338|Addr 0x7f019795aa10|Src n/a
    [engine] opt done Scheduler>>createWorker:priority:work:state: |AST 319|Tier 2|Time 511( 381+130 )ms|Inlined 19Y 0N|IR 1338/ 1564|CodeSize 4280|Addr 0x7f019795fb10|Src n/a
    [engine] opt done TaskControlBlock>>addInput:checkPriority: |AST 97|Tier 2|Time 207( 183+24 )ms|Inlined 4Y 0N|IR 399/ 792|CodeSize 2286|Addr 0x7f0197965810|Src n/a
    [engine] opt done Packet>>datum: |AST 11|Tier 2|Time 30( 27+3 )ms|Inlined 0Y 0N|IR 74/ 88|CodeSize 273|Addr 0x7f0197968510|Src n/a
    [engine] opt deopt TaskControlBlock>>runTask |AST 121|Src n/a
    [engine] opt inv. TaskControlBlock>>runTask |AST 121|Calls/Thres 7136/ 3|CallsAndLoop/Thres 7136/ 1000|Src n/a|Reason Profiled Return Type
    [engine] opt done RBObject>>append:head: |AST 118|Tier 2|Time 94( 83+11 )ms|Inlined 2Y 0N|IR 216/ 412|CodeSize 1267|Addr 0x7f019796a990|Src n/a
    [engine] opt done Scheduler>>queuePacket: |AST 127|Tier 2|Time 222( 185+37 )ms|Inlined 8Y 0N|IR 651/ 1020|CodeSize 2802|Addr 0x7f0197971e90|Src n/a
    [engine] opt done Scheduler>>holdSelf |AST 49|Tier 2|Time 88( 83+5 )ms|Inlined 1Y 0N|IR 170/ 163|CodeSize 452|Addr 0x7f0197979090|Src n/a
    [engine] opt done TaskState>>taskHolding: |AST 11|Tier 2|Time 29( 26+3 )ms|Inlined 0Y 0N|IR 76/ 87|CodeSize 277|Addr 0x7f0197979f90|Src n/a
    [engine] opt done TaskControlBlock>>runTask |AST 121|Tier 2|Time 169( 137+31 )ms|Inlined 3Y 0N|IR 625/ 1487|CodeSize 4644|Addr 0x7f019797a610|Src n/a
    [engine] opt done DeviceTaskDataRecord>>pending: |AST 11|Tier 2|Time 29( 26+3 )ms|Inlined 0Y 0N|IR 61/ 181|CodeSize 476|Addr 0x7f019797dc90|Src n/a
    [engine] opt done TaskState>>packetPending: |AST 11|Tier 2|Time 31( 29+3 )ms|Inlined 0Y 0N|IR 74/ 85|CodeSize 267|Addr 0x7f019797e990|Src n/a
    [engine] opt done Scheduler>>createHandler:priority:work:state: |AST 349|Tier 2|Time 780( 607+173 )ms|Inlined 34Y 0N|IR 2370/ 3825|CodeSize 12457|Addr 0x7f019797f710|Src n/a
    [engine] opt done TaskState>>running |AST 16|Tier 2|Time 40( 34+6 )ms|Inlined 0Y 0N|IR 212/ 204|CodeSize 755|Addr 0x7f019798a710|Src n/a
    [engine] opt done IdleTaskDataRecord>>count: |AST 11|Tier 2|Time 33( 30+3 )ms|Inlined 0Y 0N|IR 73/ 88|CodeSize 273|Addr 0x7f019798c110|Src n/a
    [engine] opt done IdleTaskDataRecord>>control: |AST 11|Tier 2|Time 32( 30+3 )ms|Inlined 0Y 0N|IR 73/ 88|CodeSize 273|Addr 0x7f019798c790|Src n/a
    [engine] opt done WorkerTaskDataRecord>>count: |AST 11|Tier 2|Time 31( 28+3 )ms|Inlined 0Y 0N|IR 73/ 88|CodeSize 273|Addr 0x7f019798ce10|Src n/a
    [engine] opt done RBObject class>>DeviceA |AST 8|Tier 2|Time 22( 20+2 )ms|Inlined 0Y 0N|IR 18/ 18|CodeSize 179|Addr 0x7f019798f010|Src n/a
    [engine] opt done RBObject class>>DeviceB |AST 8|Tier 2|Time 22( 20+2 )ms|Inlined 0Y 0N|IR 18/ 18|CodeSize 179|Addr 0x7f019798fa10|Src n/a
    [engine] opt done Scheduler>>release: |AST 93|Tier 2|Time 113( 106+7 )ms|Inlined 2Y 0N|IR 191/ 253|CodeSize 761|Addr 0x7f019798fe10|Src n/a
    [engine] opt done RBObject class>>HandlerA |AST 8|Tier 2|Time 23( 21+2 )ms|Inlined 0Y 0N|IR 18/ 18|CodeSize 179|Addr 0x7f0197990d90|Src n/a
    [engine] opt done TaskState>>packetPending |AST 18|Tier 2|Time 111( 108+3 )ms|Inlined 0Y 0N|IR 128/ 123|CodeSize 358|Addr 0x7f0197998790|Src n/a
    [engine] opt done Scheduler>>createIdler:priority:work:state: |AST 236|Tier 2|Time 358( 331+28 )ms|Inlined 13Y 0N|IR 818/ 782|CodeSize 1751|Addr 0x7f019799b310|Src n/a
    [engine] opt done Scheduler>>schedule |AST 108|Tier 2|Time 328( 226+102 )ms|Inlined 5Y 0N|IR 987/ 2675|CodeSize 9814|Addr 0x7f019799dc90|Src n/a
    [engine] opt done SequenceableCollection>>atAllPut: |AST 72|Tier 2|Time 88( 68+19 )ms|Inlined 0Y 0N|IR 206/ 479|CodeSize 2192|Addr 0x7f01979a4e90|Src n/a
    [engine] opt inv. SequenceableCollection>>atAllPut: |AST 72|Calls/Thres 379/ 3|CallsAndLoop/Thres 2051/ 1000|Src n/a
    [engine] opt done SequenceableCollection>>atAllPut: |AST 72|Tier 2|Time 88( 67+22 )ms|Inlined 0Y 0N|IR 206/ 510|CodeSize 2184|Addr 0x7f01979a6a90|Src n/a
    [engine] opt done ArrayedCollection class>>new:withAll: |AST 31|Tier 2|Time 145( 113+32 )ms|Inlined 1Y 0N|IR 258/ 672|CodeSize 2513|Addr 0x7f01979b0110|Src n/a
    [engine] opt done Behavior>>new <split-74fef3f7> |AST 26|Tier 2|Time 56( 53+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7f01979b3a10|Src n/a
    [engine] opt done Packet class>>create:identity:kind: |AST 35|Tier 2|Time 169( 156+13 )ms|Inlined 4Y 0N|IR 310/ 429|CodeSize 1449|Addr 0x7f01979b4810|Src n/a
    [engine] opt done Scheduler>>createPacket:identity:kind: |AST 29|Tier 2|Time 176( 162+13 )ms|Inlined 5Y 0N|IR 351/ 431|CodeSize 1462|Addr 0x7f01979b5690|Src n/a
    [engine] opt done Behavior>>new <split-5bb8f9e2> |AST 26|Tier 2|Time 55( 49+6 )ms|Inlined 0Y 0N|IR 94/ 374|CodeSize 1320|Addr 0x7f01979ba390|Src n/a
    [engine] opt done TaskControlBlock class>>link:create:priority:initialWorkQueue:initialState:function:privateData:|AST 47|Tier 2|Time 136( 122+14 )ms|Inlined 5Y 0N|IR 425/ 707|CodeSize 2202|Addr 0x7f01979bb090|Src n/a
    [engine] opt done Scheduler>>createTask:priority:work:state:function:data: |AST 69|Tier 2|Time 191( 158+33 )ms|Inlined 6Y 0N|IR 578/ 1393|CodeSize 4930|Addr 0x7f01979bcb10|Src n/a
    [engine] opt done RBObject class>>HandlerB |AST 8|Tier 2|Time 20( 18+2 )ms|Inlined 0Y 0N|IR 18/ 18|CodeSize 179|Addr 0x7f01979c0210|Src n/a
    [engine] opt done TaskState>>waitingWithPacket |AST 17|Tier 2|Time 42( 38+4 )ms|Inlined 0Y 0N|IR 133/ 152|CodeSize 421|Addr 0x7f01979c2910|Src n/a
    [engine] opt done Behavior>>new <split-516ebdf8> |AST 26|Tier 2|Time 53( 51+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7f01979c3210|Src n/a
    [engine] opt done TaskState class>>waitingWithPacket |AST 26|Tier 2|Time 81( 74+6 )ms|Inlined 2Y 0N|IR 166/ 248|CodeSize 579|Addr 0x7f01979c4710|Src n/a
    [engine] opt done HandlerTaskDataRecord class>>create |AST 26|Tier 2|Time 117( 114+3 )ms|Inlined 2Y 0N|IR 42/ 115|CodeSize 479|Addr 0x7f01979c5b90|Src n/a
    [engine] opt done Scheduler>>initialize |AST 77|Tier 2|Time 186( 177+10 )ms|Inlined 2Y 0N|IR 341/ 488|CodeSize 1298|Addr 0x7f01979c9190|Src n/a
    [engine] opt done TaskState class>>waiting |AST 26|Tier 2|Time 79( 73+6 )ms|Inlined 2Y 0N|IR 166/ 248|CodeSize 579|Addr 0x7f01979ca010|Src n/a
    [engine] opt done DeviceTaskDataRecord class>>create |AST 26|Tier 2|Time 81( 78+3 )ms|Inlined 2Y 0N|IR 42/ 115|CodeSize 479|Addr 0x7f01979cad10|Src n/a
    [engine] opt done Scheduler>>createHandler:priority:work:state: |AST 55|Tier 2|Time 342( 271+71 )ms|Inlined 10Y 0N|IR 816/ 2987|CodeSize 12110|Addr 0x7f01979cb390|Src n/a
    [engine] opt done Scheduler>>createDevice:priority:work:state: |AST 55|Tier 2|Time 278( 208+70 )ms|Inlined 10Y 0N|IR 816/ 2987|CodeSize 12110|Addr 0x7f01979d0d10|Src n/a
    [engine] opt done Behavior>>new <split-25c5e994> |AST 28|Tier 2|Time 161( 153+8 )ms|Inlined 3Y 0N|IR 226/ 412|CodeSize 1411|Addr 0x7f01979d7110|Src n/a
    [engine] opt done Scheduler class>>new |AST 26|Tier 2|Time 226( 215+10 )ms|Inlined 7Y 0N|IR 380/ 412|CodeSize 1411|Addr 0x7f01979d7f90|Src n/a
    [engine] opt done Richards>>benchmark |AST 30|Tier 2|Time 238( 223+15 )ms|Inlined 8Y 1N|IR 447/ 684|CodeSize 2295|Addr 0x7f01979d9810|Src n/a
    [engine] opt done TaskState class>>running |AST 26|Tier 2|Time 82( 73+10 )ms|Inlined 2Y 0N|IR 217/ 288|CodeSize 798|Addr 0x7f01979daa90|Src n/a
    [engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 266( 233+34 )ms|Inlined 10Y 1N|IR 547/ 1412|CodeSize 5041|Addr 0x7f01979dc390|Src n/a
    [engine] opt done IdleTaskDataRecord class>>create |AST 26|Tier 2|Time 70( 67+3 )ms|Inlined 2Y 0N|IR 35/ 99|CodeSize 445|Addr 0x7f01979dea10|Src n/a
    [engine] opt done Richards>>verifyResult: |AST 9|Tier 2|Time 21( 20+1 )ms|Inlined 0Y 0N|IR 19/ 20|CodeSize 181|Addr 0x7f01979df090|Src n/a
    [engine] opt done Scheduler>>createIdler:priority:work:state: |AST 55|Tier 2|Time 331( 202+129 )ms|Inlined 10Y 0N|IR 808/ 2972|CodeSize 12342|Addr 0x7f01979df490|Src n/a
    [engine] opt done WorkerTaskDataRecord class>>create |AST 26|Tier 2|Time 103( 77+27 )ms|Inlined 3Y 0N|IR 43/ 116|CodeSize 485|Addr 0x7f01979e4a90|Src n/a
    [engine] opt done True>>and: |AST 17|Tier 2|Time 32( 30+2 )ms|Inlined 0Y 0N|IR 23/ 28|CodeSize 213|Addr 0x7f01979e5810|Src n/a
    [engine] opt done Scheduler>>createWorker:priority:work:state: |AST 55|Tier 2|Time 375( 305+70 )ms|Inlined 11Y 0N|IR 817/ 2989|CodeSize 12248|Addr 0x7f01979e5f10|Src n/a
    [engine] opt done Scheduler>>start |AST 698|Tier 2|Time 2050(1558+492 )ms|Inlined 93Y 7N|IR 4850/10475|CodeSize 42212|Addr 0x7f01979ec210|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 167( 148+19 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f0197a0a710|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 282( 253+29 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7f0197a0c590|Src n/a
    [engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 272( 233+38 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f0197a13b10|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 69
    Success : 65
    Temporary Bailouts : 0
    Permanent Bailouts : 0
    Failed : 0
    Interrupted : 4
    Invalidated : 2
    Profiled Return Type : 1
    Queues : 87
    Dequeues : 22
    Target inlined into only caller : 21
    null : 1
    Splits : 201
    Compilation Accuracy : 0.971014
    Queue Accuracy : 0.747126
    Compilation Utilization : 0.052755
    Remaining Compilation Queue : 0
    Time to queue : count= 87, sum= 1028740, min= 98, average= 11824.61, max= 219965 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 69, sum= 18728, min= 0, average= 271.42, max= 934 (milliseconds), maxTarget=WorkerTaskDataRecord>>count:
    Time for compilation : count= 65, sum= 11644, min= 20, average= 179.14, max= 2050 (milliseconds), maxTarget=Scheduler>>start
    Truffle Tier : count= 65, sum= 9570, min= 18, average= 147.24, max= 1557 (milliseconds), maxTarget=Scheduler>>start
    Graal Tier : count= 65, sum= 1360, min= 1, average= 20.93, max= 330 (milliseconds), maxTarget=Scheduler>>start
    Code Installation : count= 65, sum= 713, min= 1, average= 10.98, max= 162 (milliseconds), maxTarget=Scheduler>>start
    Truffle node count : count= 65, sum= 25858, min= 12, average= 397.82, max= 6055, maxTarget=Scheduler>>start
    Trivial : count= 65, sum= 9969, min= 4, average= 153.37, max= 2255, maxTarget=Scheduler>>start
    Non Trivial : count= 65, sum= 15889, min= 8, average= 244.45, max= 3800, maxTarget=Scheduler>>start
    Monomorphic : count= 65, sum= 15778, min= 8, average= 242.74, max= 3777, maxTarget=Scheduler>>start
    Polymorphic : count= 65, sum= 111, min= 0, average= 1.71, max= 23, maxTarget=Scheduler>>start
    Megamorphic : count= 65, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=TaskState>>isWaitingWithPacket
    Truffle call count : count= 65, sum= 334, min= 0, average= 5.14, max= 100, maxTarget=Scheduler>>start
    Indirect : count= 65, sum= 3, min= 0, average= 0.05, max= 1, maxTarget=TaskControlBlock>>runTask
    Direct : count= 65, sum= 331, min= 0, average= 5.09, max= 100, maxTarget=Scheduler>>start
    Dispatched : count= 65, sum= 12, min= 0, average= 0.18, max= 7, maxTarget=Scheduler>>start
    Inlined : count= 65, sum= 319, min= 0, average= 4.91, max= 93, maxTarget=Scheduler>>start
    ---------- :
    Cloned : count= 65, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=TaskState>>isWaitingWithPacket
    Not Cloned : count= 65, sum= 331, min= 0, average= 5.09, max= 100, maxTarget=Scheduler>>start
    Truffle loops : count= 65, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=TaskState>>isWaitingWithPacket
    Graal node count :
    After Truffle Tier : count= 65, sum= 25450, min= 18, average= 391.54, max= 4850, maxTarget=Scheduler>>start
    After Graal Tier : count= 65, sum= 52031, min= 18, average= 800.48, max= 10475, maxTarget=Scheduler>>start
    Graal compilation result :
    Code size : count= 65, sum= 189741, min= 179, average= 2919.09, max= 42212, maxTarget=Scheduler>>start
    Total frame size : count= 65, sum= 5136, min= 32, average= 79.02, max= 432, maxTarget=Scheduler>>start
    Exception handlers : count= 65, sum= 16, min= 0, average= 0.25, max= 7, maxTarget=Scheduler>>start
    Infopoints : count= 65, sum= 1879, min= 4, average= 28.91, max= 335, maxTarget=Scheduler>>start
    CALL : count= 65, sum= 1526, min= 4, average= 23.48, max= 269, maxTarget=Scheduler>>start
    IMPLICIT_EXCEPTION : count= 65, sum= 328, min= 0, average= 5.05, max= 66, maxTarget=Scheduler>>start
    SAFEPOINT : count= 65, sum= 25, min= 0, average= 0.38, max= 4, maxTarget=Scheduler>>createHandler:priority:work:state:
    Marks : count= 65, sum= 516, min= 7, average= 7.94, max= 14, maxTarget=Scheduler>>start
    Data references : count= 65, sum= 1966, min= 1, average= 30.25, max= 499, maxTarget=Scheduler>>start
    62 changes: 62 additions & 0 deletions 5d99b29f-Sieve.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,62 @@
    # Sieve (iterations: 250, problem size: 3000) on Thu May 27 21:28:28 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Sieve.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'Sieve' 250 3000)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done Sieve>>sieve:size: |AST 134|Tier 2|Time 197( 166+31 )ms|Inlined 0Y 0N|IR 223/ 367|CodeSize 1635|Addr 0x7f7cc3917290|Src n/a
    [engine] opt done Magnitude>>min: |AST 21|Tier 2|Time 37( 35+3 )ms|Inlined 0Y 0N|IR 29/ 34|CodeSize 206|Addr 0x7f7cc391ff90|Src n/a
    [engine] opt done SequenceableCollection>>from:to:put: |AST 162|Tier 2|Time 164( 144+20 )ms|Inlined 1Y 0N|IR 228/ 656|CodeSize 2871|Addr 0x7f7cc3934610|Src n/a
    [engine] opt done SequenceableCollection>>atAllPut: |AST 48|Tier 2|Time 177( 157+20 )ms|Inlined 2Y 0N|IR 265/ 550|CodeSize 1947|Addr 0x7f7cc3947f10|Src n/a
    [engine] opt done ArrayedCollection class>>new:withAll: |AST 31|Tier 2|Time 234( 205+29 )ms|Inlined 3Y 0N|IR 335/ 625|CodeSize 2453|Addr 0x7f7cc3949a10|Src n/a
    [engine] opt done Sieve>>verifyResult: |AST 15|Tier 2|Time 35( 32+2 )ms|Inlined 0Y 0N|IR 25/ 26|CodeSize 216|Addr 0x7f7cc394bc10|Src n/a
    [engine] opt done Sieve>>benchmark |AST 44|Tier 2|Time 301( 255+47 )ms|Inlined 5Y 0N|IR 564/ 922|CodeSize 3231|Addr 0x7f7cc394df10|Src n/a
    [engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 301( 237+63 )ms|Inlined 7Y 0N|IR 657/ 997|CodeSize 3158|Addr 0x7f7cc3958590|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 175( 156+19 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f7cc396c510|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 243( 221+22 )ms|Inlined 4Y 1N|IR 310/ 601|CodeSize 2107|Addr 0x7f7cc3973890|Src n/a
    [engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 275( 235+41 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f7cc397aa10|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 12
    Success : 11
    Temporary Bailouts : 0
    Permanent Bailouts : 0
    Failed : 0
    Interrupted : 1
    Invalidated : 0
    Queues : 12
    Dequeues : 0
    Splits : 191
    Compilation Accuracy : 1.000000
    Queue Accuracy : 1.000000
    Compilation Utilization : 0.040332
    Remaining Compilation Queue : 0
    Time to queue : count= 12, sum= 169220, min= 119, average= 14101.69, max= 53846 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 12, sum= 274, min= 1, average= 22.89, max= 203 (milliseconds), maxTarget=Sieve>>verifyResult:
    Time for compilation : count= 11, sum= 2176, min= 36, average= 197.82, max= 301 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle Tier : count= 11, sum= 1840, min= 32, average= 167.33, max= 253 (milliseconds), maxTarget=Sieve>>benchmark
    Graal Tier : count= 11, sum= 222, min= 1, average= 20.27, max= 44 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Code Installation : count= 11, sum= 112, min= 1, average= 10.22, max= 27 (milliseconds), maxTarget=Sieve>>sieve:size:
    Truffle node count : count= 11, sum= 4228, min= 23, average= 384.36, max= 812, maxTarget=Benchmark>>innerBenchmarkLoop:
    Trivial : count= 11, sum= 1596, min= 8, average= 145.09, max= 298, maxTarget=Benchmark>>innerBenchmarkLoop:
    Non Trivial : count= 11, sum= 2632, min= 15, average= 239.27, max= 514, maxTarget=Benchmark>>innerBenchmarkLoop:
    Monomorphic : count= 11, sum= 2603, min= 15, average= 236.64, max= 514, maxTarget=Benchmark>>innerBenchmarkLoop:
    Polymorphic : count= 11, sum= 29, min= 0, average= 2.64, max= 11, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Megamorphic : count= 11, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Sieve>>sieve:size:
    Truffle call count : count= 11, sum= 30, min= 0, average= 2.73, max= 7, maxTarget=Benchmark>>innerBenchmarkLoop:
    Indirect : count= 11, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Sieve>>sieve:size:
    Direct : count= 11, sum= 30, min= 0, average= 2.73, max= 7, maxTarget=Benchmark>>innerBenchmarkLoop:
    Dispatched : count= 11, sum= 3, min= 0, average= 0.27, max= 1, maxTarget=String class>>new:
    Inlined : count= 11, sum= 27, min= 0, average= 2.45, max= 7, maxTarget=Benchmark>>innerBenchmarkLoop:
    ---------- :
    Cloned : count= 11, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Sieve>>sieve:size:
    Not Cloned : count= 11, sum= 30, min= 0, average= 2.73, max= 7, maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle loops : count= 11, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Sieve>>sieve:size:
    Graal node count :
    After Truffle Tier : count= 11, sum= 3323, min= 25, average= 302.09, max= 657, maxTarget=Benchmark>>innerBenchmarkLoop:
    After Graal Tier : count= 11, sum= 6285, min= 26, average= 571.36, max= 1035, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Graal compilation result :
    Code size : count= 11, sum= 24568, min= 206, average= 2233.45, max= 4845, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Total frame size : count= 11, sum= 1152, min= 32, average= 104.73, max= 208, maxTarget=Benchmark>>innerBenchmarkLoop:
    Exception handlers : count= 11, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Sieve>>sieve:size:
    Infopoints : count= 11, sum= 226, min= 4, average= 20.55, max= 45, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    CALL : count= 11, sum= 173, min= 4, average= 15.73, max= 32, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    IMPLICIT_EXCEPTION : count= 11, sum= 36, min= 0, average= 3.27, max= 13, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    SAFEPOINT : count= 11, sum= 17, min= 0, average= 1.55, max= 5, maxTarget=Sieve>>benchmark
    Marks : count= 11, sum= 98, min= 7, average= 8.91, max= 12, maxTarget=Sieve>>benchmark
    Data references : count= 11, sum= 170, min= 1, average= 15.45, max= 44, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    62 changes: 62 additions & 0 deletions 5d99b29f-Storage.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,62 @@
    # Storage (iterations: 250, problem size: 1000) on Thu May 27 21:24:54 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Storage.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'Storage' 250 1000)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done SomRandom>>next |AST 39|Tier 2|Time 122( 101+21 )ms|Inlined 0Y 0N|IR 83/ 158|CodeSize 527|Addr 0x7eff7f8dfc90|Src n/a
    [engine] opt done Storage>>buildTreeDepth:with: |AST 154|Tier 2|Time 1988( 376+1613)ms|Inlined 5Y 1N|IR 1059/17106|CodeSize 78762|Addr 0x7eff7f919910|Src n/a
    [engine] opt done SomRandom>>initialize |AST 10|Tier 2|Time 30( 26+4 )ms|Inlined 0Y 0N|IR 68/ 77|CodeSize 255|Addr 0x7eff7f95af10|Src n/a
    [engine] opt done Behavior>>new <split-2234078> |AST 28|Tier 2|Time 73( 70+3 )ms|Inlined 1Y 0N|IR 34/ 98|CodeSize 439|Addr 0x7eff7f960410|Src n/a
    [engine] opt done SomRandom class>>new |AST 26|Tier 2|Time 84( 80+4 )ms|Inlined 3Y 0N|IR 34/ 98|CodeSize 439|Addr 0x7eff7f961010|Src n/a
    [engine] opt done Storage>>verifyResult: |AST 15|Tier 2|Time 29( 27+2 )ms|Inlined 0Y 0N|IR 25/ 26|CodeSize 216|Addr 0x7eff7f961d90|Src n/a
    [engine] opt done Storage>>benchmark |AST 49|Tier 2|Time 1742( 290+1452)ms|Inlined 10Y 1N|IR 801/11342|CodeSize 37541|Addr 0x7eff7f967110|Src n/a
    [engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 2177( 423+1754)ms|Inlined 12Y 1N|IR 898/14361|CodeSize 49755|Addr 0x7eff7f99a590|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 181( 162+19 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7eff7f9d5410|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 259( 235+24 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7eff7f9db590|Src n/a
    [engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 282( 244+39 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7eff7f9eb210|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 12
    Success : 10
    Temporary Bailouts : 0
    Permanent Bailouts : 0
    Failed : 0
    Interrupted : 2
    Invalidated : 0
    Queues : 12
    Dequeues : 0
    Splits : 192
    Compilation Accuracy : 1.000000
    Queue Accuracy : 1.000000
    Compilation Utilization : 0.134399
    Remaining Compilation Queue : 0
    Time to queue : count= 12, sum= 166243, min= 35, average= 13853.66, max= 49766 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 12, sum= 130, min= 1, average= 10.92, max= 76 (milliseconds), maxTarget=Storage>>verifyResult:
    Time for compilation : count= 10, sum= 6711, min= 30, average= 671.12, max= 2177 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle Tier : count= 10, sum= 1788, min= 26, average= 178.82, max= 423 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Graal Tier : count= 10, sum= 3062, min= 1, average= 306.22, max= 1124 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Code Installation : count= 10, sum= 1860, min= 1, average= 186.08, max= 644 (milliseconds), maxTarget=Storage>>buildTreeDepth:with:
    Truffle node count : count= 11, sum= 5029, min= 18, average= 457.18, max= 1260, maxTarget=Benchmark>>innerBenchmarkLoop:
    Trivial : count= 11, sum= 1951, min= 8, average= 177.36, max= 484, maxTarget=Benchmark>>innerBenchmarkLoop:
    Non Trivial : count= 11, sum= 3078, min= 10, average= 279.82, max= 776, maxTarget=Benchmark>>innerBenchmarkLoop:
    Monomorphic : count= 11, sum= 3031, min= 10, average= 275.55, max= 770, maxTarget=Benchmark>>innerBenchmarkLoop:
    Polymorphic : count= 11, sum= 47, min= 0, average= 4.27, max= 11, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Megamorphic : count= 11, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=SomRandom>>next
    Truffle call count : count= 11, sum= 46, min= 0, average= 4.18, max= 13, maxTarget=Benchmark>>innerBenchmarkLoop:
    Indirect : count= 11, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=SomRandom>>next
    Direct : count= 11, sum= 46, min= 0, average= 4.18, max= 13, maxTarget=Benchmark>>innerBenchmarkLoop:
    Dispatched : count= 11, sum= 6, min= 0, average= 0.55, max= 1, maxTarget=Storage>>buildTreeDepth:with:
    Inlined : count= 11, sum= 40, min= 0, average= 3.64, max= 12, maxTarget=Benchmark>>innerBenchmarkLoop:
    ---------- :
    Cloned : count= 11, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=SomRandom>>next
    Not Cloned : count= 11, sum= 46, min= 0, average= 4.18, max= 13, maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle loops : count= 11, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=SomRandom>>next
    Graal node count :
    After Truffle Tier : count= 11, sum= 4050, min= 25, average= 368.18, max= 1059, maxTarget=Storage>>buildTreeDepth:with:
    After Graal Tier : count= 11, sum= 45216, min= 26, average= 4110.55, max= 17106, maxTarget=Storage>>buildTreeDepth:with:
    Graal compilation result :
    Code size : count= 11, sum= 176046, min= 216, average= 16004.18, max= 78762, maxTarget=Storage>>buildTreeDepth:with:
    Total frame size : count= 11, sum= 4656, min= 32, average= 423.27, max= 1696, maxTarget=Storage>>buildTreeDepth:with:
    Exception handlers : count= 11, sum= 176, min= 0, average= 16.00, max= 64, maxTarget=Storage>>benchmark
    Infopoints : count= 11, sum= 1908, min= 4, average= 173.45, max= 794, maxTarget=Storage>>buildTreeDepth:with:
    CALL : count= 11, sum= 1513, min= 4, average= 137.55, max= 611, maxTarget=Storage>>buildTreeDepth:with:
    IMPLICIT_EXCEPTION : count= 11, sum= 389, min= 0, average= 35.36, max= 180, maxTarget=Storage>>buildTreeDepth:with:
    SAFEPOINT : count= 11, sum= 6, min= 0, average= 0.55, max= 3, maxTarget=Storage>>buildTreeDepth:with:
    Marks : count= 11, sum= 263, min= 7, average= 23.91, max= 71, maxTarget=Storage>>benchmark
    Data references : count= 11, sum= 1980, min= 2, average= 180.00, max= 724, maxTarget=Storage>>buildTreeDepth:with:
    64 changes: 64 additions & 0 deletions 5d99b29f-Towers.trace.log
    Original file line number Diff line number Diff line change
    @@ -0,0 +1,64 @@
    # Towers (iterations: 250, problem size: 600) on Thu May 27 21:25:50 UTC 2021
    # `/home/fniephaus/bin/graalvm-ee-java11-21.1.0/bin/trufflesqueak --experimental-options --smalltalk.disable-startup --smalltalk.disable-interrupts --engine.Mode=default --engine.MultiTier=false --engine.TraceCompilation --engine.CompilationStatistics --log.file="/home/fniephaus/dev/are-we-fast-yet/traces/Towers.trace.log" --quiet --code "FileStream startUp: true. Harness new run: #(nil 'Towers' 250 600)" /home/fniephaus/dev/are-we-fast-yet/benchmarks/Smalltalk/AWFY64-sista-fbc.image`
    [engine] opt done TowersDisk>>next: |AST 11|Tier 2|Time 113( 97+15 )ms|Inlined 0Y 0N|IR 61/ 182|CodeSize 476|Addr 0x7fc69f6d3390|Src n/a
    [engine] opt done Towers>>pushDisk:onPile: |AST 99|Tier 2|Time 224( 189+35 )ms|Inlined 1Y 0N|IR 356/ 1147|CodeSize 4001|Addr 0x7fc69f6ed210|Src n/a
    [engine] opt done Towers>>moveTopDiskFrom:to: |AST 49|Tier 2|Time 224( 166+59 )ms|Inlined 4Y 0N|IR 615/ 1665|CodeSize 5504|Addr 0x7fc69f700290|Src n/a
    [engine] opt done TowersDisk class>>new: |AST 29|Tier 2|Time 90( 86+4 )ms|Inlined 2Y 0N|IR 37/ 102|CodeSize 441|Addr 0x7fc69f727f90|Src n/a
    [engine] opt done Towers>>buildTowerAt:disks: |AST 67|Tier 2|Time 266( 187+79 )ms|Inlined 5Y 0N|IR 461/ 1797|CodeSize 8232|Addr 0x7fc69f729990|Src n/a
    [engine] opt done Towers>>move:disksFrom:to: |AST 128|Tier 2|Time 2099(1423+676 )ms|Inlined 43Y 5N|IR 4747/12028|CodeSize 44208|Addr 0x7fc69f72ee90|Src n/a
    [engine] opt done Towers>>verifyResult: |AST 15|Tier 2|Time 32( 30+2 )ms|Inlined 0Y 0N|IR 25/ 26|CodeSize 216|Addr 0x7fc69f754590|Src n/a
    [engine] opt done Towers>>benchmark |AST 65|Tier 2|Time 2155(1445+710 )ms|Inlined 50Y 5N|IR 2940/ 7019|CodeSize 21573|Addr 0x7fc69f762310|Src n/a
    [engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 3423(1673+1750)ms|Inlined 85Y 8N|IR 4760/17117|CodeSize 54825|Addr 0x7fc69f77e990|Src n/a
    [engine] opt done String class>>new: |AST 51|Tier 2|Time 169( 151+17 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7fc69f7c9690|Src n/a
    [engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 253( 229+24 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7fc69f7cbf90|Src n/a
    [engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 279( 242+38 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7fc69f7d6890|Src n/a
    [engine] Truffle runtime statistics for engine 2
    Compilations : 14
    Success : 12
    Temporary Bailouts : 0
    Permanent Bailouts : 0
    Failed : 0
    Interrupted : 2
    Invalidated : 0
    Queues : 16
    Dequeues : 3
    Target inlined into only caller : 3
    Splits : 192
    Compilation Accuracy : 1.000000
    Queue Accuracy : 0.812500
    Compilation Utilization : 0.126026
    Remaining Compilation Queue : 0
    Time to queue : count= 16, sum= 240553, min= 51, average= 15034.57, max= 74034 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
    Time waiting in queue : count= 14, sum= 463, min= 1, average= 33.14, max= 238 (milliseconds), maxTarget=Towers>>popDiskFrom:
    Time for compilation : count= 12, sum= 9361, min= 33, average= 780.09, max= 3424 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle Tier : count= 12, sum= 5915, min= 29, average= 492.97, max= 1672 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Graal Tier : count= 12, sum= 2264, min= 1, average= 188.72, max= 1131 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Code Installation : count= 12, sum= 1180, min= 1, average= 98.39, max= 620 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle node count : count= 12, sum= 18749, min= 19, average= 1562.42, max= 7679, maxTarget=Benchmark>>innerBenchmarkLoop:
    Trivial : count= 12, sum= 7006, min= 8, average= 583.83, max= 2859, maxTarget=Benchmark>>innerBenchmarkLoop:
    Non Trivial : count= 12, sum= 11743, min= 11, average= 978.58, max= 4820, maxTarget=Benchmark>>innerBenchmarkLoop:
    Monomorphic : count= 12, sum= 11469, min= 11, average= 955.75, max= 4715, maxTarget=Benchmark>>innerBenchmarkLoop:
    Polymorphic : count= 12, sum= 274, min= 0, average= 22.83, max= 105, maxTarget=Benchmark>>innerBenchmarkLoop:
    Megamorphic : count= 12, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=TowersDisk>>next:
    Truffle call count : count= 12, sum= 220, min= 0, average= 18.33, max= 93, maxTarget=Benchmark>>innerBenchmarkLoop:
    Indirect : count= 12, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=TowersDisk>>next:
    Direct : count= 12, sum= 220, min= 0, average= 18.33, max= 93, maxTarget=Benchmark>>innerBenchmarkLoop:
    Dispatched : count= 12, sum= 21, min= 0, average= 1.75, max= 8, maxTarget=Benchmark>>innerBenchmarkLoop:
    Inlined : count= 12, sum= 199, min= 0, average= 16.58, max= 85, maxTarget=Benchmark>>innerBenchmarkLoop:
    ---------- :
    Cloned : count= 12, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=TowersDisk>>next:
    Not Cloned : count= 12, sum= 220, min= 0, average= 18.33, max= 93, maxTarget=Benchmark>>innerBenchmarkLoop:
    Truffle loops : count= 12, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=TowersDisk>>next:
    Graal node count :
    After Truffle Tier : count= 12, sum= 15050, min= 25, average= 1254.17, max= 4760, maxTarget=Benchmark>>innerBenchmarkLoop:
    After Graal Tier : count= 12, sum= 43033, min= 26, average= 3586.08, max= 17117, maxTarget=Benchmark>>innerBenchmarkLoop:
    Graal compilation result :
    Code size : count= 12, sum= 147588, min= 216, average= 12299.00, max= 54825, maxTarget=Benchmark>>innerBenchmarkLoop:
    Total frame size : count= 12, sum= 1968, min= 32, average= 164.00, max= 448, maxTarget=Towers>>move:disksFrom:to:
    Exception handlers : count= 12, sum= 25, min= 0, average= 2.08, max= 15, maxTarget=Benchmark>>innerBenchmarkLoop:
    Infopoints : count= 12, sum= 1644, min= 4, average= 137.00, max= 645, maxTarget=Benchmark>>innerBenchmarkLoop:
    CALL : count= 12, sum= 1313, min= 4, average= 109.42, max= 506, maxTarget=Benchmark>>innerBenchmarkLoop:
    IMPLICIT_EXCEPTION : count= 12, sum= 322, min= 0, average= 26.83, max= 138, maxTarget=Benchmark>>innerBenchmarkLoop:
    SAFEPOINT : count= 12, sum= 9, min= 0, average= 0.75, max= 4, maxTarget=Towers>>buildTowerAt:disks:
    Marks : count= 12, sum= 122, min= 7, average= 10.17, max= 23, maxTarget=Benchmark>>innerBenchmarkLoop:
    Data references : count= 12, sum= 1018, min= 3, average= 84.83, max= 427, maxTarget=Benchmark>>innerBenchmarkLoop: