JRuby

Ok, so I figured out where the problem lies. It's not in view rendering...it's in the i18n gem.

In JRuby 1.6, we moved to using JVM-level facilities for generating exception backtraces. These facilities are considerably more expensive than the artificial backtraces we had been maintaining before...not incredibly expensive, but not free or as cheap as they used to be by any means. If applications and libraries use exceptions for exceptional error cases, it's not a big deal.

I ran a profile of your app and saw that it was spending as much as 40% of its time generating backtraces. That's a tremendous amount; even a 1000-call-deep trace (which is several thousand Java frames) takes only a couple ms to generate.

~/projects/jruby/tmp/case_center ➔ jruby -rbenchmark -e "def foo(a); if a > 1000; 1000.times { begin; raise; rescue Exception; end }; else; foo(a + 1); end; end; 10.times { puts Benchmark.measure { foo(1) } }"
  1.721000   0.000000   1.721000 (  1.602000)
  1.586000   0.000000   1.586000 (  1.586000)
  1.562000   0.000000   1.562000 (  1.562000)
  1.565000   0.000000   1.565000 (  1.565000)
  1.564000   0.000000   1.564000 (  1.564000)
  1.577000   0.000000   1.577000 (  1.577000)
  1.563000   0.000000   1.563000 (  1.563000)
  1.555000   0.000000   1.555000 (  1.555000)
  1.552000   0.000000   1.552000 (  1.552000)
  1.560000   0.000000   1.560000 (  1.560000)

In order for exceptions to be impacting performance, there would have to be hundreds of them generated and thrown away. So I added logging to exception backtrace generation, to see where they were coming from. It turns out that the vast majority were from the following code in i18n:

      def translate(locale, key, options = {})
        raise InvalidLocale.new(locale) unless locale
        entry = key && lookup(locale, key, options[:scope], options)

        if options.empty?
          entry = resolve(locale, key, entry, options)
        else
          count, default = options.values_at(:count, :default)
          values = options.except(*RESERVED_KEYS)
          entry = entry.nil? && default ?
            default(locale, key, default, options) : resolve(locale, key, entry, options)
        end

        raise(I18n::MissingTranslationData.new(locale, key, options)) if entry.nil?
        entry = entry.dup if entry.is_a?(String)

        entry = pluralize(locale, entry, count) if count
        entry = interpolate(locale, entry, values) if values
        entry
      end

...

        def resolve(locale, object, subject, options = {})
          return subject if options[:resolve] == false
          case subject
          when Symbol
            return I18n.translate(subject, options.merge(:locale => locale, :raise => true))
          when Proc
            date_or_time = options.delete(:object) || object
            return resolve(locale, object, subject.call(date_or_time, options))
          else
            return subject
          end
        rescue MissingTranslationData
          nil
        end

Essentially, it's using exceptions as flow control here; the exception itself is never used, and the resulting overhead from all those backtraces gives us the performance you (and I) see. To make matters worse, it seems to be raising this exception repeatedly rather than caching some result somewhere. Even if someone were to claim JRuby's backtrace generation is too slow, this is still a serious code antipattern.

With those exceptions being raised, we end up with the following performance similar to yours:

Started GET "/cases/new?system=financial&type=consumer" for 0:0:0:0:0:0:0:1%0 at Wed Feb 23 21:50:08 -0600 2011
  Processing by CasesController#new as */*
  Parameters: {"system"=>"financial", "type"=>"consumer"}
Rendered config/systems/Financial/views/cases/_address_fields.html.haml (189.0ms)
Rendered config/systems/Financial/views/cases/_consumer_fields.html.haml (435.0ms)
Rendered config/systems/Financial/views/cases/_address_fields.html.haml (185.0ms)
Rendered config/systems/Financial/views/cases/_consumer_fields.html.haml (225.0ms)
Rendered config/systems/Financial/views/cases/_applicants_infos.html.haml (876.0ms)
Rendered cases/new.html.haml within layouts/application (887.0ms)
Completed 200 OK in 1071ms (Views: 922.0ms | ActiveRecord: 0.0ms)

I modified i18n to not raise exceptions but instead use catch/throw to unroll the stack, and the performance difference is pretty shocking:

Started GET "/cases/new?system=financial&type=consumer" for 0:0:0:0:0:0:0:1%0 at Wed Feb 23 21:51:20 -0600 2011
  Processing by CasesController#new as */*
  Parameters: {"system"=>"financial", "type"=>"consumer"}
Rendered config/systems/Financial/views/cases/_address_fields.html.haml (21.0ms)
Rendered config/systems/Financial/views/cases/_consumer_fields.html.haml (68.0ms)
Rendered config/systems/Financial/views/cases/_address_fields.html.haml (22.0ms)
Rendered config/systems/Financial/views/cases/_consumer_fields.html.haml (27.0ms)
Rendered config/systems/Financial/views/cases/_applicants_infos.html.haml (167.0ms)
Rendered cases/new.html.haml within layouts/application (177.0ms)
Completed 200 OK in 364ms (Views: 213.0ms | ActiveRecord: 0.0ms)

This is not quite back to 1.5.6 performance, but it's close. 1.6 with the fixed i18n seems to average from 290ms to 400ms after a few requests, where 1.5.6 averages 200ms to 350ms. And 1.5.6 without the fixed backtraces There are additional exceptions being raised and swallowed by Rails that I'll also look into.

It's also interesting to note that 1.6 with the fixed i18n performs about the same as 1.5.6 with the unfixed i18n, so simply fixing i18n may get your environment back to where it was with 1.5.6. The new crusade I must embark upon is to convince rubyists that generating hundreds of throw-away exceptions per request is a bad idea, and they should fix their code.

Thanks for the detailed explanation. A ticket has been opened on the i18n github : https://github.com/svenfuchs/i18n/issues/82

Perhaps as a temporary measure we could override fillInStackTrace on RaiseException and allow individual Ruby exception classes/hierarchies to opt out of stacktrace generation (with the default being to call super). The attribute would be settable from the Ruby side, so that people could add small bits of code in an initializer to benefit from a speedup in the JRuby case.

I've started removing the use of exceptions from the I18n backend modules we ship. See https://github.com/svenfuchs/i18n/issues/#issue/82 and https://github.com/svenfuchs/i18n/commit/35f3cf35544140f3600a167ceca2ac7705ccbead

Just for the record, exception meta data actually is being used, e.g. in Rails' translation (`t`) view helper. This doesn't mean it needs to be an Exception instance, but it's been part of the public API for a long time, so this might need more work.

Also, it is true that the Simple backend implementation does not cache anything by itself, but there's a Cache module that one can include to the Simple backend: https://github.com/svenfuchs/i18n/blob/master/lib/i18n/backend/cache.rb

Nick: Yes, that's actually a good idea. RaiseException already overrides fillInStackTrace, so that much is already done. The additional work would be to add a way for exception subclasses to disable backtraces. I mentioned this on the i18n github issue too. It would work similar to fillInStackTrace, with "raise" checking for something like "create_backtrace" on the exception object and using that instead of normal generation.

I am of two minds on making such an enhancement. I believe it would largely solve the issue of exceptions used as flow control having too much performance overhead, and they would then have no more of a performance hit than catch/throw. But we would have to get it approved in regular Ruby, which has a smaller (but still very large) perf hit from backtraces, and we would in a way be encouraging (or at least facilitating) the use of exceptions for flow control, something that's very rarely a good pattern (and by saying "very rarely", perhaps I answered my own question...sometimes there's no other way, and it would be nice to opt-out of expensive backtraces).

In any case, if we don't want to roll back the perf gains in JRuby that the new backtrace logic has given us, we'll have to get users to change their code and habits. It is an unfortunate turn of events

Sven: Do you have an example of using the Cache module? Does it avoid this heavy raising of exceptions? It might be an excellent userland workaround for backtrace performance issues on newer implementations.

If we are unable to get ruby-core to support this we can always make a gem which exposes an API which just does what MRI would do today and we would call our enhanced cheap syntax. Having a gem would also be self-documenting and also probably be self-advertising once we get a few larger projects using it.

I just wanted to confirm that Sven latest changes to the i18n solve the performance issue. More info at : https://github.com/svenfuchs/i18n/issues/#issue/82/comment/820979

Actually I (re)discovered that the three-argument form of Kernel#raise can be used to short-circuit backtrace generation:

raise SomeException, some_arg, nil

Here, some_arg will be pass to SomeException#initialize, and nil will be used for the backtrace. In JRuby 1.6.0.RC3 and higher, we will then not generate a backtrace, cutting out the performance hit you see here.

It obviously still requires people to adapt their code, but at least we have a way to opt-out of backtrace generation without adding anything to Ruby. Yay!

I'm going to mark this resolved/fixed, since we have done a little work, and there's no further improvement possible.

I did some cleanup in recent commits to refactor backtrace logic to try to reduce the perf hit as much as possible. On my machine, it takes about 1.5ms now to generate a full-length backtrace with default JVM settings, with the manipulation we do deferred until the backtrace is actually needed. I also made the modification that the three-arg Kernel#raise does not generate an internal backtrace anymore, so it will be a good workaround.

I also still plan to write up a blog post on all this, to educate Rubyists and give them some new tools to avoid the bad pattern of exceptions-as-flow-control, or to use the opt-out if they really must use exceptions this way.

On i18n's side this should be fixed in 0.6.0: https://github.com/svenfuchs/i18n/issues/82

Thanks, guys!