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

Block call IR optimization failures by 0d35995e1704bb716a9b54064208cf82ace2f150 #3577

Closed
nahi opened this issue Jan 1, 2016 · 20 comments
Closed

Comments

@nahi
Copy link
Member

nahi commented Jan 1, 2016

I found a test began failing after 0d35995 (cc @subbuss)

Repro:

% git clone git@github.com:sparklemotion/http-cookie.git
% cd http-cookie
% jruby -Ilib test/test_http_cookie_jar.rb # => fail
% jruby --dev -Ilib test/test_http_cookie_jar.rb # => OK

With 8a04861 it passes so I guess 0d35995 is a cause but I don't have enough knowledge of IR optimization.

@subbuss
Copy link
Contributor

subbuss commented Jan 1, 2016

This looks specific to JIT mode. I forced a full build of scopes to generate explicit call protocol for blocks in -X-C mode and it doesn't fail. Below is a shorter snippet I could reduce this to (but not yet an independent standalone test case). To be continued. /cc @headius

require File.expand_path('helper', File.dirname(__FILE__))
require 'tmpdir'

module TestHTTPCookieJar
  class WithHashStore < Test::Unit::TestCase
    def setup(options = nil, options2 = nil)
      default_options = {
        :store => :hash,
        :gc_threshold => 1500, # increased by 10 for shorter test time
      }
      new_options  = default_options.merge(options || {})
      @jar  = HTTP::CookieJar.new(new_options)
    end

    def cookie_values(options = {})
      {
        :name     => 'Foo',
        :value    => 'Bar',
        :path     => '/',
        :expires  => Time.at(Time.now.to_i + 10 * 86400), # to_i is important here
        :for_domain => true,
        :domain   => 'rubyforge.org',
        :origin   => 'http://rubyforge.org/'
      }.merge(options)
    end

    def test_add_multiple_cookies_with_the_same_name
      now = Time.now

      cookies = [
        { :value => 'a', :path => '/', },
        { :value => 'b', :path => '/abc/def/', :created_at => now - 1 },
        { :value => 'c', :path => '/abc/def/', :domain => 'www.rubyforge.org', :origin => 'http://www.rubyforge.org/abc/def/', :created_at => now },
        { :value => 'd', :path => '/abc/' },
      ].map { |attrs|
        HTTP::Cookie.new(cookie_values(attrs))
      }

      url = URI 'http://www.rubyforge.org/abc/def/ghi'
      cookies.permutation(cookies.size) { |shuffled|
        @jar.clear
        shuffled.each { |cookie| @jar.add(cookie) }
        @jar.each(url) { |cookie| cookie.value }
      }
    end
  end
end

@subbuss
Copy link
Contributor

subbuss commented Jan 2, 2016

Consider this snippet from http/cookie_jar/hash_store.rb

    def each(uri = nil) # :yield: cookie
      now = Time.now
      if uri
        thost = DomainName.new(uri.host)
        tpath = uri.path
        @jar.each { |domain, paths|
          next unless thost.cookie_domain?(domain)
          paths.each { |path, hash|
            next unless HTTP::Cookie.path_match?(path, tpath)
            hash.delete_if { |name, cookie|
              if cookie.expired?(now)
                true
              else
                if cookie.valid_for_uri?(uri)
                  cookie.accessed_at = now
                  yield cookie
                end
                false
              end
            }
          }
        }
...

That yield statement is throwing an error in the JIT because the self-block is a NULL_BLOCK. So, in the direct yield path somewhere, the self-block is being lost (or is not being loaded properly).

@subbuss
Copy link
Contributor

subbuss commented Jan 2, 2016

@headius could this be some confusion between selfBlock and blockArg in JIT code gen? I haven't looked at the code in detail but I see 7de397f introduced this. It might be quicker for you to audit the usage to see if the two blocks are being handled consistently everywhere.

@subbuss
Copy link
Contributor

subbuss commented Jan 2, 2016

Everything seems to check out as far as I can tell. I'll let @headius investigate further.

@headius
Copy link
Member

headius commented Jan 6, 2016

Looking into this today.

@headius
Copy link
Member

headius commented Jan 6, 2016

I believe I have a fairly narrow reproduction now.

@ary = [1]

def foo
  x = nil
  loop {
    x = (a = nil; a) or break
    x = @ary[0]
  }
end;

def bar;
  foo
  1.times {|x| yield }
end

bar { }

I suspect the "or break" is not being handled right and causing a frame to be left on the stack, so that when we return to the 1.times call we're giving the closure a frame that does not have an implicit block.

I'm not sure why this would be different in JIT, though.

@headius
Copy link
Member

headius commented Jan 6, 2016

Slightly smaller:

def foo
  x = nil
  loop {
    (a = nil; a) or break
    x = x[0]
  }
end;

def bar;
  foo
  loop {|x| yield }
end

bar { }

Here's the final optimized IR for the closure in foo:

2016-01-06T11:32:19.897-06:00: JVMVisitor: Starting JVM compilation on scope CLOSURE foo_CLOSURE_1[blah.rb:2]
2016-01-06T11:32:19.897-06:00: JVMVisitor: 

Linearized instructions for JIT:
Instructions:

CFG:
BB [1:CL1_LBL_4:-1]:>[2,9]
BB [2:CL1_LBL_5:-1]:>[4,6], <[1]
BB [4:CL1_LBL_6:-1]:>[7,9], <[2]
BB [6:CL1_LBL_0:13]:>[7,9], <[2]
BB [7:_GLOBAL_ENSURE_BLOCK__0:19]:>[9], <[4,6]
BB [9:CL1_LBL_8:-1]:<[1,4,6,7]

Instructions:
BB [1:CL1_LBL_4:-1]
    %cl_1_4 = copy(nil)
    %t_x_7 = copy(%cl_1_4)
    %cl_1_5 = copy(%cl_1_4)
    %cl_1_6 = copy(%cl_1_4)
    %cl_1_8 = copy(%cl_1_4)
    %cl_1_9 = copy(%cl_1_4)
    %cl_1_8 = save_binding_viz()
    %cl_1_9 = push_block_frame()
    push_block_binding()
    update_block_state(%self)
    %t_x_7 = binding_load(x(1:0) ;scope: foo_CLOSURE_1)
    prepare_no_block_args()
BB [2:CL1_LBL_5:-1]
    line_num(;n: 3)
    b_true(CL1_LBL_0:13, nil)
BB [4:CL1_LBL_6:-1]
    break(nil ;scope_name: foo)
BB [6:CL1_LBL_0:13]
    line_num(;n: 4)
    %cl_1_4 = call_1f(%t_x_7, Fixnum:0 ;n:[], t:NO, cl:false)
    %t_x_7 = copy(%cl_1_4)
    binding_store(%t_x_7, x(1:0) ;scope_name: foo_CLOSURE_1)
    pop_binding()
    restore_binding_viz(%cl_1_8)
    pop_block_frame(%cl_1_9)
    return(%cl_1_4)
BB [7:_GLOBAL_ENSURE_BLOCK__0:19]
    %t_x_7 = binding_load(x(1:0) ;scope: foo_CLOSURE_1)
    %cl_1_5 = recv_jruby_exc()
    %cl_1_6 = runtime_helper(%cl_1_5 ;method: HANDLE_BREAK_AND_RETURNS_IN_LAMBDA)
    rethrow_saved_exc_in_lambda()
    binding_store(%t_x_7, x(1:0) ;scope_name: foo_CLOSURE_1)
    pop_binding()
    restore_binding_viz(%cl_1_8)
    pop_block_frame(%cl_1_9)
    binding_store(%t_x_7, x(1:0) ;scope_name: foo_CLOSURE_1)
    return(%cl_1_6)
BB [9:CL1_LBL_8:-1]
    binding_store(%t_x_7, x(1:0) ;scope_name: foo_CLOSURE_1)
    pop_binding()
    restore_binding_viz(%cl_1_8)
    pop_block_frame(%cl_1_9)
    return(nil)

Both BB4 and BB6 show rescues in the GEB BB7, so it seems like block protocol is ok here. However there's also a rethrow_saved_exc_in_lambda and the commit @nahi reported (0d35995) does add that operation. Perhaps there's just an ordering problem in the GEB? The rethrow should come after the post-body protocol, shouldn't it?

@enebo
Copy link
Member

enebo commented Jan 6, 2016

I did not work on this at all so I don't know what is wrong but I am surprised that rethrow_saved_exc_in_lambda does not have OpFlags.f_can_raise_exception or OpFlags.f_is_exception for it's operation. It is suppose to throw right? @subbuss

@headius
Copy link
Member

headius commented Jan 6, 2016

I do not see that ACP even checks for f_can_raise_exception or f_is_exception. It seems like it would be more robust if, instead of guessing at scope type and "backing up" it just iterated through instructions until the first "potential exit" from the block. That would be where to add the protocol.

