Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

NPE inside jitted code in Bundler when bundling Rails 5.0.0.1 #4235

Closed
headius opened this issue Oct 19, 2016 · 27 comments
Closed

NPE inside jitted code in Bundler when bundling Rails 5.0.0.1 #4235

headius opened this issue Oct 19, 2016 · 27 comments

Comments

@headius
Copy link
Member

headius commented Oct 19, 2016

Environment

JRuby master as of today.

Rails 5.0.0.1 tag on github.

Bundler 1.13.5.

Expected Behavior

Rails should bundle properly.

Actual Behavior

I get an NPE when bundling. It happens within jitted code and does not appear to affect the simple interpreter. Here's the relevant context; I suspect it is an uninitialized variable coming from our DynamicScope:

Error details

    Java::JavaLang::NullPointerException: 
      Users.headius.projects.jruby.lib.ruby.gems.shared.gems.bundler_minus_1_dot_13_dot_5.lib.bundler.resolver.RUBY$block$search_for$6(/Users/headius/projects/jruby/lib/ruby/gems/shared/gems/bundler-1.13.5/lib/bundler/resolver.rb:268)
      org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)
      org.jruby.runtime.BlockBody.yield(BlockBody.java:116)
      org.jruby.runtime.Block.yieldArray(Block.java:179)
      org.jruby.RubyEnumerable$25.call(RubyEnumerable.java:922)
      org.jruby.runtime.CallBlock.doYield(CallBlock.java:82)
      org.jruby.runtime.BlockBody.yield(BlockBody.java:110)
      org.jruby.runtime.Block.yield(Block.java:167)
      org.jruby.RubyArray.each(RubyArray.java:1734)
      org.jruby.RubyArray$INVOKER$i$0$0$each.call(RubyArray$INVOKER$i$0$0$each.gen)
      org.jruby.RubyClass.finvoke(RubyClass.java:512)
      org.jruby.runtime.Helpers.invoke(Helpers.java:383)
      org.jruby.RubyEnumerable.callEach(RubyEnumerable.java:102)
      org.jruby.RubyEnumerable.injectCommon(RubyEnumerable.java:917)
      org.jruby.RubyEnumerable.inject(RubyEnumerable.java:938)
      org.jruby.RubyEnumerable$INVOKER$s$inject.call(RubyEnumerable$INVOKER$s$inject.gen)
      org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:171)
      org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:177)
      Users.headius.projects.jruby.lib.ruby.gems.shared.gems.bundler_minus_1_dot_13_dot_5.lib.bundler.resolver.invokeOther74:reduce(/Users/headius/projects/jruby/lib/ruby/gems/shared/gems/bundler-1.13.5/lib/bundler/resolver.rb:267)
      Users.headius.projects.jruby.lib.ruby.gems.shared.gems.bundler_minus_1_dot_13_dot_5.lib.bundler.resolver.RUBY$method$search_for$0(/Users/headius/projects/jruby/lib/ruby/gems/shared/gems/bundler-1.13.5/lib/bundler/resolver.rb:267)
      org.jruby.internal.runtime.methods.CompiledIRMethod.invokeExact(CompiledIRMethod.java:236)
      org.jruby.internal.runtime.methods.CompiledIRMethod.call(CompiledIRMethod.java:106)
      org.jruby.internal.runtime.methods.MixedModeIRMethod.call(MixedModeIRMethod.java:163)
      org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:197)
      org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:161)
      Users.headius.projects.jruby.lib.ruby.gems.shared.gems.bundler_minus_1_dot_13_dot_5.lib.bundler.resolver.invokeOther5:search_for(/Users/headius/projects/jruby/lib/ruby/gems/shared/gems/bundler-1.13.5/lib/bundler/resolver.rb:343)
      Users.headius.projects.jruby.lib.ruby.gems.shared.gems.bundler_minus_1_dot_13_dot_5.lib.bundler.resolver.RUBY$block$verify_gemfile_dependencies_are_found!$0(/Users/headius/projects/jruby/lib/ruby/gems/shared/gems/bundler-1.13.5/lib/bundler/resolver.rb:343)
@headius
Copy link
Member Author

headius commented Oct 19, 2016

