truffleruby
truffleruby copied to clipboard
Published
20 hours ago •
oracle
oracle
[Bug / Splitting] Possible issue on splitting methods and their observability
During profiling a rails app (running a single test with jt --use jvm-ce ruby -S ./bin/rails test test/...) we've noticed some methods being multiple without having any distinction.
An example during
jt --use jvm-ce ruby --cputracer --cputracer.TraceStatements --cputracer.FilterRootName="*Array#<<*" -S bin/rails test test/...
produced:
| Name | Total Count | Interpreted Count | Compiled Count | Location |
|---|---|---|---|---|
| Array#<< | 1075005 95.4% | 82523 7.7% | 992482 92.3% | (core)~1:0 |
| Array#<< | 39703 3.5% | 248 0.6% | 39455 99.4% | (core)~1:0 |
| Array#<< | 26 0.0% | 26 100.0% | 0 0.0% | (core)~1:0 |
| Array#<< | 3 0.0% | 3 100.0% | 0 0.0% | (core)~1:0 |
| Array#<< | 3 0.0% | 3 100.0% | 0 0.0% | (core)~1:0 |
| Array#<< | 3 0.0% | 3 100.0% | 0 0.0% | (core)~1:0 |
| Array#<< | 3 0.0% | 3 100.0% | 0 0.0% | (core)~1:0 |
| Array#<< | 3 0.0% | 3 100.0% | 0 0.0% | (core)~1:0 |
| Array#<< | 3 0.0% | 3 100.0% | 0 0.0% | (core)~1:0 |
| Array#<< | 2 0.0% | 2 100.0% | 0 0.0% | (core)~1:0 |
Notice the multiple lines of Array#<<.
Same run on --engine.TraceCompilation:
[engine] opt done id=170 Array#<< |Tier 1|Time 38( 27+12 )ms|AST 15|Inlined 0Y 0N|IR 194/ 1080|CodeSize 3252|Addr 0x115418580|Timestamp 526313342165250|Src (core):1
[engine] opt deopt id=170 Array#<< | |Timestamp 526313348586458|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 24( 10+13 )ms|AST 15|Inlined 0Y 0N|IR 227/ 1255|CodeSize 3868|Addr 0x11542e700|Timestamp 526313376104958|Src (core):1
[engine] opt deopt id=170 Array#<< | |Timestamp 526313383752375|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 51( 12+39 )ms|AST 15|Inlined 0Y 0N|IR 262/ 1529|CodeSize 5816|Addr 0x11545d340|Timestamp 526313436705583|Src (core):1
[engine] opt deopt id=170 Array#<< | |Timestamp 526313750882166|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 34( 7+27 )ms|AST 15|Inlined 0Y 0N|IR 292/ 1573|CodeSize 6196|Addr 0x1155868c0|Timestamp 526313797386166|Src (core):1
[engine] opt deopt id=170 Array#<< | |Timestamp 526314748801083|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 37( 6+31 )ms|AST 15|Inlined 0Y 0N|IR 340/ 1698|CodeSize 6616|Addr 0x1159112c0|Timestamp 526314790856083|Src (core):1
[engine] opt deopt id=170 Array#<< | |Timestamp 526316942213083|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 34( 7+27 )ms|AST 15|Inlined 0Y 0N|IR 416/ 2218|CodeSize 8208|Addr 0x115d98100|Timestamp 526316994690208|Src (core):1
[engine] opt deopt id=170 Array#<< | |Timestamp 526318420675958|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 101( 6+95 )ms|AST 15|Inlined 0Y 0N|IR 452/ 2406|CodeSize 9088|Addr 0x115eea280|Timestamp 526319229734041|Src (core):1
[engine] opt done id=2079 Array#<< |Tier 1|Time 4( 2+2 )ms|AST 4|Inlined 0Y 1N|IR 88/ 242|CodeSize 976|Addr 0x115d49440|Timestamp 526322635861375|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 62( 5+57 )ms|AST 15|Inlined 0Y 0N|IR 459/ 2416|CodeSize 9132|Addr 0x115e3df00|Timestamp 526324150734333|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 164( 21+143 )ms|AST 15|Inlined 0Y 0N|IR 1146/ 5234|CodeSize 23096|Addr 0x115d88480|Timestamp 526325181634416|Src (core):1
[engine] opt deopt id=170 Array#<< | |Timestamp 526325199863583|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 167( 12+155 )ms|AST 15|Inlined 0Y 0N|IR 856/ 4031|CodeSize 16000|Addr 0x115d40c00|Timestamp 526325431762250|Src (core):1
[engine] opt deopt id=170 Array#<< | |Timestamp 526325712686750|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 112( 11+101 )ms|AST 15|Inlined 0Y 0N|IR 873/ 4048|CodeSize 15880|Addr 0x115f76400|Timestamp 526325860507875|Src (core):1
[engine] opt deopt id=170 Array#<< | |Timestamp 526325884987833|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 191( 12+179 )ms|AST 15|Inlined 0Y 0N|IR 878/ 4049|CodeSize 15908|Addr 0x115d8b300|Timestamp 526326087962541|Src (core):1
[engine] opt deopt id=170 Array#<< | |Timestamp 526326226961791|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 176( 11+165 )ms|AST 15|Inlined 0Y 0N|IR 880/ 4049|CodeSize 16360|Addr 0x115b72700|Timestamp 526326409789166|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 72( 6+66 )ms|AST 15|Inlined 0Y 0N|IR 510/ 1976|CodeSize 8156|Addr 0x115ccbe00|Timestamp 526328710310458|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 37( 6+31 )ms|AST 15|Inlined 0Y 0N|IR 517/ 1986|CodeSize 8152|Addr 0x1160d8280|Timestamp 526332670863958|Src (core):1
[engine] opt deopt id=170 Array#<< | |Timestamp 526335586215416|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 42( 6+37 )ms|AST 15|Inlined 0Y 0N|IR 543/ 2012|CodeSize 8516|Addr 0x115e7e680|Timestamp 526335647133750|Src (core):1
[engine] opt done id=170 Array#<< |Tier 1|Time 86( 6+80 )ms|AST 15|Inlined 0Y 0N|IR 550/ 2022|CodeSize 8572|Addr 0x1155c8180|Timestamp 526350708078291|Src (core):1
@eregon noticed the
[engine] opt done id=2079 Array#<< |Tier 1|Time 4( 2+2 )ms|AST 4|Inlined 0Y 1N|IR 88/ 242|CodeSize 976|Addr 0x115d49440|Timestamp 526322635861375|Src (core):1
line having a different id from the rest - which is the only one with a used callsite (1N) - and a suspiciously low AST node count (4 compare to 15, like the rest).
I wonder if there is anything fishy here.
