Skip to content

Instantly share code, notes, and snippets.

@TruffleSqueak-Bot

TruffleSqueak-Bot/5d99b29-1-summary.md

Created May 27, 2021 22:05
Show Gist options
  • Save TruffleSqueak-Bot/90ac06954bf5e8b4fbd311e0fb8be157 to your computer and use it in GitHub Desktop.
Save TruffleSqueak-Bot/90ac06954bf5e8b4fbd311e0fb8be157 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
5d99b29-1-summary.md

Steady (after 50 iterations)

Benchmark Name Min Geomean Median Mean Max Total (ms) Total (min)
Bounce 363 405 368.13 364 368.04 73625 1.23
DeltaBlue 138 171 150.13 148 150.05 30025 0.5
Havlak 997 1078 1035.63 1050 1035.35 207126 3.45
Json 223 271 227.27 225 227.15 45453 0.76
List 452 500 457.68 456 457.64 91536 1.53
Mandelbrot 140 164 140.62 140 140.6 28123 0.47
NBody 204 244 207.16 205 207.08 41431 0.69
Permute 210 252 215.91 214 215.82 43181 0.72
Queens 178 219 182.48 180 182.3 36495 0.61
Richards 858 902 864.94 862 864.9 172987 2.88
Sieve 208 238 209.82 209 209.78 41963 0.7
Storage 177 211 181.1 178 180.98 36220 0.6
Towers 277 406 280.15 278 279.98 56029 0.93
4425 5061 4520.97 4509 4519.66 904194 15.07
Benchmarks ran on graalvm-ee-java11-21.1.0. 
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: 860.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
Display the source blob
Display the rendered blob
Raw
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.
Display the source blob
Display the rendered blob
Raw
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.
Raw
5d99b29f-Bounce.trace.log
# Bounce (iterations: 250, problem size: 1500) on Thu May 27 21:44:13 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 311( 261+50 )ms|Inlined 8Y 0N|IR 635/ 792|CodeSize 2514|Addr 0x7f0b4a66c390|Src n/a
[engine] opt done Bounce>>benchmark |AST 36|Tier 2|Time 335( 279+55 )ms|Inlined 9Y 0N|IR 770/ 976|CodeSize 3144|Addr 0x7f0b4a674390|Src n/a
[engine] opt done Number>>negated |AST 14|Tier 2|Time 45( 42+3 )ms|Inlined 0Y 0N|IR 24/ 91|CodeSize 403|Addr 0x7f0b4a67c310|Src n/a
[engine] opt done Number>>abs |AST 29|Tier 2|Time 75( 71+4 )ms|Inlined 1Y 0N|IR 61/ 163|CodeSize 572|Addr 0x7f0b4a681110|Src n/a
[engine] opt done SomRandom>>next |AST 39|Tier 2|Time 68( 63+5 )ms|Inlined 0Y 0N|IR 83/ 158|CodeSize 527|Addr 0x7f0b4a68a690|Src n/a
[engine] opt done SequenceableCollection>>do: <split-2e1792e7> |AST 73|Tier 2|Time 501( 321+180 )ms|Inlined 10Y 0N|IR 938/ 3673|CodeSize 14101|Addr 0x7f0b4a693490|Src n/a
[engine] opt done Behavior>>new <split-4e558728> |AST 26|Tier 2|Time 52( 47+5 )ms|Inlined 0Y 0N|IR 34/ 267|CodeSize 990|Addr 0x7f0b4a6a2090|Src n/a
[engine] opt done Ball class>>new: |AST 31|Tier 2|Time 189( 173+16 )ms|Inlined 6Y 0N|IR 391/ 490|CodeSize 1376|Addr 0x7f0b4a6acb10|Src n/a
[engine] opt done SomRandom>>initialize |AST 10|Tier 2|Time 88( 86+3 )ms|Inlined 0Y 0N|IR 68/ 77|CodeSize 255|Addr 0x7f0b4a6b9390|Src n/a
[engine] opt done Behavior>>new <split-4fac1ac2> |AST 28|Tier 2|Time 66( 62+4 )ms|Inlined 1Y 0N|IR 34/ 98|CodeSize 439|Addr 0x7f0b4a6bdb90|Src n/a
[engine] opt done SomRandom class>>new |AST 26|Tier 2|Time 86( 82+4 )ms|Inlined 3Y 0N|IR 34/ 98|CodeSize 439|Addr 0x7f0b4a6be590|Src n/a
[engine] opt done Bounce>>verifyResult: |AST 15|Tier 2|Time 31( 29+2 )ms|Inlined 0Y 0N|IR 25/ 26|CodeSize 216|Addr 0x7f0b4a6bf390|Src n/a
[engine] opt done Bounce>>benchmark |AST 169|Tier 2|Time 960( 582+378 )ms|Inlined 22Y 0N|IR 1939/ 9161|CodeSize 34630|Addr 0x7f0b4a6bf790|Src n/a
[engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 997( 470+527 )ms|Inlined 24Y 0N|IR 2031/ 9434|CodeSize 36336|Addr 0x7f0b4a6d0d10|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 0x7f0b4a6f0710|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 245( 221+24 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7f0b4a6f2190|Src n/a
[engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 274( 233+41 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f0b4a6f9b10|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.048055
Remaining Compilation Queue : 0
Time to queue : count= 19, sum= 296934, min= 51, average= 15628.11, max= 93946 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 19, sum= 1019, min= 1, average= 53.64, max= 243 (milliseconds), maxTarget=Number>>abs
Time for compilation : count= 17, sum= 4529, min= 32, average= 266.46, max= 998 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Truffle Tier : count= 17, sum= 3166, min= 28, average= 186.29, max= 581 (milliseconds), maxTarget=Bounce>>benchmark
Graal Tier : count= 17, sum= 974, min= 1, average= 57.31, max= 394 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Code Installation : count= 17, sum= 388, min= 1, average= 22.86, max= 133 (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= 27454, min= 26, average= 1614.94, max= 9434, maxTarget=Benchmark>>innerBenchmarkLoop:
Graal compilation result :
Code size : count= 17, sum= 104054, min= 216, average= 6120.82, max= 36336, 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= 780, min= 2, average= 45.88, max= 253, maxTarget=Bounce>>benchmark
Raw
5d99b29f-DeltaBlue.trace.log
# DeltaBlue (iterations: 250, problem size: 12000) on Thu May 27 21:51:10 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 Vector>>initialize: |AST 30|Tier 2|Time 161( 150+11 )ms|Inlined 0Y 0N|IR 139/ 337|CodeSize 959|Addr 0x7f16cacc3990|Src n/a
[engine] opt done Behavior>>new <split-3aefae67> |AST 26|Tier 2|Time 139( 123+16 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7f16cacbed90|Src n/a
[engine] opt done Vector class>>new: |AST 29|Tier 2|Time 189( 181+8 )ms|Inlined 2Y 0N|IR 57/ 364|CodeSize 1232|Addr 0x7f16cacc9710|Src n/a
[engine] opt done Strength class>>absoluteWeakest |AST 10|Tier 2|Time 32( 30+2 )ms|Inlined 0Y 0N|IR 21/ 27|CodeSize 230|Addr 0x7f16caccd310|Src n/a
[engine] opt done Variable>>initialize |AST 56|Tier 2|Time 144( 126+18 )ms|Inlined 4Y 0N|IR 208/ 623|CodeSize 1772|Addr 0x7f16cace0f90|Src n/a
[engine] opt inv. Variable>>initialize |AST 56|Calls/Thres 23130/ 3|CallsAndLoop/Thres 23130/ 1000|Src n/a|Reason Latest layout assumption Layout no longer valid
[engine] opt done Vector>>isEmpty |AST 18|Tier 2|Time 48( 46+2 )ms|Inlined 0Y 0N|IR 31/ 46|CodeSize 276|Addr 0x7f16cacfbc90|Src n/a
[engine] opt done BinaryConstraint>>output |AST 20|Tier 2|Time 90( 87+4 )ms|Inlined 0Y 0N|IR 37/ 64|CodeSize 401|Addr 0x7f16cacfdf10|Src n/a
[engine] opt done Vector>>append: |AST 60|Tier 2|Time 165( 150+15 )ms|Inlined 0Y 0N|IR 223/ 701|CodeSize 2109|Addr 0x7f16cad0bf90|Src n/a
[engine] opt done Vector>>forEach: <split-2bc12da> |AST 79|Tier 2|Time 148( 117+31 )ms|Inlined 1Y 0N|IR 201/ 1279|CodeSize 4382|Addr 0x7f16cad1b910|Src n/a
[engine] opt done Variable>>addConstraint: |AST 24|Tier 2|Time 120( 99+20 )ms|Inlined 1Y 0N|IR 289/ 766|CodeSize 2291|Addr 0x7f16cad22290|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 0x7f16cad24190|Src n/a
[engine] opt done Variable>>mark: |AST 11|Tier 2|Time 37( 34+3 )ms|Inlined 0Y 0N|IR 73/ 88|CodeSize 273|Addr 0x7f16cad28510|Src n/a
[engine] opt done Integer>>>> |AST 31|Tier 2|Time 43( 41+3 )ms|Inlined 0Y 0N|IR 39/ 111|CodeSize 462|Addr 0x7f16cad2e510|Src n/a
[engine] opt done SomDictionary>>hash: |AST 60|Tier 2|Time 85( 82+3 )ms|Inlined 1Y 0N|IR 33/ 106|CodeSize 436|Addr 0x7f16cad32010|Src n/a
[engine] opt done SomDictionary>>bucketIdx: |AST 40|Tier 2|Time 66( 61+6 )ms|Inlined 0Y 0N|IR 91/ 211|CodeSize 770|Addr 0x7f16cad38c10|Src n/a
[engine] opt done SomDictionary>>bucket: |AST 33|Tier 2|Time 125( 120+5 )ms|Inlined 1Y 0N|IR 155/ 115|CodeSize 599|Addr 0x7f16cad41410|Src n/a
[engine] opt done SomDictionary>>at: |AST 86|Tier 2|Time 204( 197+7 )ms|Inlined 5Y 0N|IR 238/ 189|CodeSize 867|Addr 0x7f16cad44e10|Src n/a
[engine] opt done Planner>>addPropagate:mark: |AST 131|Tier 2|Time 574( 498+77 )ms|Inlined 22Y 0N|IR 873/ 1183|CodeSize 4259|Addr 0x7f16cad46190|Src n/a
[engine] opt done Strength class>>SymRequired |AST 10|Tier 2|Time 28( 26+2 )ms|Inlined 0Y 0N|IR 21/ 27|CodeSize 230|Addr 0x7f16cad4ce10|Src n/a
[engine] opt done Behavior>>new <split-17ca8b92> |AST 26|Tier 2|Time 51( 46+5 )ms|Inlined 0Y 0N|IR 92/ 268|CodeSize 988|Addr 0x7f16cad4df90|Src n/a
[engine] opt done Strength class>>of: |AST 23|Tier 2|Time 161( 154+7 )ms|Inlined 6Y 0N|IR 285/ 204|CodeSize 929|Addr 0x7f16cad4e810|Src n/a
[engine] opt deopt Vector>>forEach: <split-2bc12da> |AST 79|Src n/a
[engine] opt inv. Planner>>addPropagate:mark: |AST 143|Calls/Thres 7453/ 3|CallsAndLoop/Thres 14907/ 1000|Src n/a|Reason validRootAssumption Split call node
[engine] opt inv. Vector>>forEach: <split-2bc12da> |AST 79|Calls/Thres 2294/ 3|CallsAndLoop/Thres 4589/ 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 0x7f16cad54e90|Src n/a
[engine] opt done Vector class>>with: |AST 43|Tier 2|Time 144( 137+7 )ms|Inlined 4Y 0N|IR 147/ 394|CodeSize 1353|Addr 0x7f16cad62a10|Src n/a
[engine] opt done Vector>>removeFirst |AST 53|Tier 2|Time 198( 193+6 )ms|Inlined 1Y 0N|IR 124/ 164|CodeSize 656|Addr 0x7f16cad63510|Src n/a
[engine] opt done Variable>>walkStrength: |AST 11|Tier 2|Time 28( 25+3 )ms|Inlined 0Y 0N|IR 60/ 165|CodeSize 445|Addr 0x7f16cad65390|Src n/a
[engine] opt done Variable>>stay: |AST 11|Tier 2|Time 29( 26+3 )ms|Inlined 0Y 0N|IR 76/ 91|CodeSize 273|Addr 0x7f16cad65e10|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: |AST 57|Tier 2|Time 149( 126+23 )ms|Inlined 3Y 0N|IR 310/ 446|CodeSize 1731|Addr 0x7f16cad67290|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 0x7f16cad6a810|Src n/a
[engine] opt done Symbol>>= <split-272a179c> |AST 28|Tier 2|Time 41( 38+3 )ms|Inlined 0Y 0N|IR 58/ 73|CodeSize 298|Addr 0x7f16cad6df90|Src n/a
[engine] opt done Strength>>weakest: |AST 25|Tier 2|Time 54( 52+3 )ms|Inlined 1Y 0N|IR 41/ 63|CodeSize 287|Addr 0x7f16cad71790|Src n/a
[engine] opt deopt Planner>>addConstraintsConsuming:to: |AST 57|Src n/a
[engine] opt inv. Planner>>addConstraintsConsuming:to: |AST 57|Calls/Thres 21458/ 3|CallsAndLoop/Thres 21458/ 1000|Src n/a|Reason validRootAssumption Split call node
[engine] opt inv. Vector class>>with: |AST 43|Calls/Thres 13760/ 3|CallsAndLoop/Thres 13760/ 1000|Src n/a|Reason frame version
[engine] opt inv. Variable>>addConstraint: |AST 24|Calls/Thres 5506/ 3|CallsAndLoop/Thres 5506/ 1000|Src n/a|Reason frame version
[engine] opt inv. Vector>>append: |AST 124|Calls/Thres 4460/ 3|CallsAndLoop/Thres 4460/ 1000|Src n/a|Reason frame version
[engine] opt done EqualityConstraint>>execute |AST 80|Tier 2|Time 92( 86+6 )ms|Inlined 3Y 0N|IR 281/ 164|CodeSize 644|Addr 0x7f16cad78910|Src n/a
[engine] opt done Vector>>forEach: <split-2bc12da> |AST 79|Tier 2|Time 475( 327+148 )ms|Inlined 3Y 0N|IR 940/ 3920|CodeSize 15381|Addr 0x7f16cad7ee10|Src n/a
[engine] opt done Vector>>forEach: <split-3605c4d3> |AST 79|Tier 2|Time 204( 127+77 )ms|Inlined 5Y 0N|IR 549/ 3057|CodeSize 11621|Addr 0x7f16cad88a10|Src n/a
[engine] opt inv. Vector>>isEmpty |AST 18|Calls/Thres 1905/ 3|CallsAndLoop/Thres 1905/ 1000|Src n/a|Reason Profiled Argument Types
[engine] opt inv. Vector>>removeFirst |AST 53|Calls/Thres 17074/ 3|CallsAndLoop/Thres 17074/ 1000|Src n/a|Reason Profiled Argument Types
[engine] opt done Plan>>execute |AST 20|Tier 2|Time 100( 91+9 )ms|Inlined 4Y 0N|IR 364/ 244|CodeSize 821|Addr 0x7f16cad93e10|Src n/a
[engine] opt done Vector>>removeFirst |AST 53|Tier 2|Time 212( 206+6 )ms|Inlined 1Y 0N|IR 123/ 164|CodeSize 656|Addr 0x7f16cad98d90|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: |AST 57|Tier 2|Time 530( 226+304 )ms|Inlined 4Y 0N|IR 1099/ 2304|CodeSize 9702|Addr 0x7f16cad99710|Src n/a
[engine] opt done Symbol>>= <split-5bb8f9e2> |AST 28|Tier 2|Time 65( 63+3 )ms|Inlined 0Y 0N|IR 58/ 73|CodeSize 298|Addr 0x7f16cada5e90|Src n/a
[engine] opt done Symbol>>= <split-a619c2> |AST 28|Tier 2|Time 42( 39+3 )ms|Inlined 0Y 0N|IR 58/ 73|CodeSize 298|Addr 0x7f16cada6990|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 0x7f16cada7290|Src n/a
[engine] opt done Vector class>>with: |AST 43|Tier 2|Time 220( 211+9 )ms|Inlined 4Y 0N|IR 281/ 394|CodeSize 1353|Addr 0x7f16cada7910|Src n/a
[engine] opt inv. Vector>>initialize: |AST 30|Calls/Thres 9299/ 3|CallsAndLoop/Thres 9299/ 1000|Src n/a
[engine] opt done Vector>>initialize: |AST 30|Tier 2|Time 64( 55+8 )ms|Inlined 0Y 0N|IR 139/ 337|CodeSize 959|Addr 0x7f16cada9e10|Src n/a
[engine] opt inv. Vector class>>new: |AST 29|Calls/Thres 10799/ 3|CallsAndLoop/Thres 10799/ 1000|Src n/a
[engine] opt done Vector class>>new: |AST 29|Tier 2|Time 104( 90+13 )ms|Inlined 2Y 0N|IR 137/ 460|CodeSize 1363|Addr 0x7f16cadaa990|Src n/a
[engine] opt inv. BinaryConstraint>>output |AST 26|Calls/Thres 142811/ 3|CallsAndLoop/Thres 142817/ 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 0x7f16cadab810|Src n/a
[engine] opt inv. Behavior>>new <split-3aefae67> |AST 27|Calls/Thres 8761/ 3|CallsAndLoop/Thres 8761/ 1000|Src n/a
[engine] opt done Behavior>>new <split-3aefae67> |AST 27|Tier 2|Time 54( 48+6 )ms|Inlined 0Y 0N|IR 80/ 141|CodeSize 502|Addr 0x7f16cadabf10|Src n/a
[engine] opt done Vector>>isEmpty |AST 18|Tier 2|Time 37( 34+2 )ms|Inlined 0Y 0N|IR 31/ 46|CodeSize 276|Addr 0x7f16cadadc90|Src n/a
[engine] opt done Vector>>append: |AST 124|Tier 2|Time 192( 128+64 )ms|Inlined 0Y 0N|IR 638/ 2330|CodeSize 9613|Addr 0x7f16cadae110|Src n/a
[engine] opt done Vector>>forEach: <split-585c13de> |AST 79|Tier 2|Time 325( 183+141 )ms|Inlined 3Y 0N|IR 1002/ 3995|CodeSize 16608|Addr 0x7f16cadb5b90|Src n/a
[engine] opt inv. BinaryConstraint>>output |AST 26|Calls/Thres 147844/ 3|CallsAndLoop/Thres 147844/ 1000|Src n/a
[engine] opt done BinaryConstraint>>output |AST 26|Tier 2|Time 49( 43+6 )ms|Inlined 0Y 0N|IR 95/ 141|CodeSize 550|Addr 0x7f16cadbe110|Src n/a
[engine] opt done Variable>>initialize |AST 56|Tier 2|Time 172( 100+72 )ms|Inlined 4Y 0N|IR 310/ 710|CodeSize 1994|Addr 0x7f16cadbf210|Src n/a
[engine] opt done Vector>>forEach: <split-187eb9a8> |AST 79|Tier 2|Time 643( 317+326 )ms|Inlined 15Y 0N|IR 1828/ 5724|CodeSize 21691|Addr 0x7f16cadc0510|Src n/a
[engine] opt done Variable class>>new |AST 26|Tier 2|Time 183( 161+22 )ms|Inlined 11Y 0N|IR 551/ 1231|CodeSize 3876|Addr 0x7f16cadcdd10|Src n/a
[engine] opt done Planner>>addPropagate:mark: <split-6331250e> |AST 131|Tier 2|Time 838( 559+279 )ms|Inlined 25Y 0N|IR 2288/ 3073|CodeSize 13386|Addr 0x7f16cadd0290|Src n/a
[engine] opt done Behavior>>new <split-6bff19ff> |AST 28|Tier 2|Time 120( 110+10 )ms|Inlined 5Y 0N|IR 265/ 586|CodeSize 1715|Addr 0x7f16caddd190|Src n/a
[engine] opt inv. BinaryConstraint>>initializeVar:var:strength:addTo: |AST 34|Calls/Thres 21541/ 3|CallsAndLoop/Thres 21541/ 1000|Src n/a
[engine] opt done BinaryConstraint>>initializeVar:var:strength:addTo: |AST 34|Tier 2|Time 189( 173+16 )ms|Inlined 8Y 0N|IR 505/ 844|CodeSize 2591|Addr 0x7f16cadde710|Src n/a
[engine] opt done Variable>>addConstraint: |AST 24|Tier 2|Time 244( 138+106 )ms|Inlined 1Y 0N|IR 738/ 3318|CodeSize 10887|Addr 0x7f16caddfe10|Src n/a
[engine] opt deopt Vector>>forEach: <split-3605c4d3> |AST 79|Src n/a
[engine] opt deopt Vector>>forEach: <split-585c13de> |AST 79|Src n/a
[engine] opt deopt Vector>>forEach: <split-187eb9a8> |AST 79|Src n/a
[engine] opt deopt BinaryConstraint>>output |AST 26|Src n/a
[engine] opt done Planner>>addPropagate:mark: <split-69ce2f62> |AST 135|Tier 2|Time 642( 567+75 )ms|Inlined 24Y 0N|IR 1418/ 1143|CodeSize 3565|Addr 0x7f16cade8590|Src n/a
[engine] opt inv. BinaryConstraint>>output |AST 26|Calls/Thres 193039/ 3|CallsAndLoop/Thres 193042/ 1000|Src n/a
[engine] opt done BinaryConstraint>>output |AST 26|Tier 2|Time 40( 34+6 )ms|Inlined 0Y 0N|IR 100/ 145|CodeSize 557|Addr 0x7f16cadecf10|Src n/a
[engine] opt done Planner>>addPropagate:mark: <split-732bb66d> |AST 143|Tier 2|Time 824( 557+267 )ms|Inlined 16Y 0N|IR 2046/ 2851|CodeSize 13155|Addr 0x7f16cadee290|Src n/a
[engine] opt inv. Vector>>forEach: <split-585c13de> |AST 79|Calls/Thres 12004/ 3|CallsAndLoop/Thres 36010/ 1000|Src n/a
[engine] opt done Vector>>forEach: <split-585c13de> |AST 79|Tier 2|Time 337( 188+149 )ms|Inlined 3Y 0N|IR 1077/ 4099|CodeSize 16614|Addr 0x7f16cadfae90|Src n/a
[engine] opt done Planner>>removePropagateFrom: |AST 41|Tier 2|Time 329( 148+181 )ms|Inlined 2Y 0N|IR 867/ 1834|CodeSize 8219|Addr 0x7f16cae05690|Src n/a
[engine] opt done BinaryConstraint>>isSatisfied <split-6ad11a56> |AST 17|Tier 2|Time 38( 34+4 )ms|Inlined 0Y 0N|IR 75/ 112|CodeSize 438|Addr 0x7f16cae0ff90|Src n/a
[engine] opt done Vector>>forEach: <split-1136b469> |AST 79|Tier 2|Time 217( 145+72 )ms|Inlined 5Y 0N|IR 657/ 2750|CodeSize 10991|Addr 0x7f16cae13810|Src n/a
[engine] opt inv. Vector>>forEach: <split-187eb9a8> |AST 79|Calls/Thres 24005/ 3|CallsAndLoop/Thres 72011/ 1000|Src n/a
[engine] opt done Vector>>forEach: <split-187eb9a8> |AST 79|Tier 2|Time 911( 554+357 )ms|Inlined 25Y 0N|IR 2712/ 6538|CodeSize 25036|Addr 0x7f16cae17f10|Src n/a
[engine] opt done Symbol>>= <split-301d8120> |AST 28|Tier 2|Time 41( 39+3 )ms|Inlined 0Y 0N|IR 58/ 44|CodeSize 326|Addr 0x7f16cae27590|Src n/a
[engine] opt done Planner>>constraintsConsuming:do: |AST 62|Tier 2|Time 601( 408+193 )ms|Inlined 24Y 0N|IR 2473/ 4116|CodeSize 16490|Addr 0x7f16cae27d90|Src n/a
[engine] opt done Vector>>forEach: <split-2b87581> |AST 79|Tier 2|Time 194( 109+84 )ms|Inlined 1Y 0N|IR 396/ 3529|CodeSize 13138|Addr 0x7f16cae33710|Src n/a
[engine] opt done Vector>>forEach: <split-38499e48> |AST 79|Tier 2|Time 400( 187+212 )ms|Inlined 3Y 0N|IR 1054/ 3930|CodeSize 16226|Addr 0x7f16cae38e90|Src n/a
[engine] opt done Vector>>forEach: <split-2d0bfb24> |AST 79|Tier 2|Time 322( 185+137 )ms|Inlined 3Y 0N|IR 1072/ 3893|CodeSize 15084|Addr 0x7f16cae44e90|Src n/a
[engine] opt done Vector>>forEach: <split-286b39c2> |AST 79|Tier 2|Time 321( 174+147 )ms|Inlined 3Y 0N|IR 941/ 3920|CodeSize 15455|Addr 0x7f16cae4d290|Src n/a
[engine] opt done Planner>>makePlan: |AST 212|Tier 2|Time 1162( 580+582 )ms|Inlined 24Y 0N|IR 2802/ 5532|CodeSize 29056|Addr 0x7f16cae55390|Src n/a
[engine] opt deopt Vector>>forEach: <split-38499e48> |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 2517( 924+1593)ms|Inlined 50Y 0N|IR 5815/20830|CodeSize 82843|Addr 0x7f16cae72210|Src n/a
[engine] opt inv. Vector>>forEach: <split-38499e48> |AST 79|Calls/Thres 36005/ 3|CallsAndLoop/Thres 108016/ 1000|Src n/a
[engine] opt done Vector>>forEach: <split-38499e48> |AST 79|Tier 2|Time 519( 356+163 )ms|Inlined 3Y 0N|IR 1128/ 4007|CodeSize 16229|Addr 0x7f16caea6d10|Src n/a
[engine] opt done EqualityConstraint>>initializeVar:var:strength:addTo: |AST 45|Tier 2|Time 2021(1063+958 )ms|Inlined 57Y 0N|IR 4712/ 9875|CodeSize 35655|Addr 0x7f16caeaff90|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: <split-7b44b63d> |AST 61|Tier 2|Time 219( 154+65 )ms|Inlined 2Y 0N|IR 916/ 1843|CodeSize 7856|Addr 0x7f16caed1c10|Src n/a
[engine] opt done AbstractConstraint>>inputsKnown: |AST 37|Tier 2|Time 133( 119+14 )ms|Inlined 5Y 0N|IR 350/ 340|CodeSize 1018|Addr 0x7f16caed6c10|Src n/a
[engine] opt done Symbol>>= <split-5f462e3b> |AST 28|Tier 2|Time 40( 38+3 )ms|Inlined 0Y 0N|IR 58/ 44|CodeSize 326|Addr 0x7f16caed8090|Src n/a
[engine] opt done BinaryConstraint>>inputsHasOne: |AST 59|Tier 2|Time 132( 96+37 )ms|Inlined 3Y 0N|IR 397/ 2273|CodeSize 7176|Addr 0x7f16caed8e90|Src n/a
[engine] opt done Vector>>forEach: <split-7c974942> |AST 79|Tier 2|Time 290( 219+71 )ms|Inlined 5Y 0N|IR 549/ 3057|CodeSize 11630|Addr 0x7f16caee6090|Src n/a
[engine] opt done Plan>>execute <split-4525d1d3> |AST 20|Tier 2|Time 96( 87+9 )ms|Inlined 4Y 0N|IR 364/ 244|CodeSize 821|Addr 0x7f16caeeab10|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: <split-4905c46b> |AST 57|Tier 2|Time 476( 305+171 )ms|Inlined 4Y 0N|IR 1174/ 2342|CodeSize 9964|Addr 0x7f16caeeb790|Src n/a
[engine] opt done BinaryConstraint>>isSatisfied <split-4a699efa> |AST 17|Tier 2|Time 37( 34+4 )ms|Inlined 0Y 0N|IR 75/ 112|CodeSize 438|Addr 0x7f16caef4a90|Src n/a
[engine] opt done BinaryConstraint>>isSatisfied <split-1ee29c84> |AST 17|Tier 2|Time 40( 36+4 )ms|Inlined 0Y 0N|IR 75/ 112|CodeSize 438|Addr 0x7f16caef5210|Src n/a
[engine] opt done Planner>>incrementalAdd: <split-6ac97b84> |AST 72|Tier 2|Time 3251(1568+1683)ms|Inlined 79Y 2N|IR 7762/17849|CodeSize 71334|Addr 0x7f16caef5990|Src n/a
[engine] opt done Symbol>>= <split-72458efc> |AST 28|Tier 2|Time 39( 37+3 )ms|Inlined 0Y 0N|IR 58/ 44|CodeSize 326|Addr 0x7f16caf26990|Src n/a
[engine] opt done Planner>>removePropagateFrom: |AST 49|Tier 2|Time 508( 377+131 )ms|Inlined 22Y 0N|IR 2166/ 3044|CodeSize 11682|Addr 0x7f16caf26e90|Src n/a
[engine] opt deopt Vector>>forEach: <split-286b39c2> |AST 79|Src n/a
[engine] opt done EqualityConstraint class>>var:var:strength:addTo: |AST 40|Tier 2|Time 2209(1072+1137)ms|Inlined 59Y 0N|IR 4696/10114|CodeSize 36401|Addr 0x7f16caf30790|Src n/a
[engine] opt done Planner>>incrementalAdd: <split-6d91790b> |AST 72|Tier 2|Time 1787(1183+603 )ms|Inlined 66Y 0N|IR 4180/ 5200|CodeSize 21693|Addr 0x7f16caf5bd10|Src n/a
[engine] opt done StayConstraint class>>var:strength:addTo: |AST 37|Tier 2|Time 2822(1501+1321)ms|Inlined 79Y 2N|IR 6182/10814|CodeSize 41899|Addr 0x7f16caf77490|Src n/a
[engine] opt done Vector>>forEach: <split-5183d589> |AST 79|Tier 2|Time 150( 106+44 )ms|Inlined 2Y 0N|IR 246/ 2170|CodeSize 7900|Addr 0x7f16cafa1110|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 1073( 514+560 )ms|Inlined 24Y 0N|IR 2873/ 5123|CodeSize 27226|Addr 0x7f16cafa4610|Src n/a
[engine] opt inv. Vector>>forEach: <split-286b39c2> |AST 79|Calls/Thres 12003/ 3|CallsAndLoop/Thres 36010/ 1000|Src n/a
[engine] opt done Vector>>forEach: <split-286b39c2> |AST 79|Tier 2|Time 332( 188+144 )ms|Inlined 3Y 0N|IR 1121/ 3877|CodeSize 16055|Addr 0x7f16cafb7810|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: <split-511d5d04> |AST 41|Tier 2|Time 60( 56+4 )ms|Inlined 1Y 0N|IR 77/ 120|CodeSize 417|Addr 0x7f16cafc0310|Src n/a
[engine] opt done Planner>>addPropagate:mark: <split-682c1e93> |AST 131|Tier 2|Time 505( 429+76 )ms|Inlined 24Y 0N|IR 1428/ 1143|CodeSize 3565|Addr 0x7f16cafc0d10|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: <split-42f22995> |AST 61|Tier 2|Time 220( 158+62 )ms|Inlined 2Y 0N|IR 923/ 1827|CodeSize 7824|Addr 0x7f16cafc4f10|Src n/a
[engine] opt done AbstractConstraint>>satisfy:propagate: <split-27068a50> |AST 165|Tier 2|Time 988( 817+171 )ms|Inlined 41Y 0N|IR 2808/ 2937|CodeSize 10921|Addr 0x7f16cafd1190|Src n/a
[engine] opt done BinaryConstraint>>isSatisfied <split-68e62ca4> |AST 17|Tier 2|Time 36( 33+3 )ms|Inlined 0Y 0N|IR 32/ 54|CodeSize 356|Addr 0x7f16cafdb110|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: <split-5328a9c1> |AST 57|Tier 2|Time 146( 123+23 )ms|Inlined 3Y 0N|IR 310/ 446|CodeSize 1731|Addr 0x7f16cafdb690|Src n/a
[engine] opt done BinaryConstraint>>isSatisfied <split-5b78fdb1> |AST 17|Tier 2|Time 36( 34+2 )ms|Inlined 0Y 0N|IR 28/ 40|CodeSize 252|Addr 0x7f16cafdde90|Src n/a
[engine] opt done Planner class>>chainTest: |AST 461|Tier 2|Time 4060(2164+1897)ms|Inlined 71Y 5N|IR 5190/16585|CodeSize 68326|Addr 0x7f16cafe1490|Src n/a
[engine] opt done Planner>>addPropagate:mark: <split-34b9fc7d> |AST 143|Tier 2|Time 1237( 748+489 )ms|Inlined 28Y 0N|IR 2846/ 4053|CodeSize 18940|Addr 0x7f16cb01e490|Src n/a
[engine] opt done Planner>>incrementalAdd: <split-5fe3908f> |AST 72|Tier 2|Time 2150(1282+868 )ms|Inlined 69Y 1N|IR 4777/ 8674|CodeSize 36909|Addr 0x7f16cb02de90|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 0x7f16cb049710|Src n/a
[engine] opt done Planner>>incrementalAdd: <split-25d958c6> |AST 72|Tier 2|Time 1618(1166+453 )ms|Inlined 66Y 0N|IR 4175/ 4878|CodeSize 21821|Addr 0x7f16cb049b90|Src n/a
[engine] opt done Behavior>>new <split-312afbc7> |AST 26|Tier 2|Time 49( 44+5 )ms|Inlined 0Y 0N|IR 92/ 276|CodeSize 1016|Addr 0x7f16cb060610|Src n/a
[engine] opt done Planner class>>projectionTest: |AST 527|Tier 2|Time 3190(2260+929 )ms|Inlined 81Y 6N|IR 3822/17235|CodeSize 73032|Addr 0x7f16cb061b90|Src n/a
[engine] opt done Planner>>addPropagate:mark: <split-4482469c> |AST 143|Tier 2|Time 875( 533+341 )ms|Inlined 28Y 0N|IR 2668/ 4308|CodeSize 20773|Addr 0x7f16cb08a310|Src n/a
[engine] opt done ScaleConstraint>>initializeSrc:scale:offset:dst:strength:addTo:|AST 55|Tier 2|Time 3305(1503+1802)ms|Inlined 62Y 4N|IR 7601/20600|CodeSize 83834|Addr 0x7f16cb098290|Src n/a
[engine] opt done ScaleConstraint class>>var:var:var:var:strength:addTo: |AST 46|Tier 2|Time 3802(1329+2473)ms|Inlined 64Y 4N|IR 7582/20654|CodeSize 84925|Addr 0x7f16cb0d3290|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: <split-7004e3d> |AST 57|Tier 2|Time 367( 205+162 )ms|Inlined 4Y 0N|IR 987/ 2243|CodeSize 10026|Addr 0x7f16cb11a310|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: <split-27f1bbe0> |AST 56|Tier 2|Time 215( 152+63 )ms|Inlined 2Y 0N|IR 762/ 1788|CodeSize 8147|Addr 0x7f16cb123190|Src n/a
[engine] opt done Vector>>forEach: <split-7c211fd0> |AST 79|Tier 2|Time 329( 181+148 )ms|Inlined 3Y 0N|IR 941/ 3920|CodeSize 16359|Addr 0x7f16cb127c10|Src n/a
[engine] opt done Vector>>forEach: <split-1c12f3ee> |AST 79|Tier 2|Time 160( 132+29 )ms|Inlined 1Y 0N|IR 201/ 1279|CodeSize 4349|Addr 0x7f16cb130210|Src n/a
[engine] opt done Vector>>forEach: <split-588ffeb> |AST 79|Tier 2|Time 330( 183+147 )ms|Inlined 3Y 0N|IR 941/ 3920|CodeSize 15455|Addr 0x7f16cb132690|Src n/a
[engine] opt done Planner>>addPropagate:mark: <split-75f2099> |AST 131|Tier 2|Time 564( 470+94 )ms|Inlined 23Y 0N|IR 1350/ 1332|CodeSize 4336|Addr 0x7f16cb13a510|Src n/a
[engine] opt done BinaryConstraint>>isSatisfied <split-693e4d19> |AST 18|Tier 2|Time 46( 42+4 )ms|Inlined 0Y 0N|IR 93/ 100|CodeSize 417|Addr 0x7f16cb13f390|Src n/a
[engine] opt done Planner>>addPropagate:mark: <split-3703bf3c> |AST 143|Tier 2|Time 936( 595+340 )ms|Inlined 28Y 0N|IR 2668/ 4308|CodeSize 20677|Addr 0x7f16cb13fa90|Src n/a
[engine] opt done BinaryConstraint>>addToGraph |AST 44|Tier 2|Time 477( 206+271 )ms|Inlined 4Y 0N|IR 1470/ 6885|CodeSize 22505|Addr 0x7f16cb14de10|Src n/a
[engine] opt done Vector>>forEach: <split-6ad5923a> |AST 79|Tier 2|Time 230( 202+29 )ms|Inlined 1Y 0N|IR 201/ 1279|CodeSize 4349|Addr 0x7f16cb15cc90|Src n/a
[engine] opt done Symbol>>= <split-65327f5> |AST 28|Tier 2|Time 41( 38+3 )ms|Inlined 0Y 0N|IR 58/ 44|CodeSize 326|Addr 0x7f16cb15f490|Src n/a
[engine] opt done AbstractConstraint>>satisfy:propagate: <split-57bd802b> |AST 151|Tier 2|Time 945( 752+193 )ms|Inlined 39Y 0N|IR 2654/ 3040|CodeSize 11246|Addr 0x7f16cb15ff90|Src n/a
[engine] opt done Planner>>addPropagate:mark: <split-45f24169> |AST 131|Tier 2|Time 662( 556+106 )ms|Inlined 23Y 0N|IR 1502/ 1575|CodeSize 5402|Addr 0x7f16cb16a690|Src n/a
[engine] opt done ScaleConstraint>>addToGraph |AST 78|Tier 2|Time 1077( 332+745 )ms|Inlined 8Y 0N|IR 2804/12974|CodeSize 45237|Addr 0x7f16cb171610|Src n/a
[engine] opt done Planner>>incrementalAdd: <split-6569dded> |AST 51|Tier 2|Time 1242( 930+311 )ms|Inlined 49Y 0N|IR 3247/ 3771|CodeSize 12602|Addr 0x7f16cb18c910|Src n/a
[engine] opt done BinaryConstraint>>isSatisfied <split-710d7aff> |AST 17|Tier 2|Time 36( 33+3 )ms|Inlined 0Y 0N|IR 32/ 54|CodeSize 356|Addr 0x7f16cb19b790|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: <split-36bc415e> |AST 57|Tier 2|Time 144( 113+31 )ms|Inlined 2Y 0N|IR 229/ 604|CodeSize 2429|Addr 0x7f16cb19c110|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: <split-6a74d228> |AST 22|Tier 2|Time 30( 29+2 )ms|Inlined 0Y 0N|IR 27/ 27|CodeSize 221|Addr 0x7f16cb19e590|Src n/a
[engine] opt done BinaryConstraint>>isSatisfied <split-5cbb84b1> |AST 17|Tier 2|Time 188( 186+3 )ms|Inlined 0Y 0N|IR 32/ 54|CodeSize 356|Addr 0x7f16cb19ea10|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: <split-2c779e5> |AST 57|Tier 2|Time 144( 114+31 )ms|Inlined 2Y 0N|IR 229/ 604|CodeSize 2429|Addr 0x7f16cb19fd90|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: <split-6a84bc2a> |AST 22|Tier 2|Time 30( 28+2 )ms|Inlined 0Y 0N|IR 27/ 27|CodeSize 221|Addr 0x7f16cb1a2a10|Src n/a
[engine] opt inv. Vector class>>new: |AST 29|Calls/Thres 10874/ 3|CallsAndLoop/Thres 10874/ 1000|Src n/a
[engine] opt done Vector class>>new: |AST 29|Tier 2|Time 102( 83+19 )ms|Inlined 2Y 0N|IR 290/ 606|CodeSize 1886|Addr 0x7f16cb1a3190|Src n/a
[engine] opt inv. Vector>>initialize: |AST 30|Calls/Thres 9374/ 3|CallsAndLoop/Thres 9374/ 1000|Src n/a
[engine] opt done Vector>>initialize: |AST 30|Tier 2|Time 63( 51+11 )ms|Inlined 0Y 0N|IR 205/ 442|CodeSize 1376|Addr 0x7f16cb1a4c90|Src n/a
[engine] opt done AbstractConstraint>>addConstraint: <split-7b60c3e> |AST 35|Tier 2|Time 2331(1183+1147)ms|Inlined 58Y 1N|IR 6024/12897|CodeSize 50243|Addr 0x7f16cb1a5a90|Src n/a
[engine] opt inv. Behavior>>new <split-3aefae67> |AST 27|Calls/Thres 8836/ 3|CallsAndLoop/Thres 8836/ 1000|Src n/a
[engine] opt done Behavior>>new <split-3aefae67> |AST 27|Tier 2|Time 50( 42+7 )ms|Inlined 0Y 0N|IR 123/ 206|CodeSize 782|Addr 0x7f16cb1cff10|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 0x7f16cb1d0890|Src n/a
[engine] opt done AbstractConstraint>>initialize: |AST 25|Tier 2|Time 170( 158+12 )ms|Inlined 7Y 0N|IR 380/ 688|CodeSize 2155|Addr 0x7f16cb1d1090|Src n/a
[engine] opt done AbstractConstraint>>satisfy:propagate: <split-466d49f0> |AST 151|Tier 2|Time 1154( 914+241 )ms|Inlined 47Y 0N|IR 3185/ 3517|CodeSize 11939|Addr 0x7f16cb1d2190|Src n/a
[engine] opt done Strength>>stronger: |AST 27|Tier 2|Time 43( 40+3 )ms|Inlined 0Y 0N|IR 39/ 62|CodeSize 312|Addr 0x7f16cb1ddd90|Src n/a
[engine] opt done BinaryConstraint>>chooseMethod: |AST 241|Tier 2|Time 171( 136+35 )ms|Inlined 4Y 0N|IR 701/ 1312|CodeSize 4865|Addr 0x7f16cb1de290|Src n/a
[engine] opt done Variable>>determinedBy: |AST 11|Tier 2|Time 31( 27+4 )ms|Inlined 0Y 0N|IR 56/ 89|CodeSize 381|Addr 0x7f16cb1e0e90|Src n/a
[engine] opt done AbstractConstraint>>satisfy:propagate: |AST 21|Tier 2|Time 56( 53+4 )ms|Inlined 1Y 0N|IR 115/ 123|CodeSize 276|Addr 0x7f16cb1e1610|Src n/a
[engine] opt done BinaryConstraint>>markUnsatisfied |AST 10|Tier 2|Time 33( 28+5 )ms|Inlined 0Y 0N|IR 77/ 273|CodeSize 840|Addr 0x7f16cb1e2510|Src n/a
[engine] opt done AbstractConstraint>>inputsKnown: |AST 52|Tier 2|Time 55( 52+3 )ms|Inlined 0Y 0N|IR 80/ 97|CodeSize 320|Addr 0x7f16cb1e3690|Src n/a
[engine] opt done BinaryConstraint>>inputsDo: |AST 60|Tier 2|Time 145( 112+33 )ms|Inlined 5Y 0N|IR 410/ 2140|CodeSize 7248|Addr 0x7f16cb1e3d10|Src n/a
[engine] opt done UnaryConstraint>>inputsDo: |AST 6|Tier 2|Time 20( 19+2 )ms|Inlined 0Y 0N|IR 19/ 20|CodeSize 181|Addr 0x7f16cb1e6910|Src n/a
[engine] opt done UnaryConstraint>>chooseMethod: |AST 60|Tier 2|Time 85( 74+10 )ms|Inlined 1Y 0N|IR 229/ 327|CodeSize 1195|Addr 0x7f16cb1e6d10|Src n/a
[engine] opt done Variable class>>value: |AST 41|Tier 2|Time 221( 194+27 )ms|Inlined 13Y 0N|IR 655/ 1310|CodeSize 4107|Addr 0x7f16cb1e7d90|Src n/a
[engine] opt done UnaryConstraint>>addToGraph |AST 27|Tier 2|Time 363( 149+214 )ms|Inlined 2Y 0N|IR 858/ 3539|CodeSize 11446|Addr 0x7f16cb1eb890|Src n/a
[engine] opt done ScaleConstraint>>inputsDo: |AST 136|Tier 2|Time 241( 145+95 )ms|Inlined 13Y 0N|IR 887/ 5969|CodeSize 19286|Addr 0x7f16cb1f3890|Src n/a
[engine] opt done ScaleConstraint>>recalculate |AST 181|Tier 2|Time 211( 181+31 )ms|Inlined 9Y 0N|IR 757/ 789|CodeSize 2527|Addr 0x7f16cb1fad10|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 0x7f16cb1fdc90|Src n/a
[engine] opt done Planner>>addConstraintsConsuming:to: <split-c3fa05a> |AST 57|Tier 2|Time 536( 210+327 )ms|Inlined 4Y 0N|IR 1118/ 2210|CodeSize 9467|Addr 0x7f16cb1ff190|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 0x7f16cb207a90|Src n/a
[engine] opt done Integer>>timesRepeat: |AST 46|Tier 2|Time 383( 192+191 )ms|Inlined 9Y 0N|IR 901/ 3175|CodeSize 11857|Addr 0x7f16cb208190|Src n/a
[engine] opt done AbstractConstraint>>addConstraint: <split-1517f633> |AST 35|Tier 2|Time 3316(1550+1766)ms|Inlined 72Y 4N|IR 7892/13721|CodeSize 61095|Addr 0x7f16cb210810|Src n/a
[engine] opt done UnaryConstraint>>initializeVar:strength:addTo: |AST 45|Tier 2|Time 4013(1822+2191)ms|Inlined 79Y 6N|IR 8305/14379|CodeSize 63711|Addr 0x7f16cb24da90|Src n/a
[engine] opt done Vector>>remove: |AST 97|Tier 2|Time 256( 189+68 )ms|Inlined 3Y 0N|IR 597/ 1589|CodeSize 6390|Addr 0x7f16cb294190|Src n/a
[engine] opt done Variable>>removeConstraint: |AST 39|Tier 2|Time 304( 220+84 )ms|Inlined 4Y 0N|IR 649/ 1832|CodeSize 7546|Addr 0x7f16cb298790|Src n/a
[engine] opt done UnaryConstraint>>removeFromGraph |AST 37|Tier 2|Time 305( 211+94 )ms|Inlined 5Y 0N|IR 734/ 1774|CodeSize 7072|Addr 0x7f16cb29e290|Src n/a
[engine] opt done Vector>>forEach: <split-61ccc65f> |AST 79|Tier 2|Time 288( 162+126 )ms|Inlined 2Y 0N|IR 890/ 2939|CodeSize 11485|Addr 0x7f16cb2a3c10|Src n/a
[engine] opt done String class>>new: |AST 51|Tier 2|Time 115( 102+13 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f16cb2abe10|Src n/a
[engine] opt done UnaryConstraint>>markUnsatisfied |AST 10|Tier 2|Time 29( 25+4 )ms|Inlined 0Y 0N|IR 92/ 106|CodeSize 404|Addr 0x7f16cb2aea10|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 198( 178+21 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7f16cb2b0f10|Src n/a
[engine] opt done Vector>>forEach: <split-695a69a1> |AST 79|Tier 2|Time 421( 272+149 )ms|Inlined 3Y 0N|IR 1054/ 3847|CodeSize 15987|Addr 0x7f16cb2b2c10|Src n/a
[engine] opt done Vector class>>new |AST 20|Tier 2|Time 105( 88+17 )ms|Inlined 3Y 0N|IR 317/ 487|CodeSize 1198|Addr 0x7f16cb2bbd10|Src n/a
[engine] opt done Vector>>forEach: <split-4b1abd11> |AST 79|Tier 2|Time 340( 196+144 )ms|Inlined 3Y 0N|IR 941/ 3837|CodeSize 15100|Addr 0x7f16cb2bd910|Src n/a
[engine] opt done Planner>>extractPlanFromConstraints: |AST 59|Tier 2|Time 1317( 642+674 )ms|Inlined 32Y 0N|IR 3589/ 6877|CodeSize 35617|Addr 0x7f16cb2c5890|Src n/a
[engine] opt done Strength class>>SymPreferred |AST 10|Tier 2|Time 24( 22+2 )ms|Inlined 0Y 0N|IR 21/ 27|CodeSize 230|Addr 0x7f16cb2e2f10|Src n/a
[engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 208( 179+29 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f16cb2e3f10|Src n/a
[engine] Truffle runtime statistics for engine 2
Compilations : 176
Success : 168
Temporary Bailouts : 5
org.graalvm.compiler.core.common.RetryableBailoutException: Assumption invalidated while compiling code: Object[Instance<org.graalvm.compiler.truffle.runtime.OptimizedAssumption>]: 5
Permanent Bailouts : 0
Failed : 0
Interrupted : 3
Invalidated : 24
null : 15
frame version : 3
Profiled Argument Types : 2
Latest layout assumption Layout no longer valid: 1
Queues : 305
Dequeues : 146
Target inlined into only caller : 121
null : 15
Split call node : 7
validRootAssumption Split call node : 2
frame version : 1
Splits : 482
Compilation Accuracy : 0.863636
Queue Accuracy : 0.521311
Compilation Utilization : 1.436005
Remaining Compilation Queue : 0
Time to queue : count= 305, sum= 1461074, min= 2, average= 4790.41, max= 62297 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 176, sum= 735539, min= 0, average= 4179.20, max= 25675 (milliseconds), maxTarget=Variable>>determinedBy:
Time for compilation : count= 173, sum= 89575, min= 20, average= 517.78, max= 4061 (milliseconds), maxTarget=Planner class>>chainTest:
Truffle Tier : count= 168, sum= 49080, min= 18, average= 292.15, max= 2260 (milliseconds), maxTarget=Planner class>>projectionTest:
Graal Tier : count= 168, sum= 22795, min= 1, average= 135.69, max= 1696 (milliseconds), maxTarget=ScaleConstraint class>>var:var:var:var:strength:addTo:
Code Installation : count= 168, sum= 10647, min= 1, average= 63.38, max= 777 (milliseconds), maxTarget=ScaleConstraint class>>var:var:var:var:strength:addTo:
Truffle node count : count= 173, sum= 181244, min= 7, average= 1047.65, max= 6387, maxTarget=UnaryConstraint>>initializeVar:strength:addTo:
Trivial : count= 173, sum= 71486, min= 1, average= 413.21, max= 2512, maxTarget=UnaryConstraint>>initializeVar:strength:addTo:
Non Trivial : count= 173, sum= 109758, min= 6, average= 634.44, max= 3875, maxTarget=UnaryConstraint>>initializeVar:strength:addTo:
Monomorphic : count= 173, sum= 106064, min= 6, average= 613.09, max= 3742, maxTarget=EqualityConstraint class>>var:var:strength:addTo:
Polymorphic : count= 173, sum= 3694, min= 0, average= 21.35, max= 171, maxTarget=AbstractConstraint>>addConstraint:
Megamorphic : count= 173, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
Truffle call count : count= 173, sum= 2179, min= 0, average= 12.60, max= 87, maxTarget=Planner class>>projectionTest:
Indirect : count= 173, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
Direct : count= 173, sum= 2179, min= 0, average= 12.60, max= 87, maxTarget=Planner class>>projectionTest:
Dispatched : count= 173, sum= 50, min= 0, average= 0.29, max= 6, maxTarget=Planner class>>projectionTest:
Inlined : count= 173, sum= 2129, min= 0, average= 12.31, max= 81, maxTarget=Planner class>>projectionTest:
---------- :
Cloned : count= 173, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
Not Cloned : count= 173, sum= 2192, min= 0, average= 12.67, max= 87, maxTarget=Planner class>>projectionTest:
Truffle loops : count= 173, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
Graal node count :
After Truffle Tier : count= 173, sum= 207273, min= 5, average= 1198.11, max= 8305, maxTarget=UnaryConstraint>>initializeVar:strength:addTo:
After Graal Tier : count= 173, sum= 478685, min= 5, average= 2766.97, max= 20830, maxTarget=Planner>>removePropagateFrom:
Graal compilation result :
Code size : count= 168, sum= 1753104, min= 120, average= 10435.14, max= 84925, maxTarget=ScaleConstraint class>>var:var:var:var:strength:addTo:
Total frame size : count= 168, sum= 37648, min= 32, average= 224.10, max= 1072, maxTarget=ScaleConstraint>>initializeSrc:scale:offset:dst:strength:addTo:
Exception handlers : count= 168, sum= 168, min= 0, average= 1.00, max= 16, maxTarget=Planner class>>projectionTest:
Infopoints : count= 168, sum= 17233, min= 4, average= 102.58, max= 804, maxTarget=ScaleConstraint>>initializeSrc:scale:offset:dst:strength:addTo:
CALL : count= 168, sum= 13267, min= 4, average= 78.97, max= 626, maxTarget=ScaleConstraint>>initializeSrc:scale:offset:dst:strength:addTo:
IMPLICIT_EXCEPTION : count= 168, sum= 3590, min= 0, average= 21.37, max= 174, maxTarget=Planner>>incrementalAdd:
SAFEPOINT : count= 168, sum= 376, min= 0, average= 2.24, max= 22, maxTarget=Planner>>removePropagateFrom:
Marks : count= 168, sum= 1772, min= 5, average= 10.55, max= 36, maxTarget=Planner class>>chainTest:
Data references : count= 168, sum= 13921, min= 0, average= 82.86, max= 1328, maxTarget=Planner class>>projectionTest:
Raw
5d99b29f-Havlak.trace.log
# Havlak (iterations: 250, problem size: 1500) on Thu May 27 21:59:19 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 158( 140+19 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fcd478fee90|Src n/a
[engine] opt done Vector class>>new: |AST 29|Tier 2|Time 196( 187+10 )ms|Inlined 2Y 0N|IR 57/ 364|CodeSize 1232|Addr 0x7fcd4790ac10|Src n/a
[engine] opt done Vector>>at: |AST 39|Tier 2|Time 82( 75+7 )ms|Inlined 0Y 0N|IR 138/ 217|CodeSize 843|Addr 0x7fcd4791d310|Src n/a
[engine] opt done Vector>>append: |AST 163|Tier 2|Time 178( 131+47 )ms|Inlined 0Y 0N|IR 452/ 1711|CodeSize 7559|Addr 0x7fcd47940610|Src n/a
[engine] opt done Vector>>forEach: <split-61e45f87> |AST 79|Tier 2|Time 1396( 730+667 )ms|Inlined 22Y 0N|IR 2475/ 8346|CodeSize 36695|Addr 0x7fcd4796c310|Src n/a
[engine] opt done Vector>>forEach: <split-4d8539de> |AST 79|Tier 2|Time 317( 231+85 )ms|Inlined 10Y 0N|IR 616/ 3045|CodeSize 11695|Addr 0x7fcd4798d710|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 0x7fcd47992f10|Src n/a
[engine] opt done HavlakLoopFinder>>identifyEdges: |AST 128|Tier 2|Time 1578( 669+910 )ms|Inlined 22Y 0N|IR 2415/ 6632|CodeSize 32771|Addr 0x7fcd47993910|Src n/a
[engine] opt done Object>>~= <split-45394b31> |AST 26|Tier 2|Time 49( 47+2 )ms|Inlined 1Y 0N|IR 27/ 34|CodeSize 250|Addr 0x7fcd479ae010|Src n/a
[engine] opt done Vector>>hasSome: <split-6ecd665> |AST 81|Tier 2|Time 114( 86+29 )ms|Inlined 1Y 0N|IR 239/ 1284|CodeSize 4736|Addr 0x7fcd479af690|Src n/a
[engine] opt done SomDictionary>>bucket: |AST 33|Tier 2|Time 77( 72+5 )ms|Inlined 1Y 0N|IR 155/ 115|CodeSize 599|Addr 0x7fcd479b5d10|Src n/a
[engine] opt done Vector>>forEach: <split-3b0ca5e1> |AST 37|Tier 2|Time 42( 40+2 )ms|Inlined 0Y 0N|IR 36/ 56|CodeSize 288|Addr 0x7fcd479b6f10|Src n/a
[engine] opt done SomSet>>hasSome: <split-585ac855> |AST 23|Tier 2|Time 130( 95+35 )ms|Inlined 2Y 0N|IR 290/ 1347|CodeSize 4818|Addr 0x7fcd479b8790|Src n/a
[engine] opt done UnionFindNode>>findSet |AST 139|Tier 2|Time 283( 272+10 )ms|Inlined 9Y 0N|IR 363/ 238|CodeSize 755|Addr 0x7fcd479bfd90|Src n/a
[engine] opt done Vector>>size |AST 18|Tier 2|Time 34( 31+3 )ms|Inlined 0Y 0N|IR 32/ 110|CodeSize 451|Addr 0x7fcd479c1710|Src n/a
[engine] opt done SomDictionary>>hash: |AST 60|Tier 2|Time 70( 67+3 )ms|Inlined 1Y 0N|IR 33/ 106|CodeSize 436|Addr 0x7fcd479c1c90|Src n/a
[engine] opt done SomDictionary>>bucketIdx: |AST 40|Tier 2|Time 59( 53+6 )ms|Inlined 0Y 0N|IR 91/ 211|CodeSize 770|Addr 0x7fcd479c2a90|Src n/a
[engine] opt deopt Vector>>at: |AST 39|Src n/a
[engine] opt done Vector class>>new |AST 20|Tier 2|Time 96( 91+5 )ms|Inlined 3Y 0N|IR 49/ 290|CodeSize 1040|Addr 0x7fcd479c8290|Src n/a
[engine] opt inv. Vector>>at: |AST 41|Calls/Thres 8739/ 3|CallsAndLoop/Thres 8745/ 1000|Src n/a
[engine] opt done Vector>>at: |AST 41|Tier 2|Time 68( 55+12 )ms|Inlined 0Y 0N|IR 149/ 275|CodeSize 1032|Addr 0x7fcd479d0610|Src n/a
[engine] opt done Integer>>timesRepeat: |AST 46|Tier 2|Time 141( 53+88 )ms|Inlined 0Y 0N|IR 162/ 1819|CodeSize 5843|Addr 0x7fcd479d5590|Src n/a
[engine] opt inv. Vector>>forEach: <split-4d8539de> |AST 79|Calls/Thres 881/ 3|CallsAndLoop/Thres 10572/ 1000|Src n/a|Reason Latest layout assumption Layout no longer valid
[engine] opt inv. HavlakLoopFinder>>identifyEdges: |AST 128|Calls/Thres 920/ 3|CallsAndLoop/Thres 11040/ 1000|Src n/a|Reason Latest layout assumption Layout no longer valid
[engine] opt done Vector>>at:put: |AST 201|Tier 2|Time 178( 122+56 )ms|Inlined 0Y 0N|IR 483/ 1903|CodeSize 8603|Addr 0x7fcd479e3490|Src n/a
[engine] opt done DictIdEntry class>>new:key:value:next: |AST 40|Tier 2|Time 76( 73+4 )ms|Inlined 2Y 0N|IR 50/ 110|CodeSize 449|Addr 0x7fcd479ebc90|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 0x7fcd479f2890|Src n/a
[engine] opt done DictEntry>>init:key:value:next: |AST 26|Tier 2|Time 35( 31+4 )ms|Inlined 0Y 0N|IR 136/ 281|CodeSize 756|Addr 0x7fcd479f3390|Src n/a
[engine] opt done Vector>>forEach: <split-5f78de22> |AST 79|Tier 2|Time 1085( 481+604 )ms|Inlined 17Y 0N|IR 2103/ 6802|CodeSize 28863|Addr 0x7fcd479f3f10|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 136( 134+2 )ms|Inlined 3Y 0N|IR 5/ 5|CodeSize 120|Addr 0x7fcd47a0ca90|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 370( 303+67 )ms|Inlined 3Y 0N|IR 814/ 1706|CodeSize 7718|Addr 0x7fcd47a16410|Src n/a
[engine] opt done Vector>>hasSome: <split-6fe46b62> |AST 79|Tier 2|Time 160( 84+76 )ms|Inlined 1Y 0N|IR 215/ 4160|CodeSize 14635|Addr 0x7fcd47a1d210|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 1066( 509+557 )ms|Inlined 18Y 0N|IR 2168/ 6724|CodeSize 29119|Addr 0x7fcd47a2cb10|Src n/a
[engine] opt inv. Vector>>hasSome: <split-6fe46b62> |AST 81|Calls/Thres 29122/ 3|CallsAndLoop/Thres 68438/ 1000|Src n/a
[engine] opt done Vector>>hasSome: <split-6fe46b62> |AST 81|Tier 2|Time 166( 83+83 )ms|Inlined 1Y 0N|IR 245/ 4397|CodeSize 14875|Addr 0x7fcd47a44090|Src n/a
[engine] opt done SomSet>>hasSome: <split-516ebdf8> |AST 23|Tier 2|Time 190( 90+100 )ms|Inlined 2Y 0N|IR 296/ 4482|CodeSize 15058|Addr 0x7fcd47a4ac90|Src n/a
[engine] opt inv. Vector>>hasSome: <split-6ecd665> |AST 81|Calls/Thres 18854/ 3|CallsAndLoop/Thres 22616/ 1000|Src n/a
[engine] opt done Vector>>hasSome: <split-6ecd665> |AST 81|Tier 2|Time 110( 80+30 )ms|Inlined 1Y 0N|IR 250/ 1284|CodeSize 4790|Addr 0x7fcd47a51990|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 1116( 567+548 )ms|Inlined 17Y 0N|IR 2173/ 6754|CodeSize 29731|Addr 0x7fcd47a54810|Src n/a
[engine] opt done HavlakLoopFinder>>findLoops |AST 760|Tier 2|Time 5390(1951+3439)ms|Inlined 61Y 11N|IR 11412/41700|CodeSize 178329|Addr 0x7fcd47a6a090|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 0x7fcd47abb110|Src n/a
[engine] opt done HavlakLoopFinder>>setLoopAttribute:nodePool:loop: |AST 137|Tier 2|Time 809( 482+327 )ms|Inlined 16Y 0N|IR 1946/ 4453|CodeSize 19367|Addr 0x7fcd47abba90|Src n/a
[engine] opt done SomSet>>initialize: |AST 25|Tier 2|Time 104( 92+12 )ms|Inlined 3Y 0N|IR 123/ 870|CodeSize 2779|Addr 0x7fcd47ace790|Src n/a
[engine] opt done Vector>>forEach: <split-74fef3f7> |AST 79|Tier 2|Time 866( 389+477 )ms|Inlined 15Y 0N|IR 1642/ 4956|CodeSize 22373|Addr 0x7fcd47ad0c90|Src n/a
[engine] opt done UnionFindNode class>>new |AST 26|Tier 2|Time 90( 66+24 )ms|Inlined 3Y 0N|IR 33/ 98|CodeSize 433|Addr 0x7fcd47adff90|Src n/a
[engine] opt done Behavior>>new <split-3eba57a7> |AST 28|Tier 2|Time 58( 56+3 )ms|Inlined 1Y 0N|IR 33/ 98|CodeSize 433|Addr 0x7fcd47ae0610|Src n/a
[engine] opt inv. Vector>>forEach: <split-61e45f87> |AST 79|Calls/Thres 37968/ 3|CallsAndLoop/Thres 84102/ 1000|Src n/a
[engine] opt done Vector>>forEach: <split-61e45f87> |AST 79|Tier 2|Time 1810( 846+963 )ms|Inlined 26Y 0N|IR 3590/11739|CodeSize 56888|Addr 0x7fcd47ae0c90|Src n/a
[engine] opt done Vector>>removeFirst |AST 53|Tier 2|Time 80( 74+5 )ms|Inlined 1Y 0N|IR 124/ 164|CodeSize 656|Addr 0x7fcd47b06a10|Src n/a
[engine] opt done SomSet>>size |AST 20|Tier 2|Time 50( 46+3 )ms|Inlined 1Y 0N|IR 46/ 128|CodeSize 536|Addr 0x7fcd47b07a10|Src n/a
[engine] opt done HavlakLoopFinder>>MaxNonBackPreds |AST 14|Tier 2|Time 25( 23+2 )ms|Inlined 0Y 0N|IR 18/ 52|CodeSize 277|Addr 0x7fcd47b0a090|Src n/a
[engine] opt done HavlakLoopFinder>>stepD:nodePool: |AST 45|Tier 2|Time 920( 411+509 )ms|Inlined 17Y 0N|IR 1816/ 4334|CodeSize 20913|Addr 0x7fcd47b0a910|Src n/a
[engine] opt done SomSet>>forEach: |AST 24|Tier 2|Time 1937( 791+1146)ms|Inlined 27Y 0N|IR 3635/11812|CodeSize 57245|Addr 0x7fcd47b1eb10|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 0x7fcd47b4ad10|Src n/a
[engine] opt done HavlakLoopFinder>>stepEProcessNonBackPreds:nodePool:workList:x:|AST 58|Tier 2|Time 2232( 831+1401)ms|Inlined 29Y 0N|IR 4000/13391|CodeSize 65337|Addr 0x7fcd47b4b410|Src n/a
[engine] opt inv. SomSet>>hasSome: <split-585ac855> |AST 23|Calls/Thres 25081/ 3|CallsAndLoop/Thres 25081/ 1000|Src n/a
[engine] opt done SomSet>>hasSome: <split-585ac855> |AST 23|Tier 2|Time 126( 90+36 )ms|Inlined 2Y 0N|IR 301/ 1347|CodeSize 4719|Addr 0x7fcd47b78f90|Src n/a
[engine] opt inv. UnionFindNode>>findSet |AST 156|Calls/Thres 57264/ 3|CallsAndLoop/Thres 68463/ 1000|Src n/a
[engine] opt done UnionFindNode>>findSet |AST 156|Tier 2|Time 372( 278+93 )ms|Inlined 12Y 0N|IR 954/ 2136|CodeSize 9045|Addr 0x7fcd47b7c010|Src n/a
[engine] opt inv. Vector>>forEach: <split-3b0ca5e1> |AST 79|Calls/Thres 56505/ 3|CallsAndLoop/Thres 56517/ 1000|Src n/a
[engine] opt done Vector>>forEach: <split-3b0ca5e1> |AST 79|Tier 2|Time 125( 95+30 )ms|Inlined 2Y 0N|IR 266/ 1382|CodeSize 5077|Addr 0x7fcd47b82890|Src n/a
[engine] opt done SomSet>>add: <split-5bb8f9e2> |AST 40|Tier 2|Time 282( 193+88 )ms|Inlined 5Y 0N|IR 804/ 2093|CodeSize 8644|Addr 0x7fcd47b84f10|Src n/a
[engine] opt done HavlakLoopFinder>>findLoops <split-65327f5> |AST 760|Tier 2|Time 5024(2275+2749)ms|Inlined 63Y 7N|IR 10458/38026|CodeSize 165513|Addr 0x7fcd47b8b610|Src n/a
[engine] opt done SimpleLoop>>addNode: |AST 24|Tier 2|Time 422( 304+118 )ms|Inlined 6Y 0N|IR 856/ 1987|CodeSize 8227|Addr 0x7fcd47be0e90|Src n/a
[engine] opt done Vector>>forEach: <split-6569dded> |AST 79|Tier 2|Time 371( 263+108 )ms|Inlined 2Y 0N|IR 686/ 2829|CodeSize 11073|Addr 0x7fcd47be7a90|Src n/a
[engine] opt done Symbol>>= <split-466d49f0> |AST 26|Tier 2|Time 40( 38+2 )ms|Inlined 0Y 0N|IR 27/ 37|CodeSize 240|Addr 0x7fcd47bee010|Src n/a
[engine] opt done Object>>~= <split-710d7aff> |AST 26|Tier 2|Time 54( 51+3 )ms|Inlined 1Y 0N|IR 95/ 53|CodeSize 341|Addr 0x7fcd47bee490|Src n/a
[engine] opt done Symbol>>= <split-2d7e1102> |AST 28|Tier 2|Time 41( 38+3 )ms|Inlined 0Y 0N|IR 58/ 44|CodeSize 324|Addr 0x7fcd47bee990|Src n/a
[engine] opt done SomSet>>add: <split-4d847d32> |AST 40|Tier 2|Time 290( 197+93 )ms|Inlined 5Y 0N|IR 801/ 1938|CodeSize 8118|Addr 0x7fcd47beee90|Src n/a
[engine] opt done Vector>>hasSome: <split-5bb3131b> |AST 81|Tier 2|Time 123( 82+41 )ms|Inlined 1Y 0N|IR 245/ 2212|CodeSize 7307|Addr 0x7fcd47bf5410|Src n/a
[engine] opt done HavlakLoopFinder>>identifyEdges: |AST 128|Tier 2|Time 1419( 603+816 )ms|Inlined 22Y 0N|IR 2505/ 6926|CodeSize 31892|Addr 0x7fcd47bf8790|Src n/a
[engine] opt done BasicBlock>>numPred |AST 20|Tier 2|Time 51( 47+4 )ms|Inlined 1Y 0N|IR 46/ 128|CodeSize 536|Addr 0x7fcd47c14610|Src n/a
[engine] opt done Vector>>forEach: <split-2adddc06> |AST 79|Tier 2|Time 970( 474+496 )ms|Inlined 23Y 0N|IR 1921/ 7065|CodeSize 34520|Addr 0x7fcd47c15610|Src n/a
[engine] opt done HavlakLoopFinder>>findLoops |AST 23|Tier 2|Time 191( 130+62 )ms|Inlined 1Y 0N|IR 527/ 1769|CodeSize 7698|Addr 0x7fcd47c29e90|Src n/a
[engine] opt done DictEntry>>value: |AST 11|Tier 2|Time 28( 26+3 )ms|Inlined 0Y 0N|IR 73/ 88|CodeSize 273|Addr 0x7fcd47c2e890|Src n/a
[engine] opt done HavlakLoopFinder>>stepD:nodePool: |AST 55|Tier 2|Time 532( 345+187 )ms|Inlined 14Y 0N|IR 1455/ 3876|CodeSize 17886|Addr 0x7fcd47c2f510|Src n/a
[engine] opt done HavlakLoopFinder>>processEdges:w: |AST 57|Tier 2|Time 1021( 521+501 )ms|Inlined 21Y 0N|IR 2233/ 5285|CodeSize 24015|Addr 0x7fcd47c3b090|Src n/a
[engine] opt done UnionFindNode>>loop: |AST 11|Tier 2|Time 30( 27+3 )ms|Inlined 0Y 0N|IR 60/ 165|CodeSize 445|Addr 0x7fcd47c53890|Src n/a
[engine] opt done LoopStructureGraph>>createNewLoop:reducible: |AST 80|Tier 2|Time 787( 413+374 )ms|Inlined 23Y 0N|IR 1891/ 5149|CodeSize 22074|Addr 0x7fcd47c54c90|Src n/a
[engine] opt done Behavior>>new <split-6ad11a56> |AST 26|Tier 2|Time 46( 41+6 )ms|Inlined 0Y 0N|IR 94/ 374|CodeSize 1320|Addr 0x7fcd47c64210|Src n/a
[engine] opt deopt LoopStructureGraph>>createNewLoop:reducible: |AST 80|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 614( 438+175 )ms|Inlined 20Y 0N|IR 1310/ 3370|CodeSize 13084|Addr 0x7fcd47c64c10|Src n/a
[engine] opt done HavlakLoopFinder>>setLoopAttribute:nodePool:loop: |AST 60|Tier 2|Time 1154( 509+645 )ms|Inlined 19Y 0N|IR 2285/ 5924|CodeSize 26611|Addr 0x7fcd47c6e190|Src n/a
[engine] opt inv. SimpleLoop class>>basicBlock:reducible: <split-726a6b94> |AST 34|Calls/Thres 57330/ 3|CallsAndLoop/Thres 57330/ 1000|Src n/a
[engine] opt done SimpleLoop class>>basicBlock:reducible: <split-726a6b94> |AST 34|Tier 2|Time 530( 342+188 )ms|Inlined 20Y 0N|IR 1310/ 3522|CodeSize 14282|Addr 0x7fcd47c89590|Src n/a
[engine] opt done SomSet>>add: <split-3ff57625> |AST 40|Tier 2|Time 368( 281+87 )ms|Inlined 5Y 0N|IR 793/ 1884|CodeSize 7816|Addr 0x7fcd47c9ba90|Src n/a
[engine] opt done HavlakLoopFinder>>stepEProcessNonBackPreds:nodePool:workList:x:|AST 213|Tier 2|Time 1201( 603+598 )ms|Inlined 25Y 0N|IR 3323/10925|CodeSize 53049|Addr 0x7fcd47ca1210|Src n/a
[engine] opt inv. LoopStructureGraph>>createNewLoop:reducible: |AST 80|Calls/Thres 63736/ 3|CallsAndLoop/Thres 63736/ 1000|Src n/a
[engine] opt done LoopStructureGraph>>createNewLoop:reducible: |AST 80|Tier 2|Time 808( 498+310 )ms|Inlined 23Y 0N|IR 1891/ 5295|CodeSize 22878|Addr 0x7fcd47cc1890|Src n/a
[engine] opt done SimpleLoop>>init:reducible: <split-522b2631> |AST 93|Tier 2|Time 456( 319+137 )ms|Inlined 18Y 0N|IR 1231/ 3021|CodeSize 12788|Addr 0x7fcd47cd2110|Src n/a
[engine] opt done SimpleLoop>>parent: |AST 28|Tier 2|Time 347( 207+140 )ms|Inlined 7Y 0N|IR 913/ 2061|CodeSize 8295|Addr 0x7fcd47cd9f90|Src n/a
[engine] opt done SomDictionary>>removeAll |AST 33|Tier 2|Time 63( 57+6 )ms|Inlined 0Y 0N|IR 129/ 305|CodeSize 939|Addr 0x7fcd47ce2590|Src n/a
[engine] opt done SimpleLoop>>addChildLoop: |AST 24|Tier 2|Time 315( 204+111 )ms|Inlined 6Y 0N|IR 848/ 1933|CodeSize 7963|Addr 0x7fcd47ce3090|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 0x7fcd47ce9490|Src n/a
[engine] opt done Object>>~= <split-2f8c9c0b> |AST 26|Tier 2|Time 47( 44+2 )ms|Inlined 1Y 0N|IR 27/ 34|CodeSize 250|Addr 0x7fcd47ce9910|Src n/a
[engine] opt done SomSet>>add: <split-77128dab> |AST 40|Tier 2|Time 285( 198+87 )ms|Inlined 5Y 0N|IR 793/ 1884|CodeSize 7816|Addr 0x7fcd47ce9e10|Src n/a
[engine] opt done DictIdEntry>>match:key: |AST 30|Tier 2|Time 110( 107+3 )ms|Inlined 0Y 0N|IR 75/ 77|CodeSize 468|Addr 0x7fcd47cef590|Src n/a
[engine] opt done Vector>>isEmpty |AST 18|Tier 2|Time 105( 103+2 )ms|Inlined 0Y 0N|IR 31/ 46|CodeSize 276|Addr 0x7fcd47cefb90|Src n/a
[engine] opt done HavlakLoopFinder>>isAncestor:v: |AST 41|Tier 2|Time 59( 55+4 )ms|Inlined 0Y 0N|IR 103/ 108|CodeSize 545|Addr 0x7fcd47cf0010|Src n/a
[engine] opt done UnionFindNode>>initialize |AST 10|Tier 2|Time 32( 30+3 )ms|Inlined 0Y 0N|IR 68/ 77|CodeSize 255|Addr 0x7fcd47cf8f90|Src n/a
[engine] opt done SomDictionary>>at: |AST 86|Tier 2|Time 222( 216+6 )ms|Inlined 5Y 0N|IR 287/ 243|CodeSize 1027|Addr 0x7fcd47cfa410|Src n/a
[engine] opt done Object>>= |AST 14|Tier 2|Time 32( 28+4 )ms|Inlined 0Y 0N|IR 76/ 131|CodeSize 513|Addr 0x7fcd47cfae10|Src n/a
[engine] opt done SomSet class>>new |AST 28|Tier 2|Time 128( 112+17 )ms|Inlined 5Y 0N|IR 261/ 632|CodeSize 1834|Addr 0x7fcd47cfb510|Src n/a
[engine] opt done SomSet>>contains: |AST 25|Tier 2|Time 134( 111+23 )ms|Inlined 3Y 0N|IR 318/ 452|CodeSize 1435|Addr 0x7fcd47cfcc90|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 0x7fcd47cfed10|Src n/a
[engine] opt deopt SomIdentitySet>>contains: |AST 25|Src n/a
[engine] opt done SomIdentitySet>>contains: |AST 25|Tier 2|Time 136( 109+27 )ms|Inlined 3Y 0N|IR 315/ 456|CodeSize 1656|Addr 0x7fcd47cff110|Src n/a
[engine] opt inv. SomIdentitySet>>contains: |AST 25|Calls/Thres 129253/ 3|CallsAndLoop/Thres 129253/ 1000|Src n/a
[engine] opt done SomIdentitySet>>contains: |AST 25|Tier 2|Time 138( 108+30 )ms|Inlined 3Y 0N|IR 315/ 442|CodeSize 1718|Addr 0x7fcd47d01310|Src n/a
[engine] opt done HavlakLoopFinder>>processEdges:w: |AST 125|Tier 2|Time 624( 394+230 )ms|Inlined 17Y 0N|IR 1991/ 4682|CodeSize 20585|Addr 0x7fcd47d03510|Src n/a
[engine] opt done HavlakLoopFinder>>initAllNodes |AST 34|Tier 2|Time 123( 121+2 )ms|Inlined 5Y 0N|IR 5/ 5|CodeSize 120|Addr 0x7fcd47d12c10|Src n/a
[engine] opt done UnionFindNode>>initNode:dfs: |AST 20|Tier 2|Time 35( 30+5 )ms|Inlined 0Y 0N|IR 105/ 202|CodeSize 719|Addr 0x7fcd47d13090|Src n/a
[engine] opt done SomIdentityDictionary>>newEntry:value:hash: |AST 31|Tier 2|Time 90( 86+3 )ms|Inlined 3Y 0N|IR 51/ 110|CodeSize 462|Addr 0x7fcd47d13a90|Src n/a
[engine] opt done SomDictionary>>insertBucketEntry:value:hash:head: |AST 122|Tier 2|Time 248( 236+12 )ms|Inlined 7Y 0N|IR 317/ 480|CodeSize 1272|Addr 0x7fcd47d16a10|Src n/a
[engine] opt done HavlakLoopFinder>>stepEProcessNonBackPreds:nodePool:workList:x:|AST 14|Tier 2|Time 28( 27+2 )ms|Inlined 0Y 0N|IR 25/ 25|CodeSize 205|Addr 0x7fcd47d17e90|Src n/a
[engine] opt done SomSet>>contains: |AST 15|Tier 2|Time 27( 26+2 )ms|Inlined 0Y 0N|IR 29/ 29|CodeSize 221|Addr 0x7fcd47d18610|Src n/a
[engine] opt done SimpleLoop>>counter: |AST 11|Tier 2|Time 28( 25+3 )ms|Inlined 0Y 0N|IR 74/ 88|CodeSize 273|Addr 0x7fcd47d18a10|Src n/a
[engine] opt done SomDictionary>>at:put: <split-1813f3e9> |AST 115|Tier 2|Time 336( 316+21 )ms|Inlined 11Y 0N|IR 508/ 743|CodeSize 2380|Addr 0x7fcd47d19090|Src n/a
[engine] opt done ControlFlowGraph>>numNodes |AST 20|Tier 2|Time 56( 52+4 )ms|Inlined 1Y 0N|IR 46/ 128|CodeSize 536|Addr 0x7fcd47d1cd10|Src n/a
[engine] opt done Vector>>removeAll |AST 37|Tier 2|Time 69( 62+7 )ms|Inlined 0Y 0N|IR 154/ 327|CodeSize 969|Addr 0x7fcd47d20090|Src n/a
[engine] opt deopt Vector>>forEach: <split-61e45f87> |AST 79|Src n/a
[engine] opt inv. ControlFlowGraph>>numNodes |AST 20|Calls/Thres 17237/ 3|CallsAndLoop/Thres 17237/ 1000|Src n/a|Reason Profiled Argument Types
[engine] opt inv. HavlakLoopFinder>>findLoops <split-65327f5> |AST 760|Calls/Thres 15/ 3|CallsAndLoop/Thres 234615/ 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 HavlakLoopFinder>>doDFS:current: |AST 226|Tier 2|Time 2154(1104+1050)ms|Inlined 68Y 1N|IR 3671/ 9249|CodeSize 48816|Addr 0x7fcd47d25310|Src n/a
[engine] opt inv. HavlakLoopFinder>>setLoopAttribute:nodePool:loop: |AST 60|Calls/Thres 49913/ 3|CallsAndLoop/Thres 49914/ 1000|Src n/a
[engine] opt done HavlakLoopFinder>>setLoopAttribute:nodePool:loop: |AST 60|Tier 2|Time 1232( 561+671 )ms|Inlined 19Y 0N|IR 2285/ 6082|CodeSize 28464|Addr 0x7fcd47d4fa10|Src n/a
[engine] opt inv. Vector>>forEach: <split-61e45f87> |AST 80|Calls/Thres 37983/ 3|CallsAndLoop/Thres 85635/ 1000|Src n/a
[engine] opt done Vector>>forEach: <split-61e45f87> |AST 80|Tier 2|Time 2649(1047+1602)ms|Inlined 46Y 1N|IR 4842/18949|CodeSize 84696|Addr 0x7fcd47d6b110|Src n/a
[engine] opt done ControlFlowGraph>>numNodes |AST 20|Tier 2|Time 50( 47+3 )ms|Inlined 1Y 0N|IR 46/ 128|CodeSize 536|Addr 0x7fcd47765d90|Src n/a
[engine] opt inv. SomSet>>forEach: |AST 24|Calls/Thres 86499/ 3|CallsAndLoop/Thres 86499/ 1000|Src n/a
[engine] opt done SomSet>>forEach: |AST 24|Tier 2|Time 3047(1050+1997)ms|Inlined 47Y 1N|IR 4906/19278|CodeSize 83154|Addr 0x7fcd47daab90|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 501( 347+154 )ms|Inlined 7Y 0N|IR 913/ 2213|CodeSize 9107|Addr 0x7fcd477ffa10|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 321( 200+121 )ms|Inlined 6Y 0N|IR 848/ 2085|CodeSize 9106|Addr 0x7fcd477f8b10|Src n/a
[engine] opt inv. SomSet>>add: <split-77128dab> |AST 40|Calls/Thres 7701/ 3|CallsAndLoop/Thres 7701/ 1000|Src n/a
[engine] opt done SomSet>>add: <split-77128dab> |AST 40|Tier 2|Time 286( 193+93 )ms|Inlined 5Y 0N|IR 793/ 2036|CodeSize 9091|Addr 0x7fcd47deed10|Src n/a
[engine] opt done LoopTesterApp>>addDummyLoops: |AST 21|Tier 2|Time 225( 203+22 )ms|Inlined 16Y 1N|IR 382/ 1411|CodeSize 5007|Addr 0x7fcd47763290|Src n/a
[engine] opt done Vector>>forEach: <split-4ebadd3d> |AST 79|Tier 2|Time 469( 230+239 )ms|Inlined 10Y 0N|IR 616/ 3066|CodeSize 12130|Addr 0x7fcd47df5090|Src n/a
[engine] opt done Behavior>>new <split-6f012914> |AST 26|Tier 2|Time 48( 42+6 )ms|Inlined 0Y 0N|IR 93/ 288|CodeSize 1058|Addr 0x7fcd47761b10|Src n/a
[engine] opt done HavlakLoopFinder>>init:lsg: |AST 68|Tier 2|Time 184( 164+20 )ms|Inlined 12Y 0N|IR 238/ 1296|CodeSize 3743|Addr 0x7fcd47dfa690|Src n/a
[engine] opt done SomIdentityDictionary class>>new |AST 18|Tier 2|Time 88( 83+5 )ms|Inlined 3Y 0N|IR 45/ 289|CodeSize 1042|Addr 0x7fcd47761190|Src n/a
[engine] opt done SomDictionary class>>new: |AST 29|Tier 2|Time 84( 79+5 )ms|Inlined 2Y 0N|IR 59/ 318|CodeSize 1097|Addr 0x7fcd47760810|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 0x7fcd477f1b10|Src n/a
[engine] opt done SomDictionary>>initialize: |AST 26|Tier 2|Time 54( 49+5 )ms|Inlined 0Y 0N|IR 116/ 268|CodeSize 761|Addr 0x7fcd477f8190|Src n/a
[engine] opt done LoopTesterApp>>buildStraight:n: <split-38499e48> |AST 95|Tier 2|Time 2034( 729+1305)ms|Inlined 30Y 0N|IR 3070/ 9356|CodeSize 45323|Addr 0x7fcd47dfd710|Src n/a
[engine] opt done HavlakLoopFinder>>findLoops <split-65327f5> |AST 760|Tier 2|Time 4823(2232+2591)ms|Inlined 59Y 7N|IR 9876/36078|CodeSize 153739|Addr 0x7fcd47e2b090|Src n/a
[engine] opt done SimpleLoop>>depthLevel: |AST 11|Tier 2|Time 28( 25+3 )ms|Inlined 0Y 0N|IR 74/ 88|CodeSize 273|Addr 0x7fcd47e77910|Src n/a
[engine] opt done HavlakLoopFinder>>findLoops <split-72ba28ee> |AST 760|Tier 2|Time 3629(1795+1834)ms|Inlined 47Y 7N|IR 8476/32313|CodeSize 139315|Addr 0x7fcd47e77f90|Src n/a
[engine] opt done Vector>>forEach: <split-6d367020> |AST 79|Tier 2|Time 684( 358+325 )ms|Inlined 20Y 1N|IR 1376/ 2801|CodeSize 10290|Addr 0x7fcd47eb6710|Src n/a
[engine] opt done SomSet>>forEach: <split-3e134896> |AST 24|Tier 2|Time 744( 368+376 )ms|Inlined 21Y 1N|IR 1414/ 2841|CodeSize 10277|Addr 0x7fcd47ec6610|Src n/a
[engine] opt done Integer>>timesRepeat: <split-4a03bb68> |AST 46|Tier 2|Time 1048( 970+78 )ms|Inlined 1Y 1N|IR 242/ 2796|CodeSize 10209|Addr 0x7fcd47ed4c10|Src n/a
[engine] opt done Behavior>>new <split-6f6962ba> |AST 26|Tier 2|Time 44( 41+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fcd47ed9910|Src n/a
[engine] opt done BasicBlock>>init: |AST 47|Tier 2|Time 129( 118+11 )ms|Inlined 6Y 0N|IR 151/ 762|CodeSize 2330|Addr 0x7fcd47eda210|Src n/a
[engine] opt done LoopTesterApp>>buildStraight:n: <split-4905c46b> |AST 95|Tier 2|Time 1792( 739+1052)ms|Inlined 30Y 0N|IR 3070/ 9356|CodeSize 45323|Addr 0x7fcd47edb490|Src n/a
[engine] opt done LoopTesterApp>>buildStraight:n: <split-17ae7628> |AST 95|Tier 2|Time 1830( 717+1113)ms|Inlined 29Y 0N|IR 2843/ 9090|CodeSize 43740|Addr 0x7fcd47f07c90|Src n/a
[engine] opt done Vector>>forEach: <split-4e868ef5> |AST 79|Tier 2|Time 646( 363+283 )ms|Inlined 9Y 0N|IR 1206/ 5175|CodeSize 21527|Addr 0x7fcd47f31f10|Src n/a
[engine] opt done Integer>>timesRepeat: <split-71c905a3> |AST 46|Tier 2|Time 285( 222+63 )ms|Inlined 17Y 1N|IR 505/ 2683|CodeSize 10976|Addr 0x7fcd47f3f910|Src n/a
[engine] opt done Vector>>forEach: <split-67a056f1> |AST 79|Tier 2|Time 1020( 469+550 )ms|Inlined 23Y 0N|IR 1921/ 7065|CodeSize 34857|Addr 0x7fcd47f43f10|Src n/a
[engine] opt done LoopTesterApp>>findLoops: |AST 44|Tier 2|Time 210( 189+20 )ms|Inlined 15Y 1N|IR 344/ 1363|CodeSize 4859|Addr 0x7fcd47f58910|Src n/a
[engine] opt done HavlakLoopFinder class>>new:lsg: |AST 34|Tier 2|Time 211( 197+14 )ms|Inlined 14Y 0N|IR 273/ 1069|CodeSize 3690|Addr 0x7fcd47f5a810|Src n/a
[engine] opt done HavlakLoopFinder>>initAllNodes |AST 64|Tier 2|Time 574( 537+37 )ms|Inlined 0Y 2N|IR 566/ 2172|CodeSize 7539|Addr 0x7fcd47f5be90|Src n/a
[engine] opt done BasicBlock>>addOutEdge: |AST 24|Tier 2|Time 186( 125+61 )ms|Inlined 1Y 0N|IR 524/ 1763|CodeSize 7881|Addr 0x7fcd47f5ee90|Src n/a
[engine] opt done LoopTesterApp>>buildStraight:n: <split-1136b469> |AST 95|Tier 2|Time 1799( 690+1109)ms|Inlined 29Y 0N|IR 2843/ 9090|CodeSize 43740|Addr 0x7fcd47f63790|Src n/a
[engine] opt done BasicBlock>>addInEdge: |AST 24|Tier 2|Time 194( 132+62 )ms|Inlined 1Y 0N|IR 524/ 1763|CodeSize 7881|Addr 0x7fcd47f8e010|Src n/a
[engine] opt done ControlFlowGraph>>addEdge: |AST 24|Tier 2|Time 194( 133+62 )ms|Inlined 1Y 0N|IR 524/ 1763|CodeSize 7881|Addr 0x7fcd47f92910|Src n/a
[engine] opt done BasicBlock class>>new: |AST 31|Tier 2|Time 283( 274+9 )ms|Inlined 8Y 0N|IR 76/ 687|CodeSize 2383|Addr 0x7fcd47f97210|Src n/a
[engine] opt done HavlakLoopFinder>>initAllNodes <split-15723761> |AST 34|Tier 2|Time 742( 579+162 )ms|Inlined 22Y 0N|IR 1662/ 2889|CodeSize 11973|Addr 0x7fcd47f98210|Src n/a
[engine] opt done HavlakLoopFinder>>findLoops <split-30af7377> |AST 760|Tier 2|Time 4748(2261+2487)ms|Inlined 59Y 7N|IR 9876/36078|CodeSize 155235|Addr 0x7fcd47fa2a90|Src n/a
[engine] opt done SimpleLoop>>nestingLevel: |AST 34|Tier 2|Time 63( 59+5 )ms|Inlined 1Y 0N|IR 158/ 159|CodeSize 381|Addr 0x7fcd47ff3110|Src n/a
[engine] opt done Magnitude>>max: |AST 21|Tier 2|Time 31( 29+2 )ms|Inlined 0Y 0N|IR 29/ 34|CodeSize 206|Addr 0x7fcd47ff3b90|Src n/a
[engine] opt done LoopStructureGraph>>calculateNestingLevelRec:depth: |AST 58|Tier 2|Time 953( 533+420 )ms|Inlined 23Y 1N|IR 1482/ 1950|CodeSize 7514|Addr 0x7fcd47ff3f90|Src n/a
[engine] opt done LoopTesterApp>>buildStraight:n: <split-247667dd> |AST 95|Tier 2|Time 1713( 701+1012)ms|Inlined 29Y 0N|IR 2843/ 9090|CodeSize 43740|Addr 0x7fcd48003890|Src n/a
[engine] opt done LoopTesterApp>>buildStraight:n: <split-1dab9dd6> |AST 95|Tier 2|Time 1780( 717+1063)ms|Inlined 30Y 0N|IR 3070/ 9356|CodeSize 45323|Addr 0x7fcd4802db10|Src n/a
[engine] opt done LoopTesterApp>>constructCFG:p:p: |AST 26|Tier 2|Time 516( 506+9 )ms|Inlined 0Y 1N|IR 107/ 481|CodeSize 1748|Addr 0x7fcd4805a810|Src n/a
[engine] opt done LoopStructureGraph>>calculateNestingLevelRec:depth: |AST 85|Tier 2|Time 1285( 378+908 )ms|Inlined 23Y 1N|IR 1645/ 4111|CodeSize 15329|Addr 0x7fcd4805b910|Src n/a
[engine] opt done LoopTesterApp>>buildBaseLoop: <split-75f2099> |AST 181|Tier 2|Time 2578(2379+198 )ms|Inlined 25Y 9N|IR 1351/ 4453|CodeSize 18737|Addr 0x7fcd4806ea10|Src n/a
[engine] opt done HavlakLoopFinder>>initAllNodes <split-4a699efa> |AST 64|Tier 2|Time 3511(1235+2276)ms|Inlined 76Y 2N|IR 4351/14935|CodeSize 77234|Addr 0x7fcd48079210|Src n/a
[engine] opt done Integer>>timesRepeat: <split-7fedfe27> |AST 46|Tier 2|Time 574( 536+38 )ms|Inlined 0Y 1N|IR 185/ 1687|CodeSize 5334|Addr 0x7fcd480c0310|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 0x7fcd480c2a10|Src n/a
[engine] opt done BasicBlockEdge class>>for:from:to: <split-6d467c87> |AST 37|Tier 2|Time 1302( 674+628 )ms|Inlined 28Y 0N|IR 2917/ 9107|CodeSize 44115|Addr 0x7fcd480c3290|Src n/a
[engine] opt done BasicBlockEdge>>init:from:to: <split-57bd802b> |AST 96|Tier 2|Time 1130( 651+479 )ms|Inlined 26Y 0N|IR 2888/ 9364|CodeSize 44895|Addr 0x7fcd480e4010|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-5e742e4> |AST 76|Tier 2|Time 126( 106+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fcd48101010|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-175acfb2> |AST 94|Tier 2|Time 554( 420+134 )ms|Inlined 13Y 0N|IR 787/ 3402|CodeSize 14078|Addr 0x7fcd48102d90|Src n/a
[engine] opt done LoopTesterApp>>buildDiamond: <split-1c12f3ee> |AST 157|Tier 2|Time 4905(2010+2895)ms|Inlined 66Y 4N|IR 8891/26180|CodeSize 128730|Addr 0x7fcd4810b990|Src n/a
[engine] opt done BasicBlockEdge>>init:from:to: <split-55ea2d70> |AST 96|Tier 2|Time 1111( 651+460 )ms|Inlined 25Y 0N|IR 2659/ 8987|CodeSize 42272|Addr 0x7fcd4817d610|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-bd2f5a9> |AST 76|Tier 2|Time 136( 115+21 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fcd48197610|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-4d4960c8> |AST 115|Tier 2|Time 446( 305+142 )ms|Inlined 14Y 0N|IR 996/ 3505|CodeSize 15132|Addr 0x7fcd48199390|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-3703bf3c> |AST 76|Tier 2|Time 132( 109+22 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fcd481a2910|Src n/a
[engine] opt done BasicBlockEdge>>init:from:to: <split-60921b21> |AST 96|Tier 2|Time 1095( 511+585 )ms|Inlined 26Y 0N|IR 2888/ 9364|CodeSize 44895|Addr 0x7fcd481a4690|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-34cf5a97> |AST 94|Tier 2|Time 498( 364+134 )ms|Inlined 13Y 0N|IR 787/ 3402|CodeSize 14078|Addr 0x7fcd481c1010|Src n/a
[engine] opt done BasicBlockEdge>>init:from:to: <split-4482469c> |AST 96|Tier 2|Time 1114( 650+463 )ms|Inlined 25Y 0N|IR 2659/ 8987|CodeSize 42272|Addr 0x7fcd481c9a10|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-26a81ca3> |AST 76|Tier 2|Time 125( 105+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fcd481e3a10|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-27068a50> |AST 115|Tier 2|Time 426( 285+142 )ms|Inlined 14Y 0N|IR 996/ 3505|CodeSize 15132|Addr 0x7fcd481e5b10|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-1087836a> |AST 115|Tier 2|Time 449( 303+146 )ms|Inlined 14Y 0N|IR 996/ 3505|CodeSize 15132|Addr 0x7fcd481ef090|Src n/a
[engine] opt done BasicBlockEdge>>init:from:to: <split-42723e1a> |AST 96|Tier 2|Time 1053( 511+542 )ms|Inlined 26Y 0N|IR 2888/ 9364|CodeSize 44895|Addr 0x7fcd481f9590|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-11653e3b> |AST 115|Tier 2|Time 501( 359+142 )ms|Inlined 14Y 0N|IR 996/ 3505|CodeSize 15132|Addr 0x7fcd48215f10|Src n/a
[engine] opt done Behavior>>new <split-6b580b88> |AST 26|Tier 2|Time 44( 41+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fcd4821f490|Src n/a
[engine] opt done BasicBlockEdge class>>for:from:to: <split-773bd77b> |AST 37|Tier 2|Time 1333( 534+799 )ms|Inlined 28Y 0N|IR 2917/ 9107|CodeSize 44115|Addr 0x7fcd48221710|Src n/a
[engine] opt done BasicBlockEdge>>init:from:to: <split-6d91790b> |AST 96|Tier 2|Time 1169( 692+477 )ms|Inlined 26Y 0N|IR 2888/ 9364|CodeSize 44895|Addr 0x7fcd48242490|Src n/a
[engine] opt done Behavior>>new <split-a567e72> |AST 26|Tier 2|Time 44( 41+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fcd4825ee10|Src n/a
[engine] opt done BasicBlockEdge class>>for:from:to: <split-6ce90bc5> |AST 37|Tier 2|Time 1226( 509+717 )ms|Inlined 27Y 0N|IR 2685/ 8840|CodeSize 41231|Addr 0x7fcd4825f710|Src n/a
[engine] opt done BasicBlockEdge>>init:from:to: <split-1a5b8489> |AST 96|Tier 2|Time 1071( 615+456 )ms|Inlined 25Y 0N|IR 2659/ 8987|CodeSize 42272|Addr 0x7fcd4827e110|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 0x7fcd48298110|Src n/a
[engine] opt done BasicBlockEdge>>init:from:to: <split-27f1bbe0> |AST 96|Tier 2|Time 1139( 685+455 )ms|Inlined 25Y 0N|IR 2659/ 8987|CodeSize 42272|Addr 0x7fcd48299990|Src n/a
[engine] opt done BasicBlockEdge class>>for:from:to: <split-72805168> |AST 37|Tier 2|Time 1299( 533+766 )ms|Inlined 27Y 0N|IR 2685/ 8840|CodeSize 41231|Addr 0x7fcd482b3d10|Src n/a
[engine] opt done Behavior>>new <split-2d84cb86> |AST 26|Tier 2|Time 47( 44+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fcd482d2d10|Src n/a
[engine] opt done LoopTesterApp>>buildDiamond: <split-7808fb9> |AST 157|Tier 2|Time 4626(1810+2816)ms|Inlined 66Y 3N|IR 8762/25670|CodeSize 124865|Addr 0x7fcd482d3810|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-4b1abd11> |AST 76|Tier 2|Time 137( 117+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fcd48341a90|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-3f36b447> |AST 76|Tier 2|Time 136( 116+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fcd48343c90|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-332f25c8> |AST 76|Tier 2|Time 200( 180+20 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fcd48345a10|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-7c211fd0> |AST 94|Tier 2|Time 420( 261+160 )ms|Inlined 13Y 0N|IR 787/ 3402|CodeSize 14078|Addr 0x7fcd48347790|Src n/a
[engine] opt done BasicBlockEdge>>init:from:to: <split-695a69a1> |AST 96|Tier 2|Time 795( 467+329 )ms|Inlined 16Y 0N|IR 2265/ 6131|CodeSize 28063|Addr 0x7fcd48350190|Src n/a
[engine] opt done BasicBlockEdge>>init:from:to: <split-4a1c0752> |AST 96|Tier 2|Time 741( 438+303 )ms|Inlined 16Y 0N|IR 2265/ 6131|CodeSize 28063|Addr 0x7fcd48366690|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-847f3e7> |AST 76|Tier 2|Time 138( 117+21 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fcd48378d90|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-69cac930> |AST 76|Tier 2|Time 228( 110+118 )ms|Inlined 4Y 0N|IR 370/ 546|CodeSize 2092|Addr 0x7fcd4837ab10|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-47c64cfe> |AST 115|Tier 2|Time 526( 288+238 )ms|Inlined 14Y 0N|IR 996/ 3505|CodeSize 15132|Addr 0x7fcd4837c890|Src n/a
[engine] opt done SimpleLoop class>>basicBlock:reducible: <split-afb5821> |AST 34|Tier 2|Time 233( 201+32 )ms|Inlined 14Y 0N|IR 523/ 1565|CodeSize 5677|Addr 0x7fcd48385e10|Src n/a
[engine] opt done BasicBlockEdge>>init:from:to: <split-264c5d07> |AST 96|Tier 2|Time 765( 468+297 )ms|Inlined 16Y 0N|IR 2265/ 6131|CodeSize 28063|Addr 0x7fcd48388810|Src n/a
[engine] opt done LoopStructureGraph>>initialize |AST 113|Tier 2|Time 490( 367+123 )ms|Inlined 23Y 0N|IR 1340/ 3925|CodeSize 15634|Addr 0x7fcd4839af10|Src n/a
[engine] opt done LoopTesterApp>>buildConnect:end: <split-63014bb6> |AST 31|Tier 2|Time 991( 396+595 )ms|Inlined 19Y 0N|IR 2356/ 6039|CodeSize 26435|Addr 0x7fcd483a3b10|Src n/a
[engine] opt done BasicBlockEdge class>>for:from:to: <split-3a4af7e1> |AST 37|Tier 2|Time 914( 519+395 )ms|Inlined 18Y 0N|IR 2296/ 5984|CodeSize 26261|Addr 0x7fcd483bd990|Src n/a
[engine] opt done LoopStructureGraph class>>new |AST 26|Tier 2|Time 1096( 926+169 )ms|Inlined 49Y 0N|IR 1668/ 4513|CodeSize 15876|Addr 0x7fcd483d2c90|Src n/a
[engine] opt done Integer>>timesRepeat: <split-458544e0> |AST 46|Tier 2|Time 1660(1057+603 )ms|Inlined 67Y 1N|IR 2148/10522|CodeSize 39815|Addr 0x7fcd483dcc10|Src n/a
[engine] opt done LoopTesterApp>>findLoops: <split-56ccd751> |AST 44|Tier 2|Time 225( 203+21 )ms|Inlined 15Y 1N|IR 344/ 1363|CodeSize 4859|Addr 0x7fcd483f0d90|Src n/a
[engine] opt done LoopTesterApp>>constructCFG:p:p: <split-17d8d05a> |AST 106|Tier 2|Time 5831(2272+3559)ms|Inlined 71Y 3N|IR 8637/26138|CodeSize 125503|Addr 0x7fcd483f2c90|Src n/a
[engine] opt done HavlakLoopFinder>>initAllNodes <split-3702467f> |AST 64|Tier 2|Time 4040(1500+2539)ms|Inlined 88Y 3N|IR 5594/17901|CodeSize 93942|Addr 0x7fcd48465f90|Src n/a
[engine] opt done Integer>>timesRepeat: <split-2d66530f> |AST 46|Tier 2|Time 660( 607+53 )ms|Inlined 0Y 1N|IR 192/ 1707|CodeSize 5422|Addr 0x7fcd484bff90|Src n/a
[engine] opt done ControlFlowGraph>>createNode: <split-6699c7b1> |AST 115|Tier 2|Time 539( 373+166 )ms|Inlined 14Y 0N|IR 982/ 3540|CodeSize 15348|Addr 0x7fcd484c3f90|Src n/a
[engine] opt done LoopTesterApp>>buildConnect:end: <split-35c27be4> |AST 31|Tier 2|Time 1118( 482+636 )ms|Inlined 19Y 0N|IR 2356/ 6039|CodeSize 26435|Addr 0x7fcd484cde10|Src n/a
[engine] opt done BasicBlockEdge class>>for:from:to: <split-4047889e> |AST 37|Tier 2|Time 965( 413+552 )ms|Inlined 18Y 0N|IR 2296/ 5984|CodeSize 26261|Addr 0x7fcd484e7c90|Src n/a
[engine] opt done LoopTesterApp>>buildConnect:end: <split-794ca15> |AST 31|Tier 2|Time 1036( 393+643 )ms|Inlined 19Y 0N|IR 2356/ 6039|CodeSize 26435|Addr 0x7fcd484fcf90|Src n/a
[engine] opt done LoopTesterApp>>constructCFG:p:p: <split-3c377bfc> |AST 115|Tier 2|Time 3711(1823+1888)ms|Inlined 55Y 1N|IR 6023/21034|CodeSize 87747|Addr 0x7fcd48517110|Src n/a
[engine] opt done String class>>new: |AST 51|Tier 2|Time 176( 156+20 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7fcd4855d990|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 251( 231+20 )ms|Inlined 4Y 1N|IR 312/ 383|CodeSize 1330|Addr 0x7fcd48561590|Src n/a
[engine] opt inv. SmallInteger>>printString |AST 152|Calls/Thres 127/ 3|CallsAndLoop/Thres 1023/ 1000|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 295( 270+25 )ms|Inlined 4Y 1N|IR 362/ 417|CodeSize 1268|Addr 0x7fcd48566e90|Src n/a
[engine] opt done ControlFlowGraph>>initialize |AST 38|Tier 2|Time 224( 205+19 )ms|Inlined 8Y 0N|IR 129/ 750|CodeSize 2292|Addr 0x7fcd4856e490|Src n/a
[engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 267( 229+39 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7fcd4856f710|Src n/a
[engine] Truffle runtime statistics for engine 2
Compilations : 224
Success : 214
Temporary Bailouts : 5
org.graalvm.compiler.core.common.CancellationBailoutException: Compilation cancelled.: 4
org.graalvm.compiler.core.common.RetryableBailoutException: Assumption invalidated while compiling code: Object[Instance<org.graalvm.compiler.truffle.runtime.OptimizedAssumption>]: 1
Permanent Bailouts : 0
Failed : 0
Interrupted : 5
Invalidated : 23
null : 18
Profiled Argument Types : 3
Latest layout assumption Layout no longer valid: 2
Queues : 380
Dequeues : 186
Target inlined into only caller : 167
null : 18
Split call node : 1
Splits : 654
Compilation Accuracy : 0.897321
Queue Accuracy : 0.510526
Compilation Utilization : 0.551456
Remaining Compilation Queue : 0
Time to queue : count= 380, sum= 6664792, min= 6, average= 17538.93, max= 283344 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 224, sum= 1534133, min= 0, average= 6848.81, max= 25320 (milliseconds), maxTarget=BasicBlock class>>new:
Time for compilation : count= 219, sum= 156722, min= 22, average= 715.63, max= 5831 (milliseconds), maxTarget=LoopTesterApp>>constructCFG:p:p:
Truffle Tier : count= 214, sum= 80193, min= 19, average= 374.74, max= 2379 (milliseconds), maxTarget=LoopTesterApp>>buildBaseLoop:
Graal Tier : count= 214, sum= 49813, min= 1, average= 232.77, max= 2723 (milliseconds), maxTarget=HavlakLoopFinder>>findLoops
Code Installation : count= 214, sum= 24130, min= 1, average= 112.76, max= 1150 (milliseconds), maxTarget=LoopTesterApp>>constructCFG:p:p:
Truffle node count : count= 219, sum= 260332, min= 12, average= 1188.73, max= 7460, maxTarget=HavlakLoopFinder>>initAllNodes
Trivial : count= 219, sum= 99535, min= 4, average= 454.50, max= 2819, maxTarget=LoopTesterApp>>buildDiamond:
Non Trivial : count= 219, sum= 160797, min= 8, average= 734.23, max= 4716, maxTarget=HavlakLoopFinder>>initAllNodes
Monomorphic : count= 219, sum= 158201, min= 8, average= 722.38, max= 4677, maxTarget=HavlakLoopFinder>>initAllNodes
Polymorphic : count= 219, sum= 2596, min= 0, average= 11.85, max= 101, maxTarget=LoopTesterApp>>buildDiamond:
Megamorphic : count= 219, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
Truffle call count : count= 219, sum= 2954, min= 0, average= 13.49, max= 91, maxTarget=HavlakLoopFinder>>initAllNodes
Indirect : count= 219, sum= 1, min= 0, average= 0.00, max= 1, maxTarget=Integer>>timesRepeat:
Direct : count= 219, sum= 2953, min= 0, average= 13.48, max= 91, maxTarget=HavlakLoopFinder>>initAllNodes
Dispatched : count= 219, sum= 86, min= 0, average= 0.39, max= 11, maxTarget=HavlakLoopFinder>>findLoops
Inlined : count= 219, sum= 2867, min= 0, average= 13.09, max= 88, maxTarget=HavlakLoopFinder>>initAllNodes
---------- :
Cloned : count= 219, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
Not Cloned : count= 219, sum= 2959, min= 0, average= 13.51, max= 91, maxTarget=HavlakLoopFinder>>initAllNodes
Truffle loops : count= 219, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Behavior>>new
Graal node count :
After Truffle Tier : count= 219, sum= 296435, min= 5, average= 1353.58, max= 11412, maxTarget=HavlakLoopFinder>>findLoops
After Graal Tier : count= 215, sum= 925153, min= 5, average= 4303.04, max= 41700, maxTarget=HavlakLoopFinder>>findLoops
Graal compilation result :
Code size : count= 214, sum= 4122436, min= 120, average= 19263.72, max= 178329, maxTarget=HavlakLoopFinder>>findLoops
Total frame size : count= 214, sum= 68096, min= 32, average= 318.21, max= 1808, maxTarget=LoopTesterApp>>buildDiamond:
Exception handlers : count= 214, sum= 137, min= 0, average= 0.64, max= 17, maxTarget=HavlakLoopFinder>>initAllNodes
Infopoints : count= 214, sum= 36866, min= 4, average= 172.27, max= 1547, maxTarget=HavlakLoopFinder>>findLoops
CALL : count= 214, sum= 28533, min= 4, average= 133.33, max= 1239, maxTarget=HavlakLoopFinder>>findLoops
IMPLICIT_EXCEPTION : count= 214, sum= 7472, min= 0, average= 34.92, max= 289, maxTarget=HavlakLoopFinder>>findLoops
SAFEPOINT : count= 214, sum= 861, min= 0, average= 4.02, max= 27, maxTarget=LoopTesterApp>>buildDiamond:
Marks : count= 214, sum= 2594, min= 5, average= 12.12, max= 42, maxTarget=HavlakLoopFinder>>findLoops
Data references : count= 214, sum= 27309, min= 0, average= 127.61, max= 1067, maxTarget=HavlakLoopFinder>>findLoops
Raw
5d99b29f-Json.trace.log
# Json (iterations: 250, problem size: 100) on Thu May 27 21:58:05 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 215( 180+35 )ms|Inlined 0Y 0N|IR 184/ 407|CodeSize 1641|Addr 0x7fce7f90d010|Src n/a
[engine] opt done String class>>new: |AST 51|Tier 2|Time 188( 170+18 )ms|Inlined 2Y 1N|IR 213/ 526|CodeSize 1925|Addr 0x7fce7f917790|Src n/a
[engine] opt done Character>>asString |AST 22|Tier 2|Time 206( 197+10 )ms|Inlined 4Y 1N|IR 191/ 259|CodeSize 920|Addr 0x7fce7f91cb10|Src n/a
[engine] opt done String>>= <split-2e1792e7> |AST 69|Tier 2|Time 150( 140+11 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7f938e90|Src n/a
[engine] opt done String>>= <split-6bff19ff> |AST 48|Tier 2|Time 62( 58+4 )ms|Inlined 0Y 0N|IR 43/ 72|CodeSize 381|Addr 0x7fce7f945b10|Src n/a
[engine] opt done Vector>>append: |AST 163|Tier 2|Time 187( 140+48 )ms|Inlined 0Y 0N|IR 456/ 1671|CodeSize 7576|Addr 0x7fce7f94b190|Src n/a
[engine] opt deopt Vector>>append: |AST 163|Src n/a
[engine] opt done JsonParser>>read <split-41e1455d> |AST 105|Tier 2|Time 293( 278+15 )ms|Inlined 6Y 1N|IR 400/ 564|CodeSize 1792|Addr 0x7fce7f960310|Src n/a
[engine] opt inv. Vector>>append: |AST 163|Calls/Thres 4594/ 3|CallsAndLoop/Thres 4744/ 1000|Src n/a
[engine] opt done Vector>>append: |AST 163|Tier 2|Time 170( 116+54 )ms|Inlined 0Y 0N|IR 453/ 1711|CodeSize 7723|Addr 0x7fce7f965110|Src n/a
[engine] opt done JsonParser>>readStringInternal |AST 111|Tier 2|Time 1000( 852+148 )ms|Inlined 36Y 4N|IR 2128/ 2851|CodeSize 10082|Addr 0x7fce7f96b490|Src n/a
[engine] opt done JsonParser>>readArrayElement: |AST 58|Tier 2|Time 809( 421+389 )ms|Inlined 20Y 1N|IR 1469/ 4631|CodeSize 13889|Addr 0x7fce7f978010|Src n/a
[engine] opt done String>>= <split-6a933be2> |AST 69|Tier 2|Time 110( 101+10 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7f982c10|Src n/a
[engine] opt done String>>compareWith: <split-5f78de22> |AST 25|Tier 2|Time 79( 71+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fce7f987610|Src n/a
[engine] opt done String>>compareWith:collated: <split-516ebdf8> |AST 33|Tier 2|Time 68( 61+7 )ms|Inlined 1Y 0N|IR 171/ 213|CodeSize 607|Addr 0x7fce7f988210|Src n/a
[engine] opt done String>>compare:with:collated: <split-4d8539de> |AST 51|Tier 2|Time 52( 45+6 )ms|Inlined 0Y 0N|IR 137/ 181|CodeSize 607|Addr 0x7fce7f988c90|Src n/a
[engine] opt done SequenceableCollection>>copyFrom:to: <split-3eba57a7> |AST 68|Tier 2|Time 153( 127+26 )ms|Inlined 3Y 1N|IR 325/ 831|CodeSize 3402|Addr 0x7fce7f989590|Src n/a
[engine] opt done String>>= <split-4d6f197e> |AST 69|Tier 2|Time 110( 101+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7f98b990|Src n/a
[engine] opt done String>>compareWith: <split-6ef7623> |AST 25|Tier 2|Time 78( 70+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fce7f98da90|Src n/a
[engine] opt done String>>compareWith:collated: <split-64e1dd11> |AST 33|Tier 2|Time 255( 247+7 )ms|Inlined 1Y 0N|IR 171/ 213|CodeSize 607|Addr 0x7fce7f98e690|Src n/a
[engine] opt done JsonParser>>readChar: |AST 39|Tier 2|Time 491( 452+39 )ms|Inlined 11Y 1N|IR 731/ 889|CodeSize 2815|Addr 0x7fce7f990010|Src n/a
[engine] opt done String>>compare:with:collated: <split-5c089b2f> |AST 51|Tier 2|Time 54( 47+6 )ms|Inlined 0Y 0N|IR 137/ 181|CodeSize 607|Addr 0x7fce7f992990|Src n/a
[engine] opt done String>>= <split-6fe46b62> |AST 48|Tier 2|Time 57( 54+3 )ms|Inlined 0Y 0N|IR 43/ 72|CodeSize 381|Addr 0x7fce7f995310|Src n/a
[engine] opt done JsonParser>>read <split-4b6ac111> |AST 109|Tier 2|Time 215( 200+15 )ms|Inlined 6Y 1N|IR 431/ 677|CodeSize 2152|Addr 0x7fce7f995d90|Src n/a
[engine] opt done Vector class>>new: |AST 29|Tier 2|Time 87( 82+6 )ms|Inlined 2Y 0N|IR 60/ 319|CodeSize 1095|Addr 0x7fce7f997490|Src n/a
[engine] opt done Behavior>>new <split-5f462e3b> |AST 26|Tier 2|Time 45( 42+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7fce7f997e10|Src n/a
[engine] opt done Vector>>initialize: |AST 30|Tier 2|Time 57( 51+6 )ms|Inlined 0Y 0N|IR 142/ 292|CodeSize 804|Addr 0x7fce7f998410|Src n/a
[engine] opt done JsonParser>>read <split-2111f854> |AST 105|Tier 2|Time 201( 188+13 )ms|Inlined 6Y 1N|IR 400/ 564|CodeSize 1792|Addr 0x7fce7f999790|Src n/a
[engine] opt done String>>= <split-5765c72a> |AST 48|Tier 2|Time 52( 49+3 )ms|Inlined 0Y 0N|IR 43/ 72|CodeSize 381|Addr 0x7fce7f99a890|Src n/a
[engine] opt done JsonParser>>readNumber |AST 136|Tier 2|Time 2335(2127+208 )ms|Inlined 66Y 7N|IR 3750/ 3576|CodeSize 9258|Addr 0x7fce7f99b110|Src n/a
[engine] opt done Behavior>>new <split-d886892> |AST 28|Tier 2|Time 266( 259+7 )ms|Inlined 5Y 0N|IR 63/ 445|CodeSize 1572|Addr 0x7fce7f9a3910|Src n/a
[engine] opt done JsonArray class>>new |AST 26|Tier 2|Time 310( 303+7 )ms|Inlined 11Y 0N|IR 73/ 445|CodeSize 1572|Addr 0x7fce7f9a4510|Src n/a
[engine] opt done JsonParser>>skipWhiteSpace |AST 19|Tier 2|Time 227( 188+39 )ms|Inlined 12Y 0N|IR 650/ 492|CodeSize 1606|Addr 0x7fce7f9a6b10|Src n/a
[engine] opt done String>>= <split-7c9b78e3> |AST 69|Tier 2|Time 109( 100+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7f9a8190|Src n/a
[engine] opt done String>>= <split-736ac09a> |AST 69|Tier 2|Time 108( 98+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7f9a9c90|Src n/a
[engine] opt done String>>= <split-3b0ca5e1> |AST 69|Tier 2|Time 116( 106+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7f9abc10|Src n/a
[engine] opt done String>>= <split-2a037324> |AST 69|Tier 2|Time 108( 98+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7f9ac990|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 0x7fce7f9ad990|Src n/a
[engine] opt done JsonParser>>endCapture |AST 64|Tier 2|Time 467( 395+72 )ms|Inlined 8Y 1N|IR 667/ 1170|CodeSize 4091|Addr 0x7fce7f9ae010|Src n/a
[engine] opt done JsonParser>>readArray |AST 135|Tier 2|Time 2113(1686+427 )ms|Inlined 62Y 6N|IR 2902/ 4808|CodeSize 15415|Addr 0x7fce7f9b1c10|Src n/a
[engine] opt done JsonParser>>isDigit |AST 196|Tier 2|Time 655( 557+98 )ms|Inlined 40Y 0N|IR 2517/ 1877|CodeSize 2724|Addr 0x7fce7f9bc410|Src n/a
[engine] opt done JsonParser>>readDigit |AST 34|Tier 2|Time 992( 709+284 )ms|Inlined 48Y 1N|IR 2977/ 2513|CodeSize 4016|Addr 0x7fce7f9c1e10|Src n/a
[engine] opt done Vector class>>new |AST 20|Tier 2|Time 93( 87+5 )ms|Inlined 3Y 0N|IR 49/ 290|CodeSize 1040|Addr 0x7fce7f9c8d10|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 0x7fce7f9c9910|Src n/a
[engine] opt done JsonParser>>readRequiredChar: |AST 22|Tier 2|Time 310( 261+49 )ms|Inlined 12Y 1N|IR 768/ 971|CodeSize 2613|Addr 0x7fce7f9ca690|Src n/a
[engine] opt done JsonParser>>readValue |AST 531|Tier 2|Time 2577(2081+496 )ms|Inlined 74Y 28N|IR 5279/ 8114|CodeSize 24251|Addr 0x7fce7f9ce610|Src n/a
[engine] opt done JsonArray>>initialize |AST 22|Tier 2|Time 104( 98+7 )ms|Inlined 4Y 0N|IR 95/ 433|CodeSize 1305|Addr 0x7fce7f9e1590|Src n/a
[engine] opt done HashIndexTable>>initialize |AST 26|Tier 2|Time 141( 115+27 )ms|Inlined 2Y 0N|IR 274/ 534|CodeSize 1577|Addr 0x7fce7f9e2210|Src n/a
[engine] opt done HashIndexTable>>hashSlotFor: |AST 52|Tier 2|Time 80( 76+4 )ms|Inlined 1Y 0N|IR 60/ 167|CodeSize 714|Addr 0x7fce7f9e4410|Src n/a
[engine] opt done String>>= <split-68e62ca4> |AST 69|Tier 2|Time 107( 98+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7f9e4e90|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 0x7fce7f9e5c10|Src n/a
[engine] opt done JsonParser>>readName |AST 35|Tier 2|Time 1024( 826+198 )ms|Inlined 41Y 4N|IR 2410/ 3086|CodeSize 10619|Addr 0x7fce7f9e7310|Src n/a
[engine] opt done JsonObject>>add:with: |AST 98|Tier 2|Time 605( 474+131 )ms|Inlined 6Y 0N|IR 1133/ 3571|CodeSize 16720|Addr 0x7fce7f9f0510|Src n/a
[engine] opt done JsonParser>>readObjectKeyValuePair: |AST 117|Tier 2|Time 2635(1826+809 )ms|Inlined 93Y 6N|IR 5951/ 9649|CodeSize 36489|Addr 0x7fce7f9fad10|Src n/a
[engine] opt done JsonParser>>readNull |AST 78|Tier 2|Time 1049( 935+114 )ms|Inlined 47Y 4N|IR 2427/ 2530|CodeSize 7081|Addr 0x7fce7fa14690|Src n/a
[engine] opt done JsonParser>>skipWhiteSpace <split-5b3f3ba0> |AST 19|Tier 2|Time 197( 164+33 )ms|Inlined 8Y 0N|IR 462/ 522|CodeSize 1030|Addr 0x7fce7fa23a10|Src n/a
[engine] opt done String>>= <split-278f8425> |AST 69|Tier 2|Time 109( 100+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7fa25090|Src n/a
[engine] opt done JsonParser>>isWhiteSpace <split-ddf20fd> |AST 74|Tier 2|Time 181( 153+28 )ms|Inlined 7Y 0N|IR 418/ 479|CodeSize 1046|Addr 0x7fce7fa25e10|Src n/a
[engine] opt done String>>compareWith: <split-695a69a1> |AST 25|Tier 2|Time 77( 69+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fce7fa2fa10|Src n/a
[engine] opt done String>>compareWith:collated: <split-4b1abd11> |AST 33|Tier 2|Time 70( 63+7 )ms|Inlined 1Y 0N|IR 171/ 213|CodeSize 607|Addr 0x7fce7fa30610|Src n/a
[engine] opt done String>>compare:with:collated: <split-3f36b447> |AST 51|Tier 2|Time 56( 50+6 )ms|Inlined 0Y 0N|IR 137/ 181|CodeSize 607|Addr 0x7fce7fa32e90|Src n/a
[engine] opt done String>>= <split-6443b128> |AST 48|Tier 2|Time 57( 54+3 )ms|Inlined 0Y 0N|IR 43/ 72|CodeSize 381|Addr 0x7fce7fa33790|Src n/a
[engine] opt done String>>= <split-5eeedb60> |AST 48|Tier 2|Time 55( 52+3 )ms|Inlined 0Y 0N|IR 43/ 72|CodeSize 381|Addr 0x7fce7fa34010|Src n/a
[engine] opt done String>>= <split-40021799> |AST 48|Tier 2|Time 54( 51+3 )ms|Inlined 0Y 0N|IR 43/ 72|CodeSize 381|Addr 0x7fce7fa34590|Src n/a
[engine] opt done JsonParser>>readObject |AST 130|Tier 2|Time 2750(2347+403 )ms|Inlined 78Y 7N|IR 3593/ 5387|CodeSize 15613|Addr 0x7fce7fa35110|Src n/a
[engine] opt done String>>compareWith: <split-60921b21> |AST 25|Tier 2|Time 150( 142+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fce7fa42a90|Src n/a
[engine] opt done String>>= <split-1eea9d2d> |AST 69|Tier 2|Time 182( 173+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7fa43f90|Src n/a
[engine] opt done Behavior>>new <split-6ad6fa53> |AST 28|Tier 2|Time 170( 132+38 )ms|Inlined 3Y 0N|IR 299/ 697|CodeSize 1862|Addr 0x7fce7fa44f10|Src n/a
[engine] opt done HashIndexTable class>>new |AST 26|Tier 2|Time 244( 177+66 )ms|Inlined 7Y 0N|IR 529/ 1015|CodeSize 2761|Addr 0x7fce7fa46f90|Src n/a
[engine] opt done String>>= <split-55ea2d70> |AST 69|Tier 2|Time 108( 99+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7fa4b010|Src n/a
[engine] opt done JsonObject>>initialize |AST 54|Tier 2|Time 346( 256+91 )ms|Inlined 16Y 0N|IR 663/ 1786|CodeSize 5551|Addr 0x7fce7fa4c090|Src n/a
[engine] opt done String>>compareWith: <split-71c905a3> |AST 25|Tier 2|Time 77( 69+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fce7fa51790|Src n/a
[engine] opt done String>>= <split-4e868ef5> |AST 69|Tier 2|Time 109( 100+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7fa52c10|Src n/a
[engine] opt done String>>compareWith: <split-1d207fad> |AST 25|Tier 2|Time 82( 74+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fce7fa54290|Src n/a
[engine] opt done String>>= <split-2d66530f> |AST 69|Tier 2|Time 114( 105+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7fa54e90|Src n/a
[engine] opt done String>>compareWith: <split-59712875> |AST 25|Tier 2|Time 84( 76+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fce7fa55c10|Src n/a
[engine] opt done String>>= <split-72cb66bc> |AST 69|Tier 2|Time 116( 107+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7fa56810|Src n/a
[engine] opt done String>>compareWith: <split-1869f114> |AST 25|Tier 2|Time 85( 77+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fce7fa57590|Src n/a
[engine] opt done String>>= <split-25f918c> |AST 69|Tier 2|Time 116( 107+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7fa58190|Src n/a
[engine] opt done String>>compareWith: <split-6090f3ca> |AST 25|Tier 2|Time 82( 74+8 )ms|Inlined 2Y 0N|IR 205/ 247|CodeSize 624|Addr 0x7fce7fa58f10|Src n/a
[engine] opt done String>>= <split-20b5ec3e> |AST 69|Tier 2|Time 118( 109+9 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7fa5aa10|Src n/a
[engine] opt done String>>= <split-6872f9c8> |AST 48|Tier 2|Time 60( 57+3 )ms|Inlined 0Y 0N|IR 43/ 72|CodeSize 381|Addr 0x7fce7fa5be10|Src n/a
[engine] opt done JsonLiteral class>>TRUE |AST 10|Tier 2|Time 27( 26+2 )ms|Inlined 0Y 0N|IR 21/ 27|CodeSize 230|Addr 0x7fce7fa5c910|Src n/a
[engine] opt done JsonParser>>read <split-f9b5552> |AST 105|Tier 2|Time 281( 268+13 )ms|Inlined 6Y 1N|IR 400/ 564|CodeSize 1792|Addr 0x7fce7fa5d310|Src n/a
[engine] opt done String>>= <split-4fe47286> |AST 69|Tier 2|Time 182( 173+10 )ms|Inlined 3Y 0N|IR 259/ 272|CodeSize 596|Addr 0x7fce7fa5e410|Src n/a
[engine] opt done Vector>>at: |AST 39|Tier 2|Time 63( 59+4 )ms|Inlined 0Y 0N|IR 69/ 101|CodeSize 514|Addr 0x7fce7fa60b10|Src n/a
[engine] opt done Object>>= |AST 14|Tier 2|Time 39( 35+4 )ms|Inlined 0Y 0N|IR 76/ 131|CodeSize 513|Addr 0x7fce7fa62210|Src n/a
[engine] opt done JsonParser>>read <split-5d58c727> |AST 105|Tier 2|Time 208( 195+13 )ms|Inlined 6Y 1N|IR 400/ 564|CodeSize 1792|Addr 0x7fce7fa63510|Src n/a
[engine] opt done JsonLiteral class>>FALSE |AST 10|Tier 2|Time 26( 24+2 )ms|Inlined 0Y 0N|IR 21/ 27|CodeSize 230|Addr 0x7fce7fa64610|Src n/a
[engine] opt done JsonParser>>readTrue |AST 78|Tier 2|Time 974( 854+120 )ms|Inlined 47Y 4N|IR 2428/ 2562|CodeSize 7014|Addr 0x7fce7fa65410|Src n/a
[engine] opt done JsonObject>>at: |AST 60|Tier 2|Time 264( 217+47 )ms|Inlined 10Y 0N|IR 543/ 617|CodeSize 1867|Addr 0x7fce7fa6bf10|Src n/a
[engine] opt done JsonParser>>readFalse |AST 93|Tier 2|Time 1233( 970+263 )ms|Inlined 58Y 5N|IR 3063/ 3163|CodeSize 8297|Addr 0x7fce7fa6e890|Src n/a
[engine] opt done Json class>>RapBenchmarkMinified |AST 8|Tier 2|Time 28( 27+2 )ms|Inlined 0Y 0N|IR 17/ 18|CodeSize 179|Addr 0x7fce7fa75a90|Src n/a
[engine] opt done JsonParser class>>with: |AST 31|Tier 2|Time 96( 90+6 )ms|Inlined 2Y 0N|IR 186/ 374|CodeSize 1299|Addr 0x7fce7fa75e90|Src n/a
[engine] opt done JsonParser>>parse |AST 82|Tier 2|Time 541( 433+108 )ms|Inlined 23Y 2N|IR 1821/ 3794|CodeSize 11628|Addr 0x7fce7fa77610|Src n/a
[engine] opt done Json>>benchmark |AST 44|Tier 2|Time 779( 524+255 )ms|Inlined 28Y 2N|IR 1528/ 3275|CodeSize 10463|Addr 0x7fce7fa7cc10|Src n/a
[engine] opt done JsonArray>>size |AST 20|Tier 2|Time 55( 52+4 )ms|Inlined 1Y 0N|IR 46/ 128|CodeSize 536|Addr 0x7fce7fa81d10|Src n/a
[engine] opt done Json>>verifyResult: |AST 126|Tier 2|Time 720( 586+134 )ms|Inlined 35Y 0N|IR 1534/ 1269|CodeSize 3432|Addr 0x7fce7fa83310|Src n/a
[engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 1690( 969+721 )ms|Inlined 65Y 2N|IR 3151/ 6183|CodeSize 19956|Addr 0x7fce7fa88410|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 283( 257+27 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7fce7fa9e590|Src n/a
[engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 288( 231+56 )ms|Inlined 3Y 1N|IR 474/ 1460|CodeSize 6556|Addr 0x7fce7faa5c10|Src n/a
[engine] Truffle runtime statistics for engine 2
Compilations : 118
Success : 99
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 19
Invalidated : 1
null : 1
Queues : 353
Dequeues : 254
Target inlined into only caller : 250
Split call node : 3
null : 1
Splits : 459
Compilation Accuracy : 0.991525
Queue Accuracy : 0.280453
Compilation Utilization : 0.522385
Remaining Compilation Queue : 0
Time to queue : count= 353, sum= 1147013, min= 129, average= 3249.33, max= 68607 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 118, sum= 317944, min= 0, average= 2694.44, max= 8265 (milliseconds), maxTarget=String>>compareWith:collated:
Time for compilation : count= 99, sum= 35888, min= 26, average= 362.51, max= 2750 (milliseconds), maxTarget=JsonParser>>readObject
Truffle Tier : count= 99, sum= 29226, min= 23, average= 295.22, max= 2347 (milliseconds), maxTarget=JsonParser>>readObject
Graal Tier : count= 99, sum= 4563, min= 1, average= 46.10, max= 539 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Code Installation : count= 99, sum= 2098, min= 1, average= 21.19, max= 390 (milliseconds), maxTarget=JsonParser>>readObjectKeyValuePair:
Truffle node count : count= 99, sum= 92401, min= 12, average= 933.34, max= 7931, maxTarget=JsonParser>>readObjectKeyValuePair:
Trivial : count= 99, sum= 34293, min= 4, average= 346.39, max= 2969, maxTarget=JsonParser>>readObjectKeyValuePair:
Non Trivial : count= 99, sum= 58108, min= 8, average= 586.95, max= 4962, maxTarget=JsonParser>>readObjectKeyValuePair:
Monomorphic : count= 99, sum= 57546, min= 8, average= 581.27, max= 4919, maxTarget=JsonParser>>readObjectKeyValuePair:
Polymorphic : count= 99, sum= 562, min= 0, average= 5.68, max= 43, maxTarget=JsonParser>>readObjectKeyValuePair:
Megamorphic : count= 99, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=SequenceableCollection>>atAllPut:
Truffle call count : count= 99, sum= 1209, min= 0, average= 12.21, max= 102, maxTarget=JsonParser>>readValue
Indirect : count= 99, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=SequenceableCollection>>atAllPut:
Direct : count= 99, sum= 1209, min= 0, average= 12.21, max= 102, maxTarget=JsonParser>>readValue
Dispatched : count= 99, sum= 96, min= 0, average= 0.97, max= 28, maxTarget=JsonParser>>readValue
Inlined : count= 99, sum= 1113, min= 0, average= 11.24, max= 93, maxTarget=JsonParser>>readObjectKeyValuePair:
---------- :
Cloned : count= 99, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=SequenceableCollection>>atAllPut:
Not Cloned : count= 99, sum= 1209, min= 0, average= 12.21, max= 102, maxTarget=JsonParser>>readValue
Truffle loops : count= 99, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=SequenceableCollection>>atAllPut:
Graal node count :
After Truffle Tier : count= 99, sum= 69602, min= 17, average= 703.05, max= 5951, maxTarget=JsonParser>>readObjectKeyValuePair:
After Graal Tier : count= 99, sum= 104548, min= 18, average= 1056.04, max= 9649, maxTarget=JsonParser>>readObjectKeyValuePair:
Graal compilation result :
Code size : count= 99, sum= 329608, min= 179, average= 3329.37, max= 36489, maxTarget=JsonParser>>readObjectKeyValuePair:
Total frame size : count= 99, sum= 8000, min= 32, average= 80.81, max= 592, maxTarget=JsonParser>>readObjectKeyValuePair:
Exception handlers : count= 99, sum= 38, min= 0, average= 0.38, max= 24, maxTarget=JsonParser>>readValue
Infopoints : count= 99, sum= 3625, min= 4, average= 36.62, max= 303, maxTarget=JsonParser>>readValue
CALL : count= 99, sum= 2751, min= 4, average= 27.79, max= 228, maxTarget=JsonParser>>readValue
IMPLICIT_EXCEPTION : count= 99, sum= 828, min= 0, average= 8.36, max= 74, maxTarget=JsonParser>>readValue
SAFEPOINT : count= 99, sum= 46, min= 0, average= 0.46, max= 8, maxTarget=JsonParser>>readObjectKeyValuePair:
Marks : count= 99, sum= 805, min= 7, average= 8.13, max= 32, maxTarget=JsonParser>>readValue
Data references : count= 99, sum= 4056, min= 2, average= 40.97, max= 303, maxTarget=JsonParser>>readValue
Raw
5d99b29f-List.trace.log
# List (iterations: 250, problem size: 1500) on Thu May 27 21:41:49 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-779de014> |AST 75|Tier 2|Time 135( 96+39 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e74ea590|Src n/a
[engine] opt done List>>isShorter:than: <split-577f9109> |AST 75|Tier 2|Time 183( 144+39 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e74ebc90|Src n/a
[engine] opt done List>>isShorter:than: <split-757529a4> |AST 75|Tier 2|Time 135( 97+38 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e74eb110|Src n/a
[engine] opt done List>>isShorter:than: <split-796d3c9f> |AST 72|Tier 2|Time 84( 75+9 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e74fe090|Src n/a
[engine] opt done List>>isShorter:than: <split-3aefae67> |AST 75|Tier 2|Time 91( 80+11 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7504190|Src n/a
[engine] opt done List>>isShorter:than: <split-2e1792e7> |AST 75|Tier 2|Time 94( 82+12 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7507590|Src n/a
[engine] opt done List>>isShorter:than: <split-29a23c3d> |AST 75|Tier 2|Time 70( 59+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e750a290|Src n/a
[engine] opt done List>>isShorter:than: <split-69c6161d> |AST 75|Tier 2|Time 71( 61+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e750b090|Src n/a
[engine] opt done List>>isShorter:than: <split-6bff19ff> |AST 75|Tier 2|Time 70( 58+12 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e750bf10|Src n/a
[engine] opt done List>>isShorter:than: <split-41e1455d> |AST 72|Tier 2|Time 66( 58+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e750d910|Src n/a
[engine] opt done List>>isShorter:than: <split-1450078a> |AST 75|Tier 2|Time 69( 59+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e750e610|Src n/a
[engine] opt done List>>isShorter:than: <split-4d6f197e> |AST 75|Tier 2|Time 68( 57+11 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e750f610|Src n/a
[engine] opt done List>>isShorter:than: <split-41477a6d> |AST 75|Tier 2|Time 68( 58+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7512e90|Src n/a
[engine] opt done List>>isShorter:than: <split-a619c2> |AST 72|Tier 2|Time 64( 55+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e7514890|Src n/a
[engine] opt done List>>isShorter:than: <split-272a179c> |AST 72|Tier 2|Time 65( 55+10 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e7515210|Src n/a
[engine] opt done List>>isShorter:than: <split-534ca02b> |AST 75|Tier 2|Time 71( 60+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7519c10|Src n/a
[engine] opt done List>>isShorter:than: <split-6fe46b62> |AST 72|Tier 2|Time 67( 58+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e751ae90|Src n/a
[engine] opt done List>>isShorter:than: <split-61e45f87> |AST 72|Tier 2|Time 64( 56+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e751b910|Src n/a
[engine] opt done List>>isShorter:than: <split-3b0ca5e1> |AST 72|Tier 2|Time 65( 56+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e7522210|Src n/a
[engine] opt done List>>isShorter:than: <split-5bb3131b> |AST 72|Tier 2|Time 65( 57+9 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e7522e90|Src n/a
[engine] opt done List>>isShorter:than: <split-54dcbb9f> |AST 72|Tier 2|Time 64( 56+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e7523810|Src n/a
[engine] opt done List>>isShorter:than: <split-69eb86b4> |AST 72|Tier 2|Time 68( 59+9 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e7526f10|Src n/a
[engine] opt done List>>isShorter:than: <split-516ebdf8> |AST 75|Tier 2|Time 67( 57+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7527890|Src n/a
[engine] opt done List>>isShorter:than: <split-bcb09a6> |AST 75|Tier 2|Time 68( 57+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7528410|Src n/a
[engine] opt done List>>isShorter:than: <split-7c2a69b4> |AST 72|Tier 2|Time 63( 54+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e7529190|Src n/a
[engine] opt done List>>isShorter:than: <split-7c2327fa> |AST 72|Tier 2|Time 65( 56+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e7529e10|Src n/a
[engine] opt done List>>isShorter:than: <split-375b5b7f> |AST 72|Tier 2|Time 65( 56+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e752a890|Src n/a
[engine] opt done List>>isShorter:than: <split-1813f3e9> |AST 72|Tier 2|Time 65( 56+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e752b210|Src n/a
[engine] opt done List>>isShorter:than: <split-4e558728> |AST 72|Tier 2|Time 90( 82+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e7533a10|Src n/a
[engine] opt done List>>isShorter:than: <split-c68a5f8> |AST 75|Tier 2|Time 93( 82+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7534390|Src n/a
[engine] opt done List>>isShorter:than: <split-6ef7623> |AST 75|Tier 2|Time 67( 57+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7536f10|Src n/a
[engine] opt done List>>isShorter:than: <split-7ed9ae94> |AST 72|Tier 2|Time 65( 56+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e7537e90|Src n/a
[engine] opt done List>>isShorter:than: <split-66908383> |AST 75|Tier 2|Time 67( 57+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7538910|Src n/a
[engine] opt done List>>isShorter:than: <split-4463d9d3> |AST 72|Tier 2|Time 63( 55+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e753b890|Src n/a
[engine] opt done List>>isShorter:than: <split-3068b369> |AST 72|Tier 2|Time 63( 54+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e753c210|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 0x7fc3e753cb90|Src n/a
[engine] opt done List>>isShorter:than: <split-5491f68b> |AST 75|Tier 2|Time 66( 56+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e753e810|Src n/a
[engine] opt done List>>isShorter:than: <split-736ac09a> |AST 75|Tier 2|Time 78( 68+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e753f390|Src n/a
[engine] opt done List>>isShorter:than: <split-1ec7d8b3> |AST 75|Tier 2|Time 78( 68+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7540110|Src n/a
[engine] opt done List>>isShorter:than: <split-74fef3f7> |AST 72|Tier 2|Time 72( 65+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e7541510|Src n/a
[engine] opt done List>>isShorter:than: <split-2a037324> |AST 72|Tier 2|Time 64( 56+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e7542490|Src n/a
[engine] opt done List>>isShorter:than: <split-648ee871> |AST 75|Tier 2|Time 67( 57+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7543110|Src n/a
[engine] opt done List>>isShorter:than: <split-585c13de> |AST 75|Tier 2|Time 64( 54+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7543c90|Src n/a
[engine] opt done List>>isShorter:than: <split-5c41d037> |AST 75|Tier 2|Time 66( 55+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7545a10|Src n/a
[engine] opt done List>>isShorter:than: <split-3eb631b8> |AST 75|Tier 2|Time 66( 56+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7546590|Src n/a
[engine] opt done List>>isShorter:than: <split-5eccd3b9> |AST 75|Tier 2|Time 64( 54+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7547110|Src n/a
[engine] opt done List>>isShorter:than: <split-2bc12da> |AST 75|Tier 2|Time 65( 55+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7547c90|Src n/a
[engine] opt done List>>isShorter:than: <split-3122b117> |AST 75|Tier 2|Time 66( 56+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7548810|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 0x7fc3e754ab90|Src n/a
[engine] opt done List>>isShorter:than: <split-13d186db> |AST 72|Tier 2|Time 65( 56+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e754b510|Src n/a
[engine] opt done List>>isShorter:than: <split-6f6962ba> |AST 72|Tier 2|Time 64( 55+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e754bf90|Src n/a
[engine] opt done List>>isShorter:than: <split-4565a70a> |AST 72|Tier 2|Time 61( 53+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e754ca10|Src n/a
[engine] opt done List>>isShorter:than: <split-7c9b78e3> |AST 75|Tier 2|Time 65( 55+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e754d890|Src n/a
[engine] opt done List>>isShorter:than: <split-6ecd665> |AST 72|Tier 2|Time 62( 53+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e754e410|Src n/a
[engine] opt done List>>isShorter:than: <split-45394b31> |AST 72|Tier 2|Time 60( 52+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e754f210|Src n/a
[engine] opt done List>>isShorter:than: <split-4d8539de> |AST 75|Tier 2|Time 66( 56+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e754fb90|Src n/a
[engine] opt done List>>isShorter:than: <split-3eba57a7> |AST 75|Tier 2|Time 67( 56+11 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7550710|Src n/a
[engine] opt done List>>isShorter:than: <split-67207d8a> |AST 75|Tier 2|Time 67( 57+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7553810|Src n/a
[engine] opt done List>>isShorter:than: <split-4d847d32> |AST 75|Tier 2|Time 67( 56+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7555510|Src n/a
[engine] opt done List>>isShorter:than: <split-a0a9fa5> |AST 72|Tier 2|Time 63( 54+10 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e7557710|Src n/a
[engine] opt done List>>isShorter:than: <split-2234078> |AST 75|Tier 2|Time 67( 57+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7558b90|Src n/a
[engine] opt done List>>isShorter:than: <split-6d367020> |AST 72|Tier 2|Time 64( 56+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e7559710|Src n/a
[engine] opt done List>>isShorter:than: <split-72458efc> |AST 72|Tier 2|Time 62( 54+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e755a590|Src n/a
[engine] opt done List>>isShorter:than: <split-36bc415e> |AST 72|Tier 2|Time 87( 78+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e755af10|Src n/a
[engine] opt done List>>isShorter:than: <split-5ec77191> |AST 75|Tier 2|Time 94( 84+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7560390|Src n/a
[engine] opt done List>>isShorter:than: <split-6a74d228> |AST 72|Tier 2|Time 66( 57+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e7561290|Src n/a
[engine] opt done List>>isShorter:than: <split-349d0836> |AST 72|Tier 2|Time 74( 66+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e7563410|Src n/a
[engine] opt done List>>isShorter:than: <split-6a714237> |AST 72|Tier 2|Time 72( 63+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e7564190|Src n/a
[engine] opt done List>>isShorter:than: <split-3e134896> |AST 72|Tier 2|Time 61( 53+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e7567b10|Src n/a
[engine] opt done List>>isShorter:than: <split-72ba28ee> |AST 72|Tier 2|Time 61( 53+8 )ms|Inlined 0Y 0N|IR 135/ 202|CodeSize 667|Addr 0x7fc3e7568490|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 0x7fc3e7568e10|Src n/a
[engine] opt done List>>isShorter:than: <split-6719a5b8> |AST 75|Tier 2|Time 62( 53+10 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e7569790|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-64e1dd11> |AST 135|Tier 2|Time 1143( 914+229 )ms|Inlined 17Y 8N|IR 1996/ 3085|CodeSize 11087|Addr 0x7fc3e7572990|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-5c089b2f> |AST 135|Tier 2|Time 1307( 909+398 )ms|Inlined 27Y 15N|IR 3254/ 4815|CodeSize 18120|Addr 0x7fc3e757e610|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: |AST 135|Tier 2|Time 1931(1237+693 )ms|Inlined 33Y 32N|IR 4815/ 7925|CodeSize 31950|Addr 0x7fc3e7595910|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-6999cd39> |AST 135|Tier 2|Time 528( 362+166 )ms|Inlined 15Y 5N|IR 1640/ 2267|CodeSize 7699|Addr 0x7fc3e75b8e10|Src n/a
[engine] opt done List>>isShorter:than: <split-4b6ac111> |AST 75|Tier 2|Time 194( 50+144 )ms|Inlined 0Y 0N|IR 200/ 234|CodeSize 847|Addr 0x7fc3e75c1710|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-69ce2f62> |AST 28|Tier 2|Time 74( 63+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e75c2290|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 0x7fc3e75c2f90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-5f462e3b> |AST 135|Tier 2|Time 1889(1036+853 )ms|Inlined 23Y 33N|IR 3808/ 6974|CodeSize 29527|Addr 0x7fc3e75c5990|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-6f012914> |AST 135|Tier 2|Time 2822(1385+1437)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54078|Addr 0x7fc3e75e7610|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-585ac855> |AST 135|Tier 2|Time 2508(1370+1138)ms|Inlined 31Y 49N|IR 5353/ 9864|CodeSize 42431|Addr 0x7fc3e7620910|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-14bae047> |AST 135|Tier 2|Time 1993(1191+802 )ms|Inlined 31Y 29N|IR 4442/ 7378|CodeSize 29415|Addr 0x7fc3e764b790|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-3b152928> |AST 135|Tier 2|Time 2921(1331+1590)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54078|Addr 0x7fc3e767ec10|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-56781d96> |AST 135|Tier 2|Time 2929(1538+1390)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54078|Addr 0x7fc3e76b6d90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-5173200b> |AST 135|Tier 2|Time 2793(1368+1426)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54078|Addr 0x7fc3e76eef10|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-5f78de22> |AST 135|Tier 2|Time 677( 625+53 )ms|Inlined 7Y 1N|IR 738/ 1037|CodeSize 2843|Addr 0x7fc3e7727390|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-5bb8f9e2> |AST 135|Tier 2|Time 1424( 915+508 )ms|Inlined 13Y 18N|IR 2196/ 3868|CodeSize 16385|Addr 0x7fc3e772a290|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 0x7fc3e773ac90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-6a933be2> |AST 135|Tier 2|Time 1745(1121+624 )ms|Inlined 23Y 33N|IR 3808/ 6868|CodeSize 29042|Addr 0x7fc3e773bd10|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-60baef24> |AST 28|Tier 2|Time 72( 61+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e7759e90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-732bb66d> |AST 135|Tier 2|Time 2788(1378+1409)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54078|Addr 0x7fc3e775da90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-d02f8d> |AST 135|Tier 2|Time 2771(1362+1409)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54078|Addr 0x7fc3e7795c10|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-378bd86d> |AST 28|Tier 2|Time 72( 62+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e77ce990|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-2189e7a7> |AST 28|Tier 2|Time 72( 61+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e77cf690|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-69b2f8e5> |AST 28|Tier 2|Time 73( 62+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e77d0710|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-61533ae> |AST 135|Tier 2|Time 2768(1545+1222)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54078|Addr 0x7fc3e77d1410|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-58065f0c> |AST 28|Tier 2|Time 165( 61+103 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e7809590|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-25c5e994> |AST 135|Tier 2|Time 1074( 648+426 )ms|Inlined 15Y 17N|IR 2263/ 3971|CodeSize 16061|Addr 0x7fc3e780a290|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-3605c4d3> |AST 135|Tier 2|Time 247( 186+61 )ms|Inlined 9Y 0N|IR 841/ 897|CodeSize 2221|Addr 0x7fc3e781a790|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-599f571f> |AST 28|Tier 2|Time 75( 64+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e781d710|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-3d7fa3ae> |AST 135|Tier 2|Time 1309( 982+327 )ms|Inlined 13Y 18N|IR 2196/ 3868|CodeSize 16385|Addr 0x7fc3e781f310|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-77128dab> |AST 135|Tier 2|Time 653( 593+60 )ms|Inlined 7Y 1N|IR 738/ 1213|CodeSize 3540|Addr 0x7fc3e782fd10|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-187eb9a8> |AST 135|Tier 2|Time 1350(1024+325 )ms|Inlined 13Y 18N|IR 2196/ 3868|CodeSize 16385|Addr 0x7fc3e7835090|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-726a6b94> |AST 28|Tier 2|Time 71( 60+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e7846090|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-312afbc7> |AST 135|Tier 2|Time 2728(1337+1391)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54078|Addr 0x7fc3e7847890|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-6569dded> |AST 28|Tier 2|Time 75( 64+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e787fa10|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-7b60c3e> |AST 135|Tier 2|Time 2724(1332+1392)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54078|Addr 0x7fc3e7880a10|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-466d49f0> |AST 28|Tier 2|Time 74( 63+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e78b8b90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-710d7aff> |AST 28|Tier 2|Time 79( 68+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e78b9890|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-5395ea39> |AST 28|Tier 2|Time 78( 67+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e78ba590|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-1517f633> |AST 28|Tier 2|Time 78( 67+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e78bb290|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-4fe01803> |AST 28|Tier 2|Time 79( 68+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e78bbf90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-65327f5> |AST 28|Tier 2|Time 78( 68+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e78bd210|Src n/a
[engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 743( 730+13 )ms|Inlined 1Y 1N|IR 136/ 441|CodeSize 1755|Addr 0x7fc3e78bff10|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-34e951c0> |AST 28|Tier 2|Time 73( 62+11 )ms|Inlined 1Y 0N|IR 172/ 257|CodeSize 697|Addr 0x7fc3e78c1110|Src n/a
[engine] opt done List>>verifyResult: |AST 15|Tier 2|Time 27( 26+2 )ms|Inlined 0Y 0N|IR 25/ 26|CodeSize 213|Addr 0x7fc3e78c1e10|Src n/a
[engine] opt done List>>isShorter:than: <split-30feffc> |AST 72|Tier 2|Time 58( 49+9 )ms|Inlined 0Y 0N|IR 138/ 212|CodeSize 749|Addr 0x7fc3e78c2210|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-2d7e1102> |AST 135|Tier 2|Time 2763(1336+1427)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54078|Addr 0x7fc3e78c3190|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-20637b5a> |AST 135|Tier 2|Time 2917(1517+1400)ms|Inlined 41Y 64N|IR 7013/12532|CodeSize 54078|Addr 0x7fc3e78fb790|Src n/a
[engine] opt done ListElement class>>new: |AST 31|Tier 2|Time 71( 67+4 )ms|Inlined 2Y 0N|IR 40/ 102|CodeSize 441|Addr 0x7fc3e7933c90|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 0x7fc3e7934310|Src n/a
[engine] opt done List>>makeList: |AST 76|Tier 2|Time 388( 340+49 )ms|Inlined 14Y 1N|IR 378/ 1017|CodeSize 3845|Addr 0x7fc3e7934a90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-28cb9120> |AST 135|Tier 2|Time 2750(1369+1381)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54682|Addr 0x7fc3e7938610|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-6ad11a56> |AST 130|Tier 2|Time 1654( 893+761 )ms|Inlined 23Y 33N|IR 3739/ 6930|CodeSize 29637|Addr 0x7fc3e7972b90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-522b2631> |AST 135|Tier 2|Time 2635(1283+1352)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54682|Addr 0x7fc3e7992690|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-63429932> |AST 135|Tier 2|Time 2720(1295+1425)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54634|Addr 0x7fc3e79cd490|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-18fdb6cf> |AST 135|Tier 2|Time 2873(1482+1391)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54682|Addr 0x7fc3e7a07e90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-45f24169> |AST 130|Tier 2|Time 2728(1331+1397)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7fc3e7a43790|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-6ad5923a> |AST 135|Tier 2|Time 2890(1319+1571)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54634|Addr 0x7fc3e7a87b10|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-43b0ade> |AST 130|Tier 2|Time 2748(1358+1391)ms|Inlined 41Y 64N|IR 6948/12652|CodeSize 54600|Addr 0x7fc3e7ac0b90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-15723761> |AST 135|Tier 2|Time 2709(1338+1371)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54682|Addr 0x7fc3e7af9f90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-3fbfa96> |AST 135|Tier 2|Time 2719(1328+1391)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54682|Addr 0x7fc3e7b32610|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-2adddc06> |AST 130|Tier 2|Time 2713(1326+1387)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7fc3e7b6ac90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-301d8120> |AST 135|Tier 2|Time 2725(1482+1243)ms|Inlined 41Y 64N|IR 7013/12624|CodeSize 54634|Addr 0x7fc3e7ba3390|Src n/a
[engine] opt done ListElement>>length |AST 43|Tier 2|Time 257( 240+18 )ms|Inlined 2Y 1N|IR 321/ 517|CodeSize 1799|Addr 0x7fc3e7bdba10|Src n/a
[engine] opt done List>>benchmark |AST 76|Tier 2|Time 1461(1130+330 )ms|Inlined 60Y 7N|IR 2118/ 4624|CodeSize 16337|Addr 0x7fc3e7be1c90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-d1d7998> |AST 130|Tier 2|Time 2710(1339+1371)ms|Inlined 41Y 64N|IR 6948/12652|CodeSize 54600|Addr 0x7fc3e7bf6590|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-6c31818> |AST 135|Tier 2|Time 2713(1338+1375)ms|Inlined 41Y 64N|IR 7013/12657|CodeSize 54688|Addr 0x7fc3e7c2ea90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-7b44b63d> |AST 130|Tier 2|Time 1065(1022+44 )ms|Inlined 3Y 3N|IR 440/ 1012|CodeSize 3262|Addr 0x7fc3e7c67990|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-4a699efa> |AST 130|Tier 2|Time 2758(1341+1417)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7fc3e7c6a610|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-38499e48> |AST 130|Tier 2|Time 2772(1524+1248)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7fc3e7ca2d10|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-17ae7628> |AST 130|Tier 2|Time 2675(1319+1356)ms|Inlined 41Y 64N|IR 6948/12652|CodeSize 54600|Addr 0x7fc3e7cdb410|Src n/a
[engine] opt done ListElement>>length <split-6d467c87> |AST 38|Tier 2|Time 86( 70+17 )ms|Inlined 2Y 1N|IR 267/ 500|CodeSize 1653|Addr 0x7fc3e7d13c10|Src n/a
[engine] opt done ListElement>>length <split-4917d36b> |AST 43|Tier 2|Time 92( 71+21 )ms|Inlined 2Y 1N|IR 321/ 593|CodeSize 2132|Addr 0x7fc3e7d15010|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-6579c3d9> |AST 130|Tier 2|Time 2699(1306+1392)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7fc3e7d16b90|Src n/a
[engine] opt done List>>talkWithX:withY:withZ: <split-66434cc8> |AST 130|Tier 2|Time 2661(1273+1388)ms|Inlined 41Y 64N|IR 6948/12619|CodeSize 54594|Addr 0x7fc3e7d4f290|Src n/a
[engine] opt done String class>>new: |AST 51|Tier 2|Time 168( 150+19 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7fc3e7d8e910|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 0x7fc3e7d91010|Src n/a
[engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 288( 248+39 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7fc3e7d98790|Src n/a
[engine] Truffle runtime statistics for engine 2
Compilations : 153
Success : 150
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 3
Invalidated : 0
Queues : 210
Dequeues : 60
Target inlined into only caller : 60
Splits : 353
Compilation Accuracy : 1.000000
Queue Accuracy : 0.714286
Compilation Utilization : 0.822953
Remaining Compilation Queue : 0
Time to queue : count= 210, sum= 959239, min= 55, average= 4567.81, max= 137571 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 153, sum= 1008163, min= 0, average= 6589.30, max= 32577 (milliseconds), maxTarget=ListElement>>length
Time for compilation : count= 150, sum= 113565, min= 27, average= 757.10, max= 2929 (milliseconds), maxTarget=List>>talkWithX:withY:withZ:
Truffle Tier : count= 150, sum= 63801, min= 23, average= 425.34, max= 1545 (milliseconds), maxTarget=List>>talkWithX:withY:withZ:
Graal Tier : count= 150, sum= 27030, min= 1, average= 180.21, max= 824 (milliseconds), maxTarget=List>>talkWithX:withY:withZ:
Code Installation : count= 150, sum= 22733, min= 1, average= 151.56, max= 770 (milliseconds), maxTarget=List>>talkWithX:withY:withZ:
Truffle node count : count= 150, sum= 257224, min= 17, average= 1714.83, max= 6741, maxTarget=List>>talkWithX:withY:withZ:
Trivial : count= 150, sum= 89357, min= 6, average= 595.71, max= 2331, maxTarget=List>>talkWithX:withY:withZ:
Non Trivial : count= 150, sum= 167867, min= 11, average= 1119.11, max= 4410, maxTarget=List>>talkWithX:withY:withZ:
Monomorphic : count= 150, sum= 162975, min= 11, average= 1086.50, max= 4284, maxTarget=List>>talkWithX:withY:withZ:
Polymorphic : count= 150, sum= 4892, min= 0, average= 32.61, max= 126, maxTarget=List>>talkWithX:withY:withZ:
Megamorphic : count= 150, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=List>>isShorter:than:
Truffle call count : count= 150, sum= 3786, min= 0, average= 25.24, max= 105, maxTarget=List>>talkWithX:withY:withZ:
Indirect : count= 150, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=List>>isShorter:than:
Direct : count= 150, sum= 3786, min= 0, average= 25.24, max= 105, maxTarget=List>>talkWithX:withY:withZ:
Dispatched : count= 150, sum= 2184, min= 0, average= 14.56, max= 64, maxTarget=List>>talkWithX:withY:withZ:
Inlined : count= 150, sum= 1602, min= 0, average= 10.68, max= 60, maxTarget=List>>benchmark
---------- :
Cloned : count= 150, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=List>>isShorter:than:
Not Cloned : count= 150, sum= 3786, min= 0, average= 25.24, max= 105, maxTarget=List>>talkWithX:withY:withZ:
Truffle loops : count= 150, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=List>>isShorter:than:
Graal node count :
After Truffle Tier : count= 150, sum= 267496, min= 25, average= 1783.31, max= 7013, maxTarget=List>>talkWithX:withY:withZ:
After Graal Tier : count= 150, sum= 471758, min= 26, average= 3145.05, max= 12657, maxTarget=List>>talkWithX:withY:withZ:
Graal compilation result :
Code size : count= 150, sum= 1990510, min= 213, average= 13270.07, max= 54688, maxTarget=List>>talkWithX:withY:withZ:
Total frame size : count= 150, sum= 70592, min= 32, average= 470.61, max= 1904, maxTarget=List>>talkWithX:withY:withZ:
Exception handlers : count= 150, sum= 2198, min= 0, average= 14.65, max= 64, maxTarget=List>>talkWithX:withY:withZ:
Infopoints : count= 150, sum= 29146, min= 4, average= 194.31, max= 793, maxTarget=List>>talkWithX:withY:withZ:
CALL : count= 150, sum= 20912, min= 4, average= 139.41, max= 569, maxTarget=List>>talkWithX:withY:withZ:
IMPLICIT_EXCEPTION : count= 150, sum= 7364, min= 0, average= 49.09, max= 203, maxTarget=List>>talkWithX:withY:withZ:
SAFEPOINT : count= 150, sum= 870, min= 0, average= 5.80, max= 21, maxTarget=List>>talkWithX:withY:withZ:
Marks : count= 150, sum= 4218, min= 7, average= 28.12, max= 92, maxTarget=List>>talkWithX:withY:withZ:
Data references : count= 150, sum= 22509, min= 2, average= 150.06, max= 591, maxTarget=List>>talkWithX:withY:withZ:
Raw
5d99b29f-Mandelbrot.trace.log
# Mandelbrot (iterations: 250, problem size: 500) on Thu May 27 21:46: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/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 111( 97+14 )ms|Inlined 0Y 0N|IR 76/ 112|CodeSize 461|Addr 0x7f8def904290|Src n/a
[engine] opt done Mandelbrot>>mandelbrot: |AST 500|Tier 2|Time 393( 272+121 )ms|Inlined 2Y 0N|IR 550/ 1809|CodeSize 13398|Addr 0x7f8def928a90|Src n/a
[engine] opt done String class>>new: |AST 51|Tier 2|Time 180( 158+21 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f8def94ff10|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 249( 227+22 )ms|Inlined 4Y 1N|IR 361/ 419|CodeSize 1240|Addr 0x7f8def956f90|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.008163
Remaining Compilation Queue : 0
Time to queue : count= 6, sum= 431655, min= 162, average= 71942.57, max= 116578 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 6, sum= 51, min= 1, average= 8.56, max= 17 (milliseconds), maxTarget=String class>>new:
Time for compilation : count= 4, sum= 952, min= 123, average= 238.05, max= 395 (milliseconds), maxTarget=Mandelbrot>>mandelbrot:
Truffle Tier : count= 4, sum= 753, min= 96, average= 188.42, max= 271 (milliseconds), maxTarget=Mandelbrot>>mandelbrot:
Graal Tier : count= 4, sum= 126, min= 10, average= 31.72, max= 84 (milliseconds), maxTarget=Mandelbrot>>mandelbrot:
Code Installation : count= 4, sum= 71, min= 6, average= 17.91, max= 39 (milliseconds), maxTarget=Mandelbrot>>mandelbrot:
Truffle node count : count= 5, sum= 2317, min= 40, average= 463.40, max= 892, maxTarget=Mandelbrot>>mandelbrot:
Trivial : count= 5, sum= 897, min= 15, average= 179.40, max= 342, maxTarget=Mandelbrot>>mandelbrot:
Non Trivial : count= 5, sum= 1420, min= 25, average= 284.00, max= 550, maxTarget=Mandelbrot>>mandelbrot:
Monomorphic : count= 5, sum= 1391, min= 25, average= 278.20, max= 550, maxTarget=Mandelbrot>>mandelbrot:
Polymorphic : count= 5, sum= 29, min= 0, average= 5.80, max= 11, maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Megamorphic : count= 5, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Integer>><<
Truffle call count : count= 5, sum= 14, min= 0, average= 2.80, max= 5, maxTarget=SmallInteger>>printString
Indirect : count= 5, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Integer>><<
Direct : count= 5, sum= 14, min= 0, average= 2.80, max= 5, maxTarget=SmallInteger>>printString
Dispatched : count= 5, sum= 3, min= 0, average= 0.60, max= 1, maxTarget=String class>>new:
Inlined : count= 5, sum= 11, min= 0, average= 2.20, max= 4, maxTarget=SmallInteger>>printString
---------- :
Cloned : count= 5, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Integer>><<
Not Cloned : count= 5, sum= 14, min= 0, average= 2.80, max= 5, maxTarget=SmallInteger>>printString
Truffle loops : count= 5, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=Integer>><<
Graal node count :
After Truffle Tier : count= 5, sum= 1674, min= 76, average= 334.80, 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:
Raw
5d99b29f-NBody.trace.log
# NBody (iterations: 250, problem size: 250000) on Thu May 27 21:45:53 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>>vx: |AST 11|Tier 2|Time 133( 111+22 )ms|Inlined 0Y 0N|IR 76/ 91|CodeSize 286|Addr 0x7fc18790d110|Src n/a
[engine] opt done Body>>vy: |AST 11|Tier 2|Time 127( 106+22 )ms|Inlined 0Y 0N|IR 76/ 91|CodeSize 286|Addr 0x7fc18790ca90|Src n/a
[engine] opt done Body>>vz: |AST 11|Tier 2|Time 126( 102+24 )ms|Inlined 0Y 0N|IR 76/ 91|CodeSize 286|Addr 0x7fc18790d790|Src n/a
[engine] opt done NBodySystem>>advance: |AST 187|Tier 2|Time 165( 154+11 )ms|Inlined 3Y 0N|IR 310/ 304|CodeSize 658|Addr 0x7fc18792b290|Src n/a
[engine] opt done SequenceableCollection>>do: <split-14bae047> |AST 73|Tier 2|Time 267( 215+52 )ms|Inlined 4Y 0N|IR 493/ 1700|CodeSize 5618|Addr 0x7fc18793e310|Src n/a
[engine] opt done NBodySystem>>advance: |AST 816|Tier 2|Time 678( 573+105 )ms|Inlined 11Y 0N|IR 1341/ 2268|CodeSize 9276|Addr 0x7fc187956d10|Src n/a
[engine] opt done NBody>>innerBenchmarkLoop: |AST 95|Tier 2|Time 2859(1848+1010)ms|Inlined 98Y 1N|IR 6158/11947|CodeSize 55373|Addr 0x7fc187987490|Src n/a
[engine] opt done String class>>new: |AST 51|Tier 2|Time 166( 148+19 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7fc1879bd990|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 244( 220+24 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7fc1879c6910|Src n/a
[engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 273( 233+41 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7fc1879d5590|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.092455
Remaining Compilation Queue : 0
Time to queue : count= 14, sum= 174408, min= 90, average= 12457.76, max= 55392 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 11, sum= 242, min= 0, average= 22.06, max= 132 (milliseconds), maxTarget=NBodySystem>>advance:
Time for compilation : count= 10, sum= 5130, min= 150, average= 513.09, max= 2860 (milliseconds), maxTarget=NBody>>innerBenchmarkLoop:
Truffle Tier : count= 10, sum= 3709, min= 102, average= 370.94, max= 1848 (milliseconds), maxTarget=NBody>>innerBenchmarkLoop:
Graal Tier : count= 10, sum= 871, min= 6, average= 87.12, max= 665 (milliseconds), maxTarget=NBody>>innerBenchmarkLoop:
Code Installation : count= 10, sum= 550, min= 4, average= 55.03, max= 346 (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>>vz:
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>>vz:
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>>vz:
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>>vz:
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:
Raw
5d99b29f-Permute.trace.log
# Permute (iterations: 250, problem size: 1000) on Thu May 27 21:57:02 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 170( 151+19 )ms|Inlined 0Y 0N|IR 173/ 156|CodeSize 488|Addr 0x7f5b13914390|Src n/a
[engine] opt done Permute>>permute: |AST 138|Tier 2|Time 1024( 701+323 )ms|Inlined 20Y 8N|IR 2982/ 4177|CodeSize 20610|Addr 0x7f5b13942690|Src n/a
[engine] opt done SequenceableCollection>>atAllPut: |AST 72|Tier 2|Time 115( 99+16 )ms|Inlined 0Y 0N|IR 184/ 407|CodeSize 1641|Addr 0x7f5b13957c10|Src n/a
[engine] opt done Permute>>verifyResult: |AST 15|Tier 2|Time 35( 33+2 )ms|Inlined 0Y 0N|IR 25/ 26|CodeSize 216|Addr 0x7f5b13959b10|Src n/a
[engine] opt done ArrayedCollection class>>new:withAll: |AST 31|Tier 2|Time 133( 121+12 )ms|Inlined 1Y 0N|IR 237/ 289|CodeSize 977|Addr 0x7f5b1395e810|Src n/a
[engine] opt done Permute>>benchmark |AST 49|Tier 2|Time 1000( 738+262 )ms|Inlined 23Y 8N|IR 3024/ 2967|CodeSize 11974|Addr 0x7f5b1396c410|Src n/a
[engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 1080( 684+396 )ms|Inlined 25Y 8N|IR 3120/ 3754|CodeSize 15169|Addr 0x7f5b1397d310|Src n/a
[engine] opt done String class>>new: |AST 51|Tier 2|Time 189( 170+19 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f5b1399f810|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 253( 230+23 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7f5b139a3590|Src n/a
[engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 293( 253+40 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f5b139b1a10|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.076187
Remaining Compilation Queue : 0
Time to queue : count= 11, sum= 180310, min= 34, average= 16391.84, max= 56537 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 11, sum= 54, min= 0, average= 4.98, max= 17 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time for compilation : count= 10, sum= 4321, min= 36, average= 432.19, max= 1081 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Truffle Tier : count= 10, sum= 3177, min= 33, average= 317.80, max= 738 (milliseconds), maxTarget=Permute>>benchmark
Graal Tier : count= 10, sum= 729, min= 1, average= 72.92, max= 262 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Code Installation : count= 10, sum= 414, min= 1, average= 41.47, max= 134 (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= 59187, min= 216, average= 5918.70, 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:
Raw
5d99b29f-Queens.trace.log
# Queens (iterations: 250, problem size: 1000) on Thu May 27 22:04: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/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: |AST 77|Tier 2|Time 176( 151+24 )ms|Inlined 0Y 0N|IR 216/ 257|CodeSize 1117|Addr 0x7f0f83918590|Src n/a
[engine] opt done Queens>>row:column:put: |AST 83|Tier 2|Time 110( 97+12 )ms|Inlined 0Y 0N|IR 188/ 289|CodeSize 1130|Addr 0x7f0f83919010|Src n/a
[engine] opt done SequenceableCollection>>atAllPut: |AST 72|Tier 2|Time 129( 96+33 )ms|Inlined 0Y 0N|IR 252/ 717|CodeSize 2826|Addr 0x7f0f83931690|Src n/a
[engine] opt done ArrayedCollection class>>new:withAll: |AST 31|Tier 2|Time 151( 112+39 )ms|Inlined 1Y 0N|IR 302/ 682|CodeSize 2303|Addr 0x7f0f8394ae90|Src n/a
[engine] opt done Queens>>placeQueen: |AST 149|Tier 2|Time 754( 496+258 )ms|Inlined 11Y 1N|IR 2084/ 2683|CodeSize 14517|Addr 0x7f0f8394d690|Src n/a
[engine] opt done True>>and: |AST 17|Tier 2|Time 41( 39+2 )ms|Inlined 0Y 0N|IR 23/ 28|CodeSize 213|Addr 0x7f0f8395a610|Src n/a
[engine] opt done Queens>>verifyResult: |AST 9|Tier 2|Time 23( 22+2 )ms|Inlined 0Y 0N|IR 19/ 20|CodeSize 181|Addr 0x7f0f8395e590|Src n/a
[engine] opt done Queens>>queens |AST 100|Tier 2|Time 1154( 623+532 )ms|Inlined 20Y 1N|IR 2848/ 3478|CodeSize 16209|Addr 0x7f0f8396a590|Src n/a
[engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 713( 700+13 )ms|Inlined 1Y 1N|IR 138/ 441|CodeSize 1738|Addr 0x7f0f83975a10|Src n/a
[engine] opt done Queens>>benchmark |AST 68|Tier 2|Time 1380( 662+718 )ms|Inlined 22Y 1N|IR 2949/ 4831|CodeSize 23254|Addr 0x7f0f83977a90|Src n/a
[engine] opt done String class>>new: |AST 51|Tier 2|Time 174( 155+19 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f0f8398e310|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 244( 221+23 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7f0f83995610|Src n/a
[engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 280( 239+41 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f0f839a0410|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.107782
Remaining Compilation Queue : 0
Time to queue : count= 14, sum= 149935, min= 37, average= 10709.71, max= 47129 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 13, sum= 61, min= 0, average= 4.70, max= 18 (milliseconds), maxTarget=String class>>new:
Time for compilation : count= 12, sum= 5097, min= 25, average= 424.75, max= 1381 (milliseconds), maxTarget=Queens>>benchmark
Truffle Tier : count= 12, sum= 3371, min= 21, average= 280.95, max= 700 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Graal Tier : count= 12, sum= 1243, min= 1, average= 103.61, max= 538 (milliseconds), maxTarget=Queens>>benchmark
Code Installation : count= 12, sum= 482, min= 1, average= 40.19, 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= 66755, min= 181, average= 5562.92, max= 23254, 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= 13, sum= 796, min= 1, average= 61.23, max= 267, maxTarget=Queens>>benchmark
Raw
5d99b29f-Richards.trace.log
# Richards (iterations: 250, problem size: 100) on Thu May 27 21:53:17 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 159( 137+21 )ms|Inlined 0Y 0N|IR 125/ 98|CodeSize 353|Addr 0x7f6a4b902c10|Src n/a
[engine] opt done TaskState>>isWaitingWithPacket |AST 31|Tier 2|Time 107( 87+20 )ms|Inlined 0Y 0N|IR 84/ 101|CodeSize 362|Addr 0x7f6a4b902610|Src n/a
[engine] opt done Packet>>link: |AST 11|Tier 2|Time 44( 40+4 )ms|Inlined 0Y 0N|IR 61/ 181|CodeSize 476|Addr 0x7f6a4b910210|Src n/a
[engine] opt done Scheduler>>findTask: |AST 45|Tier 2|Time 105( 99+6 )ms|Inlined 0Y 0N|IR 70/ 131|CodeSize 564|Addr 0x7f6a4b918f90|Src n/a
[engine] opt done Packet>>identity: |AST 11|Tier 2|Time 33( 29+4 )ms|Inlined 0Y 0N|IR 74/ 88|CodeSize 273|Addr 0x7f6a4b91f890|Src n/a
[engine] opt done TaskControlBlock>>runTask |AST 121|Tier 2|Time 281( 245+36 )ms|Inlined 3Y 0N|IR 537/ 1469|CodeSize 4594|Addr 0x7f6a4b921c90|Src n/a
[engine] opt done TaskState>>taskWaiting: |AST 11|Tier 2|Time 58( 54+4 )ms|Inlined 0Y 0N|IR 76/ 87|CodeSize 277|Addr 0x7f6a4b92c590|Src n/a
[engine] opt done Scheduler>>createDevice:priority:work:state: |AST 157|Tier 2|Time 371( 329+43 )ms|Inlined 15Y 0N|IR 1140/ 1276|CodeSize 3644|Addr 0x7f6a4b94d410|Src n/a
[engine] opt done Scheduler>>wait |AST 27|Tier 2|Time 57( 52+5 )ms|Inlined 1Y 0N|IR 126/ 137|CodeSize 338|Addr 0x7f6a4b952c90|Src n/a
[engine] opt done Scheduler>>createWorker:priority:work:state: |AST 319|Tier 2|Time 457( 386+72 )ms|Inlined 19Y 0N|IR 1338/ 1564|CodeSize 4283|Addr 0x7f6a4b95a790|Src n/a
[engine] opt done TaskControlBlock>>addInput:checkPriority: |AST 97|Tier 2|Time 146( 122+24 )ms|Inlined 4Y 0N|IR 399/ 792|CodeSize 2295|Addr 0x7f6a4b95f190|Src n/a
[engine] opt done Packet>>datum: |AST 11|Tier 2|Time 115( 112+3 )ms|Inlined 0Y 0N|IR 74/ 88|CodeSize 273|Addr 0x7f6a4b961a90|Src n/a
[engine] opt deopt TaskControlBlock>>runTask |AST 121|Src n/a
[engine] opt inv. TaskControlBlock>>runTask |AST 121|Calls/Thres 5912/ 3|CallsAndLoop/Thres 5912/ 1000|Src n/a|Reason Profiled Return Type
[engine] opt done RBObject>>append:head: |AST 118|Tier 2|Time 95( 84+11 )ms|Inlined 2Y 0N|IR 216/ 412|CodeSize 1267|Addr 0x7f6a4b966910|Src n/a
[engine] opt done Scheduler>>queuePacket: |AST 127|Tier 2|Time 316( 278+38 )ms|Inlined 8Y 0N|IR 651/ 1020|CodeSize 2808|Addr 0x7f6a4b96f310|Src n/a
[engine] opt done Scheduler>>holdSelf |AST 49|Tier 2|Time 77( 73+4 )ms|Inlined 1Y 0N|IR 170/ 163|CodeSize 452|Addr 0x7f6a4b975e90|Src n/a
[engine] opt done TaskControlBlock>>runTask |AST 121|Tier 2|Time 165( 133+32 )ms|Inlined 3Y 0N|IR 625/ 1487|CodeSize 4649|Addr 0x7f6a4b976a90|Src n/a
[engine] opt done Scheduler>>createHandler:priority:work:state: |AST 349|Tier 2|Time 809( 631+178 )ms|Inlined 34Y 0N|IR 2370/ 3825|CodeSize 12991|Addr 0x7f6a4b979290|Src n/a
[engine] opt done TaskState>>taskHolding: |AST 11|Tier 2|Time 31( 28+3 )ms|Inlined 0Y 0N|IR 76/ 87|CodeSize 277|Addr 0x7f6a4b984f10|Src n/a
[engine] opt done DeviceTaskDataRecord>>pending: |AST 11|Tier 2|Time 33( 30+4 )ms|Inlined 0Y 0N|IR 61/ 181|CodeSize 476|Addr 0x7f6a4b985890|Src n/a
[engine] opt done TaskState>>packetPending: |AST 11|Tier 2|Time 35( 32+3 )ms|Inlined 0Y 0N|IR 74/ 85|CodeSize 267|Addr 0x7f6a4b986290|Src n/a
[engine] opt done TaskState>>running |AST 16|Tier 2|Time 43( 37+6 )ms|Inlined 0Y 0N|IR 212/ 204|CodeSize 755|Addr 0x7f6a4b987810|Src n/a
[engine] opt done IdleTaskDataRecord>>count: |AST 11|Tier 2|Time 32( 30+3 )ms|Inlined 0Y 0N|IR 73/ 88|CodeSize 273|Addr 0x7f6a4b988d10|Src n/a
[engine] opt done IdleTaskDataRecord>>control: |AST 11|Tier 2|Time 32( 29+3 )ms|Inlined 0Y 0N|IR 73/ 88|CodeSize 273|Addr 0x7f6a4b989390|Src n/a
[engine] opt done WorkerTaskDataRecord>>count: |AST 11|Tier 2|Time 32( 29+3 )ms|Inlined 0Y 0N|IR 73/ 88|CodeSize 273|Addr 0x7f6a4b989a10|Src n/a
[engine] opt done RBObject class>>DeviceA |AST 8|Tier 2|Time 21( 20+2 )ms|Inlined 0Y 0N|IR 18/ 18|CodeSize 179|Addr 0x7f6a4b98ac90|Src n/a
[engine] opt done RBObject class>>DeviceB |AST 8|Tier 2|Time 23( 21+2 )ms|Inlined 0Y 0N|IR 18/ 18|CodeSize 179|Addr 0x7f6a4b98b690|Src n/a
[engine] opt done Scheduler>>release: |AST 93|Tier 2|Time 115( 108+7 )ms|Inlined 2Y 0N|IR 191/ 253|CodeSize 761|Addr 0x7f6a4b98ba90|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 0x7f6a4b98c710|Src n/a
[engine] opt done TaskState>>packetPending |AST 18|Tier 2|Time 38( 34+3 )ms|Inlined 0Y 0N|IR 128/ 123|CodeSize 358|Addr 0x7f6a4b98fc10|Src n/a
[engine] opt done Scheduler>>createIdler:priority:work:state: |AST 236|Tier 2|Time 293( 265+28 )ms|Inlined 13Y 0N|IR 818/ 782|CodeSize 1751|Addr 0x7f6a4b992710|Src n/a
[engine] opt done Scheduler>>schedule |AST 108|Tier 2|Time 258( 156+102 )ms|Inlined 5Y 0N|IR 987/ 2675|CodeSize 9822|Addr 0x7f6a4b996910|Src n/a
[engine] opt done SequenceableCollection>>atAllPut: |AST 72|Tier 2|Time 120( 101+19 )ms|Inlined 0Y 0N|IR 206/ 479|CodeSize 2192|Addr 0x7f6a4b99e810|Src n/a
[engine] opt inv. SequenceableCollection>>atAllPut: |AST 72|Calls/Thres 416/ 3|CallsAndLoop/Thres 2252/ 1000|Src n/a
[engine] opt done SequenceableCollection>>atAllPut: |AST 72|Tier 2|Time 88( 67+21 )ms|Inlined 0Y 0N|IR 206/ 510|CodeSize 2184|Addr 0x7f6a4b9a4610|Src n/a
[engine] opt done ArrayedCollection class>>new:withAll: |AST 31|Tier 2|Time 133( 104+30 )ms|Inlined 1Y 0N|IR 258/ 672|CodeSize 2513|Addr 0x7f6a4b9af890|Src n/a
[engine] opt done Behavior>>new <split-74fef3f7> |AST 26|Tier 2|Time 53( 50+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7f6a4b9b2410|Src n/a
[engine] opt done Packet class>>create:identity:kind: |AST 35|Tier 2|Time 165( 152+13 )ms|Inlined 4Y 0N|IR 310/ 429|CodeSize 1449|Addr 0x7f6a4b9b2f90|Src n/a
[engine] opt done Scheduler>>createPacket:identity:kind: |AST 29|Tier 2|Time 173( 160+14 )ms|Inlined 5Y 0N|IR 351/ 431|CodeSize 1462|Addr 0x7f6a4b9b3e10|Src n/a
[engine] opt done Behavior>>new <split-5bb8f9e2> |AST 26|Tier 2|Time 56( 50+6 )ms|Inlined 0Y 0N|IR 94/ 374|CodeSize 1320|Addr 0x7f6a4b9b7690|Src n/a
[engine] opt done TaskControlBlock class>>link:create:priority:initialWorkQueue:initialState:function:privateData:|AST 47|Tier 2|Time 139( 125+15 )ms|Inlined 5Y 0N|IR 425/ 707|CodeSize 2202|Addr 0x7f6a4b9b8390|Src n/a
[engine] opt done Scheduler>>createTask:priority:work:state:function:data: |AST 69|Tier 2|Time 196( 163+33 )ms|Inlined 6Y 0N|IR 578/ 1393|CodeSize 4930|Addr 0x7f6a4b9ba310|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 0x7f6a4b9c0490|Src n/a
[engine] opt done TaskState>>waitingWithPacket |AST 17|Tier 2|Time 40( 36+4 )ms|Inlined 0Y 0N|IR 133/ 152|CodeSize 421|Addr 0x7f6a4b9c0890|Src n/a
[engine] opt done Behavior>>new <split-516ebdf8> |AST 26|Tier 2|Time 54( 50+3 )ms|Inlined 0Y 0N|IR 33/ 97|CodeSize 433|Addr 0x7f6a4b9c1190|Src n/a
[engine] opt done TaskState class>>waitingWithPacket |AST 26|Tier 2|Time 84( 77+7 )ms|Inlined 2Y 0N|IR 166/ 248|CodeSize 579|Addr 0x7f6a4b9c2690|Src n/a
[engine] opt done HandlerTaskDataRecord class>>create |AST 26|Tier 2|Time 80( 77+3 )ms|Inlined 2Y 0N|IR 42/ 115|CodeSize 479|Addr 0x7f6a4b9c3690|Src n/a
[engine] opt done Scheduler>>initialize |AST 77|Tier 2|Time 145( 135+10 )ms|Inlined 2Y 0N|IR 341/ 488|CodeSize 1298|Addr 0x7f6a4b9c3d10|Src n/a
[engine] opt done TaskState class>>waiting |AST 26|Tier 2|Time 77( 70+7 )ms|Inlined 2Y 0N|IR 166/ 248|CodeSize 579|Addr 0x7f6a4b9c4b90|Src n/a
[engine] opt done DeviceTaskDataRecord class>>create |AST 26|Tier 2|Time 93( 90+3 )ms|Inlined 2Y 0N|IR 42/ 115|CodeSize 479|Addr 0x7f6a4b9c5890|Src n/a
[engine] opt done Scheduler>>createHandler:priority:work:state: |AST 55|Tier 2|Time 306( 219+87 )ms|Inlined 10Y 0N|IR 816/ 2987|CodeSize 12110|Addr 0x7f6a4b9c5f10|Src n/a
[engine] opt done Scheduler>>createDevice:priority:work:state: |AST 55|Tier 2|Time 290( 220+70 )ms|Inlined 10Y 0N|IR 816/ 2987|CodeSize 12110|Addr 0x7f6a4b9cb890|Src n/a
[engine] opt done Behavior>>new <split-25c5e994> |AST 28|Tier 2|Time 163( 155+8 )ms|Inlined 3Y 0N|IR 226/ 412|CodeSize 1411|Addr 0x7f6a4b9d3710|Src n/a
[engine] opt done Scheduler class>>new |AST 26|Tier 2|Time 221( 210+11 )ms|Inlined 7Y 0N|IR 380/ 412|CodeSize 1411|Addr 0x7f6a4b9d4510|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 0x7f6a4b9d5d90|Src n/a
[engine] opt done TaskState class>>running |AST 26|Tier 2|Time 81( 71+10 )ms|Inlined 2Y 0N|IR 217/ 288|CodeSize 798|Addr 0x7f6a4b9d7310|Src n/a
[engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 274( 240+34 )ms|Inlined 10Y 1N|IR 547/ 1412|CodeSize 5041|Addr 0x7f6a4b9d8c10|Src n/a
[engine] opt done IdleTaskDataRecord class>>create |AST 26|Tier 2|Time 73( 69+3 )ms|Inlined 2Y 0N|IR 35/ 99|CodeSize 445|Addr 0x7f6a4b9db590|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 0x7f6a4b9dbc10|Src n/a
[engine] opt done Scheduler>>createIdler:priority:work:state: |AST 55|Tier 2|Time 271( 201+70 )ms|Inlined 10Y 0N|IR 808/ 2972|CodeSize 12342|Addr 0x7f6a4b9dc010|Src n/a
[engine] opt done WorkerTaskDataRecord class>>create |AST 26|Tier 2|Time 82( 79+3 )ms|Inlined 3Y 0N|IR 43/ 116|CodeSize 485|Addr 0x7f6a4b9e1610|Src n/a
[engine] opt done True>>and: |AST 17|Tier 2|Time 31( 29+2 )ms|Inlined 0Y 0N|IR 23/ 28|CodeSize 213|Addr 0x7f6a4b9e2390|Src n/a
[engine] opt done Scheduler>>createWorker:priority:work:state: |AST 55|Tier 2|Time 368( 212+156 )ms|Inlined 11Y 0N|IR 817/ 2989|CodeSize 12248|Addr 0x7f6a4b9e2790|Src n/a
[engine] opt done Scheduler>>start |AST 698|Tier 2|Time 2021(1521+500 )ms|Inlined 93Y 7N|IR 4850/10475|CodeSize 42212|Addr 0x7f6a4b9e8a90|Src n/a
[engine] opt done String class>>new: |AST 51|Tier 2|Time 162( 144+18 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f6a4ba04210|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 280( 251+29 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7f6a4ba05c90|Src n/a
[engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 271( 231+40 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f6a4ba0d690|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.051774
Remaining Compilation Queue : 0
Time to queue : count= 87, sum= 1044962, min= 96, average= 12011.07, max= 218862 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 69, sum= 18458, min= 0, average= 267.51, max= 951 (milliseconds), maxTarget=DeviceTaskDataRecord>>pending:
Time for compilation : count= 65, sum= 11371, min= 20, average= 174.94, max= 2021 (milliseconds), maxTarget=Scheduler>>start
Truffle Tier : count= 65, sum= 9357, min= 18, average= 143.96, max= 1520 (milliseconds), maxTarget=Scheduler>>start
Graal Tier : count= 65, sum= 1351, min= 1, average= 20.79, max= 326 (milliseconds), maxTarget=Scheduler>>start
Code Installation : count= 65, sum= 662, min= 1, average= 10.20, max= 174 (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= 190268, min= 179, average= 2927.20, max= 42212, maxTarget=Scheduler>>start
Total frame size : count= 65, sum= 5152, min= 32, average= 79.26, 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= 1980, min= 1, average= 30.46, max= 499, maxTarget=Scheduler>>start
Raw
5d99b29f-Sieve.trace.log
# Sieve (iterations: 250, problem size: 3000) on Thu May 27 21:52:18 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 192( 163+29 )ms|Inlined 0Y 0N|IR 223/ 367|CodeSize 1635|Addr 0x7f8b06cbc190|Src n/a
[engine] opt done Magnitude>>min: |AST 21|Tier 2|Time 46( 43+3 )ms|Inlined 0Y 0N|IR 29/ 34|CodeSize 206|Addr 0x7f8b06cc4710|Src n/a
[engine] opt done SequenceableCollection>>from:to:put: |AST 162|Tier 2|Time 159( 138+21 )ms|Inlined 1Y 0N|IR 228/ 656|CodeSize 2871|Addr 0x7f8b06cd7190|Src n/a
[engine] opt done SequenceableCollection>>atAllPut: |AST 48|Tier 2|Time 164( 145+18 )ms|Inlined 2Y 0N|IR 265/ 550|CodeSize 1947|Addr 0x7f8b06ce9b90|Src n/a
[engine] opt done Sieve>>verifyResult: |AST 15|Tier 2|Time 31( 29+2 )ms|Inlined 0Y 0N|IR 25/ 26|CodeSize 216|Addr 0x7f8b06ceb690|Src n/a
[engine] opt done ArrayedCollection class>>new:withAll: |AST 31|Tier 2|Time 212( 185+28 )ms|Inlined 3Y 0N|IR 335/ 625|CodeSize 2453|Addr 0x7f8b06cebd90|Src n/a
[engine] opt done Sieve>>benchmark |AST 44|Tier 2|Time 275( 230+45 )ms|Inlined 5Y 0N|IR 564/ 922|CodeSize 3231|Addr 0x7f8b06cf0f90|Src n/a
[engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 291( 230+61 )ms|Inlined 7Y 0N|IR 657/ 997|CodeSize 3158|Addr 0x7f8b06cfb610|Src n/a
[engine] opt done String class>>new: |AST 51|Tier 2|Time 174( 157+17 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f8b06d18f90|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 240( 217+22 )ms|Inlined 4Y 1N|IR 310/ 601|CodeSize 2107|Addr 0x7f8b06d1d790|Src n/a
[engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 280( 240+40 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f8b06d25510|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.038852
Remaining Compilation Queue : 0
Time to queue : count= 12, sum= 169254, min= 158, average= 14104.53, max= 53823 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 12, sum= 233, min= 1, average= 19.49, max= 178 (milliseconds), maxTarget=Sieve>>verifyResult:
Time for compilation : count= 11, sum= 2093, min= 32, average= 190.35, max= 292 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Truffle Tier : count= 11, sum= 1776, min= 29, average= 161.46, max= 239 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Graal Tier : count= 11, sum= 211, min= 1, average= 19.27, max= 42 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Code Installation : count= 11, sum= 105, min= 1, average= 9.62, max= 20 (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:
Raw
5d99b29f-Storage.trace.log
# Storage (iterations: 250, problem size: 1000) on Thu May 27 21:48:56 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 113( 92+22 )ms|Inlined 0Y 0N|IR 83/ 158|CodeSize 527|Addr 0x7fa016c97310|Src n/a
[engine] opt done Storage>>buildTreeDepth:with: |AST 154|Tier 2|Time 1923( 389+1534)ms|Inlined 5Y 1N|IR 1059/17106|CodeSize 79169|Addr 0x7fa016cd6090|Src n/a
[engine] opt done SomRandom>>initialize |AST 10|Tier 2|Time 31( 27+4 )ms|Inlined 0Y 0N|IR 68/ 77|CodeSize 255|Addr 0x7fa016d1a710|Src n/a
[engine] opt done Behavior>>new <split-2234078> |AST 28|Tier 2|Time 79( 76+3 )ms|Inlined 1Y 0N|IR 34/ 98|CodeSize 439|Addr 0x7fa016d1c690|Src n/a
[engine] opt done SomRandom class>>new |AST 26|Tier 2|Time 88( 84+4 )ms|Inlined 3Y 0N|IR 34/ 98|CodeSize 439|Addr 0x7fa016d1d010|Src n/a
[engine] opt done Storage>>verifyResult: |AST 15|Tier 2|Time 30( 28+2 )ms|Inlined 0Y 0N|IR 25/ 26|CodeSize 216|Addr 0x7fa016d1dc10|Src n/a
[engine] opt done Storage>>benchmark |AST 49|Tier 2|Time 1719( 293+1426)ms|Inlined 10Y 1N|IR 801/11342|CodeSize 37541|Addr 0x7fa016d24010|Src n/a
[engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 2145( 313+1832)ms|Inlined 12Y 1N|IR 898/14361|CodeSize 49755|Addr 0x7fa016d56e10|Src n/a
[engine] opt done String class>>new: |AST 51|Tier 2|Time 185( 166+19 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7fa016d93910|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 261( 237+24 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7fa016d97910|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.135563
Remaining Compilation Queue : 0
Time to queue : count= 12, sum= 161885, min= 35, average= 13490.47, max= 48530 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 12, sum= 168, min= 1, average= 14.05, max= 82 (milliseconds), maxTarget=Storage>>verifyResult:
Time for compilation : count= 10, sum= 6604, min= 31, average= 660.42, max= 2146 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Truffle Tier : count= 10, sum= 1703, min= 26, average= 170.38, max= 388 (milliseconds), maxTarget=Storage>>buildTreeDepth:with:
Graal Tier : count= 10, sum= 2960, min= 1, average= 296.00, max= 1190 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Code Installation : count= 10, sum= 1940, min= 1, average= 194.03, max= 642 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
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= 10, sum= 44181, min= 26, average= 4418.10, max= 17106, maxTarget=Storage>>buildTreeDepth:with:
Graal compilation result :
Code size : count= 10, sum= 171608, min= 216, average= 17160.80, max= 79169, maxTarget=Storage>>buildTreeDepth:with:
Total frame size : count= 10, sum= 4480, min= 32, average= 448.00, max= 1696, maxTarget=Storage>>buildTreeDepth:with:
Exception handlers : count= 10, sum= 176, min= 0, average= 17.60, max= 64, maxTarget=Storage>>benchmark
Infopoints : count= 10, sum= 1863, min= 4, average= 186.30, max= 794, maxTarget=Storage>>buildTreeDepth:with:
CALL : count= 10, sum= 1481, min= 4, average= 148.10, max= 611, maxTarget=Storage>>buildTreeDepth:with:
IMPLICIT_EXCEPTION : count= 10, sum= 376, min= 0, average= 37.60, max= 180, maxTarget=Storage>>buildTreeDepth:with:
SAFEPOINT : count= 10, sum= 6, min= 0, average= 0.60, max= 3, maxTarget=Storage>>buildTreeDepth:with:
Marks : count= 10, sum= 254, min= 7, average= 25.40, max= 71, maxTarget=Storage>>benchmark
Data references : count= 10, sum= 1892, min= 2, average= 189.20, max= 680, maxTarget=Storage>>buildTreeDepth:with:
Raw
5d99b29f-Towers.trace.log
# Towers (iterations: 250, problem size: 600) on Thu May 27 21:49: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 142( 124+18 )ms|Inlined 0Y 0N|IR 61/ 182|CodeSize 476|Addr 0x7f8d0f8f1d90|Src n/a
[engine] opt done Towers>>pushDisk:onPile: |AST 99|Tier 2|Time 244( 209+35 )ms|Inlined 1Y 0N|IR 356/ 1147|CodeSize 4001|Addr 0x7f8d0f90db90|Src n/a
[engine] opt done Towers>>popDiskFrom: |AST 83|Tier 2|Time 100( 89+12 )ms|Inlined 1Y 0N|IR 177/ 358|CodeSize 979|Addr 0x7f8d0f921190|Src n/a
[engine] opt done Towers>>moveTopDiskFrom:to: |AST 49|Tier 2|Time 226( 164+62 )ms|Inlined 4Y 0N|IR 615/ 1665|CodeSize 5504|Addr 0x7f8d0f921e10|Src n/a
[engine] opt done TowersDisk class>>new: |AST 29|Tier 2|Time 95( 91+4 )ms|Inlined 2Y 0N|IR 37/ 102|CodeSize 441|Addr 0x7f8d0f940090|Src n/a
[engine] opt done Towers>>buildTowerAt:disks: |AST 67|Tier 2|Time 238( 159+79 )ms|Inlined 5Y 0N|IR 461/ 1797|CodeSize 8232|Addr 0x7f8d0f941e10|Src n/a
[engine] opt done Towers>>move:disksFrom:to: |AST 128|Tier 2|Time 2016(1359+658 )ms|Inlined 43Y 5N|IR 4745/11904|CodeSize 44571|Addr 0x7f8d0f948490|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 0x7f8d0f96e190|Src n/a
[engine] opt done Towers>>benchmark |AST 65|Tier 2|Time 2110(1653+457 )ms|Inlined 50Y 5N|IR 2940/ 7019|CodeSize 21573|Addr 0x7f8d0f97ed90|Src n/a
[engine] opt done Benchmark>>innerBenchmarkLoop: |AST 59|Tier 2|Time 3416(1652+1763)ms|Inlined 85Y 8N|IR 4760/17117|CodeSize 54819|Addr 0x7f8d0f994910|Src n/a
[engine] opt done String class>>new: |AST 51|Tier 2|Time 170( 150+19 )ms|Inlined 2Y 1N|IR 213/ 472|CodeSize 1899|Addr 0x7f8d0f9da710|Src n/a
[engine] opt done SmallInteger>>printString |AST 152|Tier 2|Time 255( 231+24 )ms|Inlined 4Y 1N|IR 361/ 443|CodeSize 1368|Addr 0x7f8d0f9dfe90|Src n/a
[engine] opt done SequenceableCollection>>copyReplaceFrom:to:with: |AST 177|Tier 2|Time 274( 235+39 )ms|Inlined 3Y 1N|IR 474/ 1035|CodeSize 4845|Addr 0x7f8d0f9e6310|Src n/a
[engine] Truffle runtime statistics for engine 2
Compilations : 14
Success : 13
Temporary Bailouts : 0
Permanent Bailouts : 0
Failed : 0
Interrupted : 1
Invalidated : 0
Queues : 16
Dequeues : 2
Target inlined into only caller : 2
Splits : 192
Compilation Accuracy : 1.000000
Queue Accuracy : 0.875000
Compilation Utilization : 0.126394
Remaining Compilation Queue : 0
Time to queue : count= 16, sum= 239643, min= 44, average= 14977.71, max= 73715 (milliseconds), maxTarget=SequenceableCollection>>copyReplaceFrom:to:with:
Time waiting in queue : count= 14, sum= 426, min= 0, average= 30.49, max= 245 (milliseconds), maxTarget=Towers>>popDiskFrom:
Time for compilation : count= 13, sum= 9349, min= 32, average= 719.21, max= 3417 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Truffle Tier : count= 13, sum= 6144, min= 29, average= 472.63, max= 1652 (milliseconds), maxTarget=Towers>>benchmark
Graal Tier : count= 13, sum= 2033, min= 1, average= 156.39, max= 1140 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Code Installation : count= 13, sum= 1172, min= 1, average= 90.19, max= 625 (milliseconds), maxTarget=Benchmark>>innerBenchmarkLoop:
Truffle node count : count= 13, sum= 18902, min= 19, average= 1454.00, max= 7679, maxTarget=Benchmark>>innerBenchmarkLoop:
Trivial : count= 13, sum= 7065, min= 8, average= 543.46, max= 2859, maxTarget=Benchmark>>innerBenchmarkLoop:
Non Trivial : count= 13, sum= 11837, min= 11, average= 910.54, max= 4820, maxTarget=Benchmark>>innerBenchmarkLoop:
Monomorphic : count= 13, sum= 11563, min= 11, average= 889.46, max= 4715, maxTarget=Benchmark>>innerBenchmarkLoop:
Polymorphic : count= 13, sum= 274, min= 0, average= 21.08, max= 105, maxTarget=Benchmark>>innerBenchmarkLoop:
Megamorphic : count= 13, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=TowersDisk>>next:
Truffle call count : count= 13, sum= 221, min= 0, average= 17.00, max= 93, maxTarget=Benchmark>>innerBenchmarkLoop:
Indirect : count= 13, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=TowersDisk>>next:
Direct : count= 13, sum= 221, min= 0, average= 17.00, max= 93, maxTarget=Benchmark>>innerBenchmarkLoop:
Dispatched : count= 13, sum= 21, min= 0, average= 1.62, max= 8, maxTarget=Benchmark>>innerBenchmarkLoop:
Inlined : count= 13, sum= 200, min= 0, average= 15.38, max= 85, maxTarget=Benchmark>>innerBenchmarkLoop:
---------- :
Cloned : count= 13, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=TowersDisk>>next:
Not Cloned : count= 13, sum= 221, min= 0, average= 17.00, max= 93, maxTarget=Benchmark>>innerBenchmarkLoop:
Truffle loops : count= 13, sum= 0, min= 0, average= 0.00, max= 0, maxTarget=TowersDisk>>next:
Graal node count :
After Truffle Tier : count= 13, sum= 15225, min= 25, average= 1171.15, max= 4760, maxTarget=Benchmark>>innerBenchmarkLoop:
After Graal Tier : count= 13, sum= 43267, min= 26, average= 3328.23, max= 17117, maxTarget=Benchmark>>innerBenchmarkLoop:
Graal compilation result :
Code size : count= 13, sum= 148924, min= 216, average= 11455.69, max= 54819, maxTarget=Benchmark>>innerBenchmarkLoop:
Total frame size : count= 13, sum= 2032, min= 32, average= 156.31, max= 480, maxTarget=Towers>>move:disksFrom:to:
Exception handlers : count= 13, sum= 25, min= 0, average= 1.92, max= 15, maxTarget=Benchmark>>innerBenchmarkLoop:
Infopoints : count= 13, sum= 1653, min= 4, average= 127.15, max= 645, maxTarget=Benchmark>>innerBenchmarkLoop:
CALL : count= 13, sum= 1321, min= 4, average= 101.62, max= 506, maxTarget=Benchmark>>innerBenchmarkLoop:
IMPLICIT_EXCEPTION : count= 13, sum= 323, min= 0, average= 24.85, max= 138, maxTarget=Benchmark>>innerBenchmarkLoop:
SAFEPOINT : count= 13, sum= 9, min= 0, average= 0.69, max= 4, maxTarget=Towers>>buildTowerAt:disks:
Marks : count= 13, sum= 129, min= 7, average= 9.92, max= 23, maxTarget=Benchmark>>innerBenchmarkLoop:
Data references : count= 13, sum= 1024, min= 3, average= 78.77, max= 427, maxTarget=Benchmark>>innerBenchmarkLoop:
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment