Details

    • Type: Bug Bug
    • Status: Closed Closed
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: JRuby 1.6RC1, JRuby 1.6RC2
    • Fix Version/s: JRuby 1.6RC3
    • Component/s: None
    • Labels:
      None
    • Environment:
      Mac OS X 10.6
    • Number of attachments :
      0

      Description

      The rendering of rails views is consistently 4x slower in JRuby 1.6 vs JRuby 1.5.6

      JRuby 1.5.6:

      Rendered config/systems/Financial/views/cases/_address_fields.html.haml (116.0ms)
      Rendered config/systems/Financial/views/cases/_consumer_fields.html.haml (250.0ms)
      Rendered config/systems/Financial/views/cases/_address_fields.html.haml (77.0ms)
      Rendered config/systems/Financial/views/cases/_consumer_fields.html.haml (75.0ms)
      Rendered config/systems/Financial/views/cases/_applicants_infos.html.haml (510.0ms)
      

      Jruby 1.6.0RC:

      Rendered config/systems/Financial/views/cases/_address_fields.html.haml (467.0ms)
      Rendered config/systems/Financial/views/cases/_consumer_fields.html.haml (1045.0ms)
      Rendered config/systems/Financial/views/cases/_address_fields.html.haml (439.0ms)
      Rendered config/systems/Financial/views/cases/_consumer_fields.html.haml (506.0ms)
      Rendered config/systems/Financial/views/cases/_applicants_infos.html.haml (2054.0ms)
      

        Activity

        Hide
        Charles Oliver Nutter added a comment -

        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.

        Show
        Charles Oliver Nutter added a comment - 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.
        Hide
        Charles Oliver Nutter added a comment -

        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.

        Show
        Charles Oliver Nutter added a comment - 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.
        Hide
        Jean-Dominique Morani added a comment -

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

        Show
        Jean-Dominique Morani added a comment - Thanks for the detailed explanation. A ticket has been opened on the i18n github : https://github.com/svenfuchs/i18n/issues/82
        Hide
        Nick Sieger added a comment -

        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.

        Show
        Nick Sieger added a comment - 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.
        Hide
        Sven Fuchs added a comment -

        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

        Show
        Sven Fuchs added a comment - 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
        Hide
        Charles Oliver Nutter added a comment -

        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.

        Show
        Charles Oliver Nutter added a comment - 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.
        Hide
        Thomas E Enebo added a comment -

        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.

        Show
        Thomas E Enebo added a comment - 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.
        Hide
        Jean-Dominique Morani added a comment -

        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

        Show
        Jean-Dominique Morani added a comment - 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
        Hide
        Charles Oliver Nutter added a comment -

        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.

        Show
        Charles Oliver Nutter added a comment - 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.
        Charles Oliver Nutter made changes -
        Field Original Value New Value
        Status Open [ 1 ] Resolved [ 5 ]
        Assignee Thomas E Enebo [ enebo ] Charles Oliver Nutter [ headius ]
        Resolution Fixed [ 1 ]
        Charles Oliver Nutter made changes -
        Fix Version/s JRuby 1.6RC3 [ 17147 ]
        Fix Version/s JRuby 1.6 [ 17062 ]
        Hide
        Sven Fuchs added a comment -

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

        Thanks, guys!

        Show
        Sven Fuchs added a comment - On i18n's side this should be fixed in 0.6.0: https://github.com/svenfuchs/i18n/issues/82 Thanks, guys!
        Charles Oliver Nutter made changes -
        Status Resolved [ 5 ] Closed [ 6 ]

          People

          • Assignee:
            Charles Oliver Nutter
            Reporter:
            Jean-Dominique Morani
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: