Excessive splitting with `Method#to_proc`

nirvdrum commented 2 months ago

I'm trying to track down a production issue where the Array#<< method keeps splitting. There's no deoptimization. If I trace splitting, the log just fills up with something like the following (I removed a few interspersed splits from other methods, but most of these appear back-to-back).

Splitting Log

I've added logging to RubyRootNode#cloneUninitialized and with that, I've tracked the source of the split to Truffle::Splitter.add_substring. In particular, Truffle::Splitter.split accepts a block to work with the split results, but if no block is provided, it returns an array of the split components. To avoid code duplication, it does the following if a block is not provided:

result = []
block = orig_block || result.method(:<<).to_proc

That's the source of the Array#<< splits. The string splitting code is quite large, so cutting that out we're left with:

def splits(&block)
  [].method(:<<).to_proc.call(1)
end

loop { splits }

If you run jt ruby --engine.TraceSplitting split_issue.rb, you'll see a consecutive run of splits for Array#<<:

[engine] split 505-52ccf197-1     Array#<<                                                    |AST   10|Tier 1|Calls/Thres       3/    1|CallsAndLoop/Thres       3/  400|SourceSection (core)~1:0
[engine] split 506-2b06681c-1     Array#<<                                                    |AST   10|Tier 1|Calls/Thres       3/    1|CallsAndLoop/Thres       3/  400|SourceSection (core)~1:0
[engine] split 507-20f6b6e0-1     Array#<<                                                    |AST   10|Tier 1|Calls/Thres       3/    1|CallsAndLoop/Thres       3/  400|SourceSection (core)~1:0
[engine] split 508-67cd84f9-1     Array#<<                                                    |AST   10|Tier 1|Calls/Thres       3/    1|CallsAndLoop/Thres       3/  400|SourceSection (core)~1:0
[engine] split 509-52b891de-1     Array#<<                                                    |AST   10|Tier 1|Calls/Thres       3/    1|CallsAndLoop/Thres       3/  400|SourceSection (core)~1:0
[engine] split 510-4ae6451d-1     Array#<<                                                    |AST   10|Tier 1|Calls/Thres       3/    1|CallsAndLoop/Thres       3/  400|SourceSection (core)~1:0
[engine] split 511-54530644-1     Array#<<                                                    |AST   10|Tier 1|Calls/Thres       3/    1|CallsAndLoop/Thres       3/  400|SourceSection (core)~1:0```

The splitting will stop once the dispatch cache limit in MethodNodes.ToProcNode#toProcCachedSingleContext is hit. In my production environment, however, the splitting never stops. I haven't yet determined why that is and my attempts at finding a small reproduction haven't produced the non-stop splitting. Unfortunately, due to security restrictions in the production environment I can only use jdb as the debugger and that's making for a very slow process.

The primary attribution stems back to a code loop that writes to a file once per second. It looks like:

tempfilename = File.join(Dir.tmpdir, "monitor_#{Process.pid}")
tempfile = File.open(tempfilename, "w", encoding: marshaled_stats.encoding)

The File.open call will call Truffle::IOOperations.normalize_options, which in turn calls String#split. The loop body is not dynamically declaring classes or methods, so I'm not sure why the splits won't converge.

We can work around this by changing the way Truffle::Splitter works, but I think it's worth looking at the larger issue.

eregon commented 2 months ago

Thank you for the report, that repro is enough to show there is unexpected splitting there, it should split at most once since there is a single caller of splits.

eregon commented 2 months ago

I investigated this. What we need is a global cache from InternalMethod to (Method#to_proc) CallTarget, like we already have for Symbol#to_proc. We should simply add a CallTarget field in InternalMethod for that. Once we have that we should have a single specialization in Method#to_proc and no more inline caching, that specialization just checking if the CallTarget field is non-null and creating a RubyProc from it, or creating the CallTarget and store it behind a TruffleBoundary.

(we could also force split + inline cache that, but the minimal performance gain doesn't seem worth the footprint cost)

eregon commented 2 months ago

Regarding Truffle::Splitter.split we should remove the .to_proc there because it seems unnecessary (and rename block to callable) and we should always_split it, as well as its caller String#split so calls to the block/callable are fast and not some IndirectCallNode because Truffle::Splitter.split is too big to split heuristically.

EDIT: @nirvdrum will do this

andrykonchin commented 2 months ago

Fixed in dc120e729c55bb93e4a9e4657cd22d3a61fd3325/#3529 and 95c8d7f5a7b7015cf8ef4042b418b8cb6a187aec/#3540

oracle / truffleruby

Excessive splitting with `Method#to_proc` #3527