Ok, it looks like this is an IR issue. Here's the method, following by explanation of the error.

    def search_for(dependency)
      platform = dependency.__platform
      dependency = dependency.dep unless dependency.is_a? Gem::Dependency
      search = @search_for[dependency] ||= begin
        index = index_for(dependency)
        results = index.search(dependency, @base[dependency.name])
        if vertex = @base_dg.vertex_named(dependency.name)
          # ***** CONDITIONALLY INITIALIZED *****
          locked_requirement = vertex.payload.requirement
        end
        spec_groups = if results.any?
          nested = []
          results.each do |spec|
            version, specs = nested.last
            if version == spec.version
              specs << spec
            else
              nested << [spec.version, [spec]]
            end
          end
          nested.reduce([]) do |groups, (version, specs)|
            # ***** NEXT LINE NPEs *****
            next groups if locked_requirement && !locked_requirement.satisfied_by?(version)
            groups << SpecGroup.new(specs)
          end
        else
          []
        end
        # GVP handles major itself, but it's still a bit risky to trust it with it
        # until we get it settled with new behavior. For 2.x it can take over all cases.
        if @gem_version_promoter.major?
          spec_groups
        else
          @gem_version_promoter.sort_versions(dependency, spec_groups)
        end
      end
      search.select {|sg| sg.for?(platform, @ruby_version) }.each {|sg| sg.activate_platform!(platform) }
    end

The locked_requirement variable is conditionally initialized and later accessed in a block. It appears our IR is not detecting that this variable may not be initialized, so it can end up as null.

cc @subbuss @enebo

I'll try to come up with a small repro.

@headius
Copy link
Member Author

headius commented Oct 19, 2016

Well that didn't take long.

$ jruby -e "def foo(a); if a; b = 1; end; 1.times { puts b.to_s }; end; foo(false)"
Unhandled Java exception: java.lang.NullPointerException

@subbuss
Copy link
Contributor

subbuss commented Oct 19, 2016

Looks like a bug in the null var inits code .. b is probably not being init to null. will take a look later tonight unless you guys get to it first.

@subbuss
Copy link
Contributor

subbuss commented Oct 19, 2016

The bug is in

public void identifyInits(Set<Variable> undefinedVars) {
int parentScopeDepth = 1;
if (problem.getScope().getFlags().contains(IRFlags.REUSE_PARENT_DYNSCOPE)) {
parentScopeDepth = 0;
}
// System.out.println("BB " + basicBlock + "; state\n" + toString());
initSolution();
for (Instr i: basicBlock.getInstrs()) {
// Variables that belong to outer scopes should always
// be considered defined.
for (Variable v: i.getUsedVariables()) {
if (!v.isSelf()) {
if (v instanceof LocalVariable && ((LocalVariable)v).getScopeDepth() >= parentScopeDepth) {
tmp.set(problem.getDFVar(v));
}
if (!tmp.get(problem.getDFVar(v))) {
// System.out.println("Variable " + v + " in instr " + i + " in " + basicBlock + " isn't defined!");
undefinedVars.add(v);
}
}
}
// v is defined
if (i instanceof ResultInstr) {
tmp.set(problem.getDFVar(((ResultInstr) i).getResult()));
}
}
}
.. the identifyInits method .. That code is not looking at variables used but not defined in nested closures at all.

@subbuss
Copy link
Contributor

subbuss commented Oct 19, 2016

As I am getting ready to head out in the morning (in Seattle at some offsites), I thought I would quickly pop in and mention that this is a simple fix but I cannot fix it now since I am going to be out and about the whole day. But here is the quick scoop in case anyone wants to take a crack at it. IRScope used to maintain state about used and defined vars. So, all that needs to be done is for 'identifyMissingInits' code to collect all used-but-not-defined vars from all nested closures (all the way to the leaf) that belong to current scope and add it to the set of vars needing inits.

@subbuss
Copy link
Contributor

subbuss commented Oct 19, 2016

Okay, I'll take a crack at this now for a short while and get back to it tonight. It might be a bit more involved than the outline above if we don't want to be extra conservative around closures.

@subbuss subbuss self-assigned this Oct 19, 2016
@subbuss
Copy link
Contributor

subbuss commented Oct 20, 2016

This functionality needs a whole bunch of specs with all kinds of corner cases. Can someone create them? I am not going to be able to till next week at least.

@headius
Copy link
Member Author

headius commented Oct 20, 2016

@subbuss You're awesome...I was going to look into it this afternoon, but instead I'll try to fill out some edge case tests.