I've got a patch that works for this case, but I'm not sure what else it might affect yet:

diff --git a/core/src/main/java/org/jruby/ir/passes/AddCallProtocolInstructions.java b/core/src/main/java/org/jruby/ir/passes/AddCallProtocolInstructions.java
index ad04604..facd40d 100644
--- a/core/src/main/java/org/jruby/ir/passes/AddCallProtocolInstructions.java
+++ b/core/src/main/java/org/jruby/ir/passes/AddCallProtocolInstructions.java
@@ -135,41 +135,41 @@ public class AddCallProtocolInstructions extends CompilerPass {
             //
             // Allocate GEB if necessary for popping
             BasicBlock geb = cfg.getGlobalEnsureBB();
             boolean gebProcessed = false;
             if (geb == null) {
                 Variable exc = scope.createTemporaryVariable();
                 geb = new BasicBlock(cfg, Label.getGlobalEnsureBlockLabel());
                 geb.addInstr(new ReceiveJRubyExceptionInstr(exc)); // JRuby Implementation exception handling
                 geb.addInstr(new ThrowExceptionInstr(exc));
                 cfg.addGlobalEnsureBB(geb);
             }

             // Pop on all scope-exit paths
             for (BasicBlock bb: cfg.getBasicBlocks()) {
                 Instr i = null;
                 ListIterator<Instr> instrs = bb.getInstrs().listIterator();
                 while (instrs.hasNext()) {
                     i = instrs.next();
                     // Breaks & non-local returns in blocks will throw exceptions
                     // and pops for them will be handled in the GEB
-                    if (!bb.isExitBB() && i instanceof ReturnInstr) {
+                    if (!bb.isExitBB() && i instanceof ReturnInstr || i instanceof RethrowSavedExcInLambdaInstr) {
                         if (requireBinding) fixReturn(scope, (ReturnInstr)i, instrs);
                         // Add before the break/return
                         instrs.previous();
                         popSavedState(scope, bb == geb, requireBinding, requireFrame, savedViz, savedFrame, instrs);
                         if (bb == geb) gebProcessed = true;
                         break;
                     }
                 }

                 if (bb.isExitBB() && !bb.isEmpty()) {
                     // Last instr could be a return -- so, move iterator one position back
                     if (i != null && i instanceof ReturnInstr) {
                         if (requireBinding) fixReturn(scope, (ReturnInstr)i, instrs);
                         instrs.previous();
                     }
                     popSavedState(scope, bb == geb, requireBinding, requireFrame, savedViz, savedFrame, instrs);
                     if (bb == geb) gebProcessed = true;
                 } else if (!gebProcessed && bb == geb) {
                     // Add before throw-exception-instr which would be the last instr
                     if (i != null) {

@headius
Copy link
Member

headius commented Jan 6, 2016

Note that popSavedState does appear to back up one, so it seems like it should have put the protocol before the RethrowSavedExc instruction...but it didn't.

    private void popSavedState(IRScope scope, boolean isGEB, boolean requireBinding, boolean requireFrame, Variable savedViz, Variable savedFrame, ListIterator<Instr> instrs) {
        if (scope instanceof IRClosure && isGEB) {
            // Add before RethrowSavedExcInLambdaInstr
            instrs.previous();
        }
        if (requireBinding) instrs.add(new PopBindingInstr());
        if (scope instanceof IRClosure) {
            instrs.add(new RestoreBindingVisibilityInstr(savedViz));
            instrs.add(new PopBlockFrameInstr(savedFrame));
        } else {
            if (requireFrame) instrs.add(new PopMethodFrameInstr());
        }
    }

@subbuss
Copy link
Contributor

subbuss commented Jan 6, 2016

@headius that IR looks broken .. as the commit message for that commit (0d35995) shows, rethrow was introduced precisely for the reason that is still broken .. to pop state before exceptions are thrown. So, something is broken in how the instructions are added in AddACP.

@subbuss
Copy link
Contributor

subbuss commented Jan 6, 2016

Pasting IRC comments since I will be moving in/out of irc ..

<subbu: headius, my original patch is broken .. 
<subbu> becuase i add these 2 instrs in ir builder
<subbu>         addInstr(new RethrowSavedExcInLambdaInstr());
<subbu>         addInstr(new ReturnInstr(ret));
<subbu> but only back up one.
<subbu> so, the pop business is happening between those 2 instrs.
<subbu> i guess i didn't add the right tests there.
<subbu> tests should have caught this.

@headius your fix may not handle all cases. But, in any case, yes, redoing the code in AddACP to add the pops in all the required places a bit more robustly would be a good thing. Note that in the RethrowSavedExcInLambda case, there is a return that shows up after it .. so, the pops shouldn't be added twice.

@subbuss
Copy link
Contributor

subbuss commented Jan 6, 2016

@enebo yes .. a bug reg. missing flags as well.

headius added a commit that referenced this issue Jan 6, 2016
Temporary fix for #3577. The longer term fix will be to make the
instruction insert logic in AddCallProtocol less sensitive to the
contents of exit blocks.
@headius
Copy link
Member

headius commented Jan 6, 2016

This is fixed with a one-off change in f9c2c97. The better fix will be to make AddCallProtocol not be so sensitive to the contents of the exit blocks when it adds post-call logic.

@nahi The test case you reported runs green with my change. Thanks for bisecting; it made it much easier to figure out.

@headius headius closed this as completed Jan 6, 2016
@headius headius added this to the JRuby 9.0.5.0 milestone Jan 6, 2016
headius added a commit that referenced this issue Jan 6, 2016
@nahi
Copy link
Member Author

nahi commented Jan 7, 2016

Thanks for investigating it. I'd learn the internal from it :-)

But with the fix b56f3ca my repro still fails. This test includes something uncovered?

% jruby -v
jruby 9.0.5.0-SNAPSHOT (2.2.3) 2016-01-07 b56f3ca Java HotSpot(TM) 64-Bit Server VM 25.66-b17 on 1.8.0_66-b17 +jit [darwin-x86_64]

% jruby -Ilib test/test_http_cookie_jar.rb
...
45 tests, 58 assertions, 1 failures, 21 errors, 0 pendings, 0 omissions, 0 notifications
51.1111% passed

% jruby --dev -Ilib test/test_http_cookie_jar.rb
...
45 tests, 180 assertions, 0 failures, 0 errors, 0 pendings, 0 omissions, 0 notifications
100% passed

@nahi nahi reopened this Jan 7, 2016
@headius
Copy link
Member

headius commented Jan 7, 2016

I think it's more likely that my fix for the fix unfixed the fix :-( I'll spend more time on it tonight or tomorrow and get it right.

headius added a commit that referenced this issue Jan 7, 2016
The problems in #3577 stemmed from the introduction of a second
exit instruction into global ensure blocks (rethrow saved exc).
Logic elsewhere in our passes that dealt with the GEB all assumed
that there would be exactly one control-transfer instruction at
the end of the GEB, and inserted various logic before this point:

* Stores of modified variables into the current binding.
* Pops of binding and frame at the end of the method body.

Once there were two instructions, it becamse a mess to know where
to insert these instructions.

This change modifies the "rethrow" instruction to itself be a
special case of "return" that may throw a saved exception. In both
cases, it is unrolling at least the current stack frame, and this
allows us to have a single instruction to do both normal returns
and saved exception rethrows in the GEB.

This change reverts previous fixes for #3577 that attempted to
work around the double-exit.
@headius
Copy link
Member

headius commented Jan 7, 2016

Ok, I made a new fix by removing my changes and modifying @subbu's "rethrow" change from 0d35995.

All these problem stemmed from there being two exits from the GEB and none of our GEB logic handling that right (because they're all fragile and make assumptions about the structure of the GEB).

My change was to combine "return" and "rethrow" into a single instruction so these assumptions would still be true.

This still doesn't feel like the long term fix. All these places that do "instruction math" to splice in additional code need to be reevaluated and made more robust in case we have other exits we need to add.

Alternatively, we could say that there should only ever be one exit from a GEB and enforce that somehow.

@subbuss @enebo Obviously looking forward to your review of this new fix.

@headius
Copy link
Member

headius commented Jan 7, 2016

@nahi Please retest with JRuby master. It passes your tests again for me and I confirmed (via -Xjit.logging=true) that it is successfully jitting every method and block it encounters.

@subbuss
Copy link
Contributor

subbuss commented Jan 7, 2016

@headius .. I like this fix.

@nahi
Copy link
Member Author

nahi commented Jan 7, 2016

@headius Thanks for the fix. I confirmed 86884e7 fixed the test, and it also fixed httpclient test I was observing.

@nahi nahi closed this as completed Jan 7, 2016
@headius headius added the jit label Jan 7, 2016
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

4 participants