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

Performance regression when going from 9.1.7.0 to 9.1.8.0 with virtus gem #4540

Closed
ivoanjo opened this issue Mar 20, 2017 · 14 comments
Closed

Comments

@ivoanjo
Copy link
Contributor

ivoanjo commented Mar 20, 2017

Environment

Rubies:

  • jruby 9.1.8.0 (2.3.1) 2017-03-06 90fc7ab Java HotSpot(TM) 64-Bit Server VM 25.121-b13 on 1.8.0_121-b13 +jit [linux-x86_64]
  • jruby 9.1.7.0 (2.3.1) 2017-01-11 68056ae Java HotSpot(TM) 64-Bit Server VM 25.121-b13 on 1.8.0_121-b13 +jit [linux-x86_64]

Kernel: Linux maruchan 4.10.0-11-generic #13-Ubuntu SMP Wed Mar 1 21:27:28 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux (Ubuntu 16.10).

Expected Behavior

After upgrading a from 9.1.7.0 to 9.1.8.0 I experienced a massive slowdown in processing time on a production application. I was able to reduce this to the usage of the virtus gem, but haven't yet been able to pin down the issue.

Test case (using benchmark-ips and virtus):

require 'benchmark/ips'
require 'virtus'

class TestModel
  include Virtus.model

  attribute :id, String
end

Benchmark.ips do |benchmark|
  benchmark.time = 15
  benchmark.warmup = 15

  benchmark.report(JRUBY_VERSION) { TestModel.new }

  benchmark.compare!
end

Actual Behavior

Output on 9.1.7.0:

Warming up --------------------------------------
             9.1.7.0    14.921k i/100ms
Calculating -------------------------------------
             9.1.7.0    182.901k (± 5.7%) i/s -      2.745M in  15.066610s

Output in 9.1.8.0:

Warming up --------------------------------------
             9.1.8.0   480.000  i/100ms
Calculating -------------------------------------
             9.1.8.0      5.149k (± 7.3%) i/s -     76.800k in  15.000051s
@headius
Copy link
Member

headius commented Mar 23, 2017

Wow, now that's a regression. I'll investigate.

@headius
Copy link
Member

headius commented Mar 23, 2017

Confirmed locally.

@headius
Copy link
Member

headius commented Mar 23, 2017

It appears something is causing a lot of stack traces to be generated. Here's top items from --sample:

         Stub + native   Method                        
 76.6%     0  +  2312    java.lang.Throwable.getStackTraceElement
 11.2%     0  +   338    java.lang.Throwable.fillInStackTrace
  0.6%     0  +    18    java.lang.String.intern

@headius
Copy link
Member

headius commented Mar 23, 2017

Ok, so here's the problem. The libraries involved are raising so many exceptions!

Here's the backtrace of one of these exceptions. This is happening on initialization of the Virtus object for every attribute that has a default value of nil. It attempts to coerce the value to a string using to_str.

Here's the rescue and swallow, from virtus/attribute/coercer.rb at line 31:

      def call(value)
        coercers[value.class].public_send(method, value)
      rescue ::Coercible::UnsupportedCoercion
        value
      end

JRuby 9.1.7.0 and a couple releases before that would see this as an opportunity to eliminate the stack trace generation, since the exception is not being used. However, because we can't always be certain what the rescue clause will do (rescue is supposed to call === on the given argument to compare it with the in-flight exception) we don't know whether the exception will escape.

JRuby 9.1.8.0 dealt with this problem by only doing the backtrace elimination when the rescue is blank, which implicitly means StandardError, since that's a core class and it would be extremely unlikely for anyone to modify its === method. Unfortunately that means we "regressed" on the performance of this benchmark, but I would argue it's not really our fault. These libraries will behave poorly (granted, not as poorly) on any implementation where exceptions are not guaranteed to be free (all implementations I know of).

There may be no simple fix for this one, I'm afraid.

A more complicated fix would involve having rescue blocks pre-inspect their arguments to see if they use a default === implementation, which would allow us to optimistically eliminate backtraces in more cases. It would not be foolproof, however, since things could change between the pre-inspection and the actual rescue.

Pinging @enebo for thoughts.

@enebo
Copy link
Member

enebo commented Mar 23, 2017

I think from an insanely pathological standpoint we cannot even use @headius solution if we go through n nested rescues where a non-standard === might redefine another exceptions === implementation while unwinding the stack. I think that is crazy sauce so perhaps we don't care if someone does that but even thinking about this solution opens up lots of unclear implementation details/concerns.

I have not looked at virtus code but I feel there might be a much faster way of doing this coercion (for us and MRI). Since this appears to be a custom exception at least this one can be changed. If they switched from rescue to catch then they will probably reduce the exception overheard by a factor of 10-15x (not sure what rescue happens within each coercer but this outer layer can be much faster). Something tells me exception handling in MRI is a large chunk of this coercion cost for simple things like nil not having to_str.

@headius
Copy link
Member

headius commented Mar 23, 2017

@ivoanjo I believe we must push back against either virtus or coercible here. Even though MRI handles this performance case better than us, and 9.1.7.0 was (incorrectly) able to remove the backtrace cost altogether, there's an obviously wrong pattern here: default nil values are failing to coerce every time. It seems like one of the two libraries needs to fix this, in virtus perhaps by not having nil default values or in coercible by not trying and failing to coerce things that don't need to be coerced.

@enebo There will always be pathological cases, but the worst case situation would be we elide some backtrace and that super-weird code doesn't get to see it. This is also assuming that it would actually need the backtrace in that pathological code. I think that's an acceptable risk.

The pseudo-code would be something like this

for Ruby:

begin
  do_call
rescue MyException
  swallow
end

we do:

begin
  if MyException is still MyException and its #=== is the built-in one
    set backtrace elimination flag
  end
  do_call
rescue MyException
  clear backtrace elimination flag
end

We could also make the backtrace elimination predicated on the condition "MyException resolves the same and has built-in ===" and make the decision lazily right before we attempt to generate a trace.

@enebo
Copy link
Member

enebo commented Mar 23, 2017

I just looked at Coercible and I have another thought but it may or may not be a good suggestion. Add a third argument to raise for the backtrace. We will execute even faster than an empty rescue (our big opto). That depends on whether Coercible finds it important for coercers to generate actual backtraces or not.

Ah I am only considering the raises Coercible does too. This is still an issue if you are blindly sending to nil with to_str. Nothing can eliminate that cost short of asking nil or just treating nil as a special object. Generically, I do wonder if :respond_to? + :send would be much slower than what is being done since MRI exception throws will undoubtedly be slower than that combo in the failure case.

@headius
Copy link
Member

headius commented Mar 23, 2017

@ivoanjo FYI you can pass -Xlog.backtraces to JRuby to see where backtraces are being generated, or just -Xlog.exceptions to see the exceptions being raised.

@enebo
Copy link
Member

enebo commented Mar 23, 2017

@headius yeah I think we can ignore the pathology in this case as well. I think the universe will explode from heat death before the scenario I described happens in real code.

@ivoanjo
Copy link
Contributor Author

ivoanjo commented Mar 24, 2017

Thanks @headius and @enebo for the help in analysing this!

I fully agree that generating exceptions in the hot path of the app is definitely not the way to go. I guess the next step is to report this to the gem developers and suggest that they adopt another way of doing these coercion checks.

@ioquatix
Copy link
Contributor

I once wrote a C++ parser that used exceptions for flow control to unwind the stack when it couldn't parse any further. It was insanely slow compared to a code path that just manually returned a failure token. It was a good lesson about using exceptions for flow control.

@headius
Copy link
Member

headius commented Mar 28, 2017

Just circling back to this because it's in my tabs...

Using exceptions for flow control isn't always so bad, but in this case the cost of also generating stack traces for those exceptions destroys all performance. So the workarounds/fixes available are:

  • Use catch/throw if you need to unroll stack to a known point without using exceptions.
  • Use a pre-allocated cached exception to do the unrolling. This will be roughly as fast as catch/throw.
  • Supply a dummy backtrace for the exception by passing a third argument to raise.

In this case, it seems there's also a possible improvement in how the default nil value is handled for these data structures.

@enebo I am inclined to close this as invalid, but perhaps we should keep it open for the smart backtrace elision work?

@enebo
Copy link
Member

enebo commented Mar 28, 2017

@headius yeah I think we can solve this with some pathological breakage but we should open up a new issue on the work we need to do. Otherwise we would end up needing to edit this issue and it would read pretty weird.

@headius
Copy link
Member

headius commented Mar 28, 2017

Opened #4551 for the additional backtrace work.

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