@headius
Copy link
Member Author

headius commented Oct 20, 2016

@subbuss What kinds of corner are you thinking of? I thought through various amounts of nesting closures, different contexts like class bodies...none seemed like they'd be very valuable. And more complicated conditional cases reduce logically to the simple case anyway.

@subbuss
Copy link
Contributor

subbuss commented Oct 21, 2016

For now, just the two (one from this task, and one from 192ca18) are sufficient. I had other complicated scenarios in mind, but they are no longer relevant because I had forgotten about the assumption in 4253b8e.

@headius
Copy link
Member Author

headius commented Oct 31, 2016

I'm either going crazy or this is still broken on master. I tried to clone and bundle https://github.com/floehopper/introspection, and I'm getting the same trace again:

[] ~/projects/introspection $ bundle install
Fetching gem metadata from https://rubygems.org/.............
Fetching version metadata from https://rubygems.org/.
--- ERROR REPORT TEMPLATE -------------------------------------------------------
- What did you do?

  I ran the command `/Users/headius/projects/jruby/bin/bundle install`

- What did you expect to happen?

  I expected Bundler to...

- What happened instead?

  Instead, what happened was...


Error details

    Java::JavaLang::NullPointerException: 
      Users.headius.projects.jruby.lib.ruby.gems.shared.gems.bundler_minus_1_dot_13_dot_5.lib.bundler.resolver.RUBY$block$search_for$0(/Users/headius/projects/jruby/lib/ruby/gems/shared/gems/bundler-1.13.5/lib/bundler/resolver.rb:268)
      org.jruby.runtime.CompiledIRBlockBody.yieldDirect(CompiledIRBlockBody.java:156)
      org.jruby.runtime.MixedModeIRBlockBody.yieldDirect(MixedModeIRBlockBody.java:122)
      org.jruby.runtime.BlockBody.yield(BlockBody.java:116)
      org.jruby.runtime.Block.yieldArray(Block.java:179)
...

This is the same line as before: #4235 (comment)

It seems the case used in bundler is still broken, even though we fixed the reduced case.

@headius
Copy link
Member Author

headius commented Oct 31, 2016

I have come up with a reproduction. It's a bit more complicated than we thought.

The following code is structured to better reproduce the bundler issue. The key events that seem to cause the error are:

  1. The closure must first JIT independent of the method body. If the method body JITs successfully first, the code runs fine.
  2. The method itself must attempt to JIT but fail.
  3. The closure inside the method re-JITs and starts failing.

If you run this script with -Xjit.logging -Xjit.background=false, you will see the closure JIT, and things run ok...until the method fails to JIT,

def search_for(blah)
  asdf = [1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1,]
  asdf.each { |i| i * i }
  if blah
    locked_requirement = "foo"
  end
  [1..100].each do |s|
    p locked_requirement
  end
end

1000.times {
  search_for(false)
}

Without the "nil" output, here's the lines I get.

2016-10-31T12:45:03.591-05:00 [main] INFO Ruby : done compiling target script: -e
2016-10-31T12:45:03.631-05:00 [main] INFO JITCompiler : done jitting: <block> search_for_CLOSURE_1.search_for_CLOSURE_1 at /Users/headius/projects/jruby/blah.rb:2
...
<NILS REMOVED>
...
2016-10-31T12:45:03.687-05:00 [main] INFO JITCompiler : done jitting: <block> /Users/headius/projects/jruby/blah.rb_CLOSURE_1./Users/headius/projects/jruby/blah.rb_CLOSURE_1 at /Users/headius/projects/jruby/blah.rb:11
2016-10-31T12:45:03.708-05:00 [main] INFO JITCompiler : Could not compile; passes run: [org.jruby.ir.passes.LocalOptimizationPass@584ed071, org.jruby.ir.passes.DeadCodeElimination@805d30ee, org.jruby.ir.passes.OptimizeDynScopesPass@f61f6f63, org.jruby.ir.passes.OptimizeDelegationPass@6c7a3ce9, org.jruby.ir.passes.AddCallProtocolInstructions@87f2d916, org.jruby.ir.passes.AddMissingInitsPass@a7c39fef]: Object Object.search_for at /Users/headius/projects/jruby/blah.rb:0 because of: "literal array has more than 250 elements"
2016-10-31T12:45:03.711-05:00 [main] INFO JITCompiler : done jitting: <block> search_for_CLOSURE_2.search_for_CLOSURE_2 at /Users/headius/projects/jruby/blah.rb:6
nil
Unhandled Java exception: java.lang.NullPointerException
java.lang.NullPointerException: null
                                        getClass at org/jruby/runtime/callsite/CachingCallSite.java:444

@enebo
Copy link
Member

enebo commented Oct 31, 2016

@headius @subbuss so when JIT fails we do not full build and run in interp we fall back to startup interp. The closure is assuming it will access the lvar from code with missing inits added. The primary issue being you cannot add inits to startup instructions since it is just a list.

We could maybe in JIT failure case retain full build and use full interp since it cannot fail and would have the inits but I am not sure how this fits into how we store references in the *Methods. Can a mixed mode method use either full interp engire OR a JIT compiled method? I guess I will poke around there.

@enebo
Copy link
Member

enebo commented Oct 31, 2016

So rough draft and this feels a bit icky:

  • catch in JITCompiler will use full build as fall back on failure (assumption: full build never fails?)
  • It will make a InterpretedIRMethod in the place of what would normally happen CompiledIRMethod
  • we will need to make a new instance of InterpretedIRMethod and call completeBuild with the fullIC

@subbuss
Copy link
Contributor

subbuss commented Oct 31, 2016

In the middle of some parsoid work, but, quick qn: won't the interp continue to use the return nil if null logic in dynamic scope? or did that get removed?

@enebo
Copy link
Member

enebo commented Oct 31, 2016

@subbuss My understanding at this point is it is the recompiled nested closure which is making the assumption so it is not interpreting.

@enebo
Copy link
Member

enebo commented Oct 31, 2016

Another option would be that since closure needs to know that it is compiling over a failed parent scope perhaps it can emit nil checking? Can we know that? I guess it would be nice to know at IRScope level.

@headius
Copy link
Member Author

headius commented Oct 31, 2016

Ok, ignore the bit about the closure jitting twice. The first closure to JIT was the each loop I used to anchor the big array. Here's the script with that loop removed:

<nils removed>
def search_for(blah)
  asdf = [1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1,]
  asdf.to_s
  if blah
    locked_requirement = "foo"
  end
  [1..100].each do |s|
    p locked_requirement
  end
end

1000.times {
  search_for(false)
}

And the full output:

[] ~/projects/jruby $ jruby -Xjit.logging -Xjit.background=false blah.rb
2016-10-31T15:51:00.082-05:00 [main] ERROR Ruby : failed to compile target script blah.rb: literal array has more than 250 elements
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
nil
2016-10-31T15:51:00.303-05:00 [main] INFO JITCompiler : done jitting: <block> blah.rb_CLOSURE_1.blah.rb_CLOSURE_1 at blah.rb:11
2016-10-31T15:51:00.360-05:00 [main] INFO JITCompiler : Could not compile; passes run: [org.jruby.ir.passes.LocalOptimizationPass@584ed071, org.jruby.ir.passes.DeadCodeElimination@805d30ee, org.jruby.ir.passes.OptimizeDynScopesPass@f61f6f63, org.jruby.ir.passes.OptimizeDelegationPass@6c7a3ce9, org.jruby.ir.passes.AddCallProtocolInstructions@87f2d916, org.jruby.ir.passes.AddMissingInitsPass@a7c39fef]: Object Object.search_for at blah.rb:0 because of: "literal array has more than 250 elements"
2016-10-31T15:51:00.364-05:00 [main] INFO JITCompiler : done jitting: <block> search_for_CLOSURE_1.search_for_CLOSURE_1 at blah.rb:6
nil
Unhandled Java exception: java.lang.NullPointerException
java.lang.NullPointerException: null
                 getClass at org/jruby/runtime/callsite/CachingCallSite.java:444
                     call at org/jruby/runtime/callsite/CachingCallSite.java:125
                rbInspect at org/jruby/RubyBasicObject.java:1136
                        p at org/jruby/RubyKernel.java:477
                     call at org/jruby/RubyKernel$INVOKER$s$0$0$p.gen:-1
                     call at org/jruby/internal/runtime/methods/JavaMethod.java:720
                     call at org/jruby/internal/runtime/methods/DynamicMethod.java:199
             cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:338
                     call at org/jruby/runtime/callsite/CachingCallSite.java:163
           invokeOther0:p at blah.rb:8
      block in search_for at blah.rb:8
              yieldDirect at org/jruby/runtime/CompiledIRBlockBody.java:156
              yieldDirect at org/jruby/runtime/MixedModeIRBlockBody.java:122
                    yield at org/jruby/runtime/BlockBody.java:108
                    yield at org/jruby/runtime/Block.java:167
                     each at org/jruby/specialized/RubyArrayOneObject.java:128
                     call at org/jruby/RubyArray$INVOKER$i$0$0$each.gen:-1
                     call at org/jruby/internal/runtime/methods/JavaMethod.java:497
                callBlock at org/jruby/runtime/callsite/CachingCallSite.java:77
                     call at org/jruby/runtime/callsite/CachingCallSite.java:83
                interpret at org/jruby/ir/instructions/CallBase.java:428
              processCall at org/jruby/ir/interpreter/InterpreterEngine.java:356
                interpret at org/jruby/ir/interpreter/StartupInterpreterEngine.java:73
                interpret at org/jruby/ir/interpreter/InterpreterEngine.java:84
         INTERPRET_METHOD at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:179
                     call at org/jruby/internal/runtime/methods/MixedModeIRMethod.java:165
                     call at org/jruby/internal/runtime/methods/DynamicMethod.java:199
             cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:338
                     call at org/jruby/runtime/callsite/CachingCallSite.java:163
  invokeOther0:search_for at blah.rb:13
         block in blah.rb at blah.rb:13
              yieldDirect at org/jruby/runtime/CompiledIRBlockBody.java:156
              yieldDirect at org/jruby/runtime/MixedModeIRBlockBody.java:122
            yieldSpecific at org/jruby/runtime/IRBlockBody.java:73
            yieldSpecific at org/jruby/runtime/Block.java:136
                    times at org/jruby/RubyFixnum.java:299
                     call at org/jruby/RubyFixnum$INVOKER$i$0$0$times.gen:-1
                     call at org/jruby/internal/runtime/methods/JavaMethod.java:497
             cacheAndCall at org/jruby/runtime/callsite/CachingCallSite.java:298
                callBlock at org/jruby/runtime/callsite/CachingCallSite.java:79
                     call at org/jruby/runtime/callsite/CachingCallSite.java:83
                interpret at org/jruby/ir/instructions/CallBase.java:428
              processCall at org/jruby/ir/interpreter/InterpreterEngine.java:356
                interpret at org/jruby/ir/interpreter/StartupInterpreterEngine.java:73
           INTERPRET_ROOT at org/jruby/ir/interpreter/Interpreter.java:112
                  execute at org/jruby/ir/interpreter/Interpreter.java:99
                  execute at org/jruby/ir/interpreter/Interpreter.java:35
                  execute at org/jruby/ir/IRTranslator.java:42
           runInterpreter at org/jruby/Ruby.java:867
           runInterpreter at org/jruby/Ruby.java:871
              runNormally at org/jruby/Ruby.java:766
              runNormally at org/jruby/Ruby.java:779
              runFromMain at org/jruby/Ruby.java:592
            doRunFromMain at org/jruby/Main.java:425
              internalRun at org/jruby/Main.java:313
                      run at org/jruby/Main.java:242
                     main at org/jruby/Main.java:204

@headius
Copy link
Member Author

headius commented Oct 31, 2016

Further simplification of the script shows that even if ONLY the closure JITs, it blows up.

def search_for(blah)
  asdf = [1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1,]
  asdf.to_s
  if blah
    locked_requirement = "foo"
  end
  100.times do |s|
    locked_requirement.to_s
    p s
  end
end

3.times { search_for(false) }

Run like jruby -Xjit.logging -Xjit.background=false -e 'load "blah.rb"'

So this is a mismatch of running jitted blocks in any unjitted context that might have uninitialized variables, because the IR interpreters do not make any guarantees that those variables have been initialized.

@enebo
Copy link
Member

enebo commented Oct 31, 2016

Ok we have talked quite a bit about this. The issue is whether we fail to JIT method then JIT a closure after that failure OR we execute a child closure enough to JIT before the method we can end up hitting a case where the parent scope has no var init code in it.

In the case of a failure of a method we can fall over to use Full interp with the Full code we just made. This has one risk that we seem to no longer run CI against Full interp with all passes. It also cannot solve the second scenario where a block happens to run first.

The other solution is that a closure JITting can look at parent scopes up to a hard scope (method/closure/module/script) and if any of them do not have a fullIC we have to emit nil checks in the emitted bytecode. This solution has the downside that hot closures will be penalized and will never get fixed later unless the method happens to JIT.

We realized that we can do this lack of nil checking on any hard scopes since they cannot capture another scopes variables. So that is what we plan on keeping for 9.1.6.0.

We can also skip checks for any closures which do not capture a parents.

Possibly we can check full status of captured parents and still do opt if they have all been compiled (e.g. have fullIC).

@enebo
Copy link
Member

enebo commented Oct 31, 2016

Ah another one. any vars local to the closure scope itself need not be nil checked since we will run pass to add missing inits for it.

headius added a commit that referenced this issue Oct 31, 2016
This is a "fix" for #4235 in that it prevents closures from ever
blindly reading closed-over variables that have not been
initialized to nil. This may happen if the block jits independent
of the method, in which case the method will continue to be run
through null-checking interpreter logic, so the closure code
cannot guarantee all values are non-null on first read.

This is only a "fix" in quotes because it completely disables the
fast path optimizaton for all non-method JIT.

Note that I did add specialized "OrNil" paths to the generated
DynamicScope subclasses, so that should at least inline to a field
plus null check.
@headius
Copy link
Member Author

headius commented Oct 31, 2016

I have done an emergency "fix" (0e65638) for this that disables the fast path scope gets if we're not in a method body. This avoids the problem of a parent scope running in interpreter (with null checks and without initialization logic) containing a closure that has been jitted (without null checks).

I also generated the additional specialized "OrNil" methods into our DynamicScope subtypes, so the null-checking paths should inline down to a field get, a null check, and a possible field set.

This should be a good enough fix for 9.1.6.0 but as @enebo says we're penalizing jitted closures inside scopes that themselves never jit.

@subbuss
Copy link
Contributor

subbuss commented Nov 1, 2016

Okay, yes, the problem is that as the comment in the analysis shows, it assumes that variables in external scopes have been defined already -- this assumption is violated when a closure is JIT-ted independent of the parent scope. Can this scheme work?

  • Add a flag to IRScope called ancestorsJitted, selfJitted. ancestorsJitted is true for IRMethod always, and selfJitted is false for everyone initially.
  • When a scope JITs, set selfJitted to true. If ancestorsJitted is true, set child.ancestorsJitted to true for all children. Recursively propagate it down the scope nesting tree if a child has child.selfJitted to true.
  • When you are allocating a dyn-scope for a closure, allocate an optimized dynscope or the old-style dynscope depending on whether (ancestorsJitted && selfJitted) true or false.
  • This lets you alloc the right DynScope always without losing opt opportunity, but you are adding 2 instrs (logical-and, branch) now to all calls with closures.

@enebo
Copy link
Member

enebo commented Nov 1, 2016

@subbuss I think just calling up parents to non-closure scope and we can ask isFull or make a method which just notices whether full build has occurred. A full build should add add init as a default pass I think as a base condition to being correct too. I think we just need to assume we have no missing inits before any other flow-based optimizations. As far as base assumptions for state of our instrs missing inits seems like it should be front and foremost to me.

@enebo enebo modified the milestones: JRuby 9.1.7.0, JRuby 9.1.6.0 Nov 7, 2016
@enebo
Copy link
Member

enebo commented Nov 7, 2016

So we have something which is no longer broken but it is non-optimal. I am bumping this one version so we can keep track of doing a better fix. I would make a new issue but since we have not had nil init opto in place in a release yet this would be confusing to list in our issues resolved list anyways.

@headius
Copy link
Member Author

headius commented Dec 8, 2016

@enebo Perhaps we should bump to 9.2 since we're starting to wind down the 9.1 series a bit and want to get a 9.1.7.0 out in the next week?

@enebo enebo modified the milestones: JRuby 9.2.0.0, JRuby 9.1.7.0 Dec 8, 2016
@headius
Copy link
Member Author

headius commented May 15, 2018

Closing this in favor of another issue. What we have is still less than ideal, since an interpreted method that's only called once will never see a contained block jit, no matter how many times it is called. However the original reported problem was solved, and this is now getting pretty stale.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants