Details

    • Type: Bug Bug
    • Status: Resolved Resolved
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: JRuby 1.6RC3
    • Fix Version/s: JRuby 1.7.0.RC1
    • Component/s: None
    • Labels:
      None
    • Environment:
    • Number of attachments :
      0

      Description

      When I running the specs for a (large) Rails app with the profiler and sample enabled I'm getting a Java stack trace thrown at exit. The spec runs normally, although it does take a very long time to start; much longer than JRuby 1.4 or 1.5.

      $ JRUBY_OPTS='--profile.flat --sample' spec spec/an_ordinary_spec.rb

      .................................
      Finished in 0.661 seconds

      33 examples, 0 failures

      main thread profile results:
      Total time: 66.40

      total self children calls method
      ----------------------------------------------------------------
      65.55 0.02 65.53 11726 Kernel#require
      65.54 0.00 65.54 59 Kernel#load
      [snip]
      8.38 0.00 8.38 1 Bundler.require
      8.38 0.00 8.38 1 Bundler::Runtime#require
      6.59 0.00 6.59 1 Rails::Initializer#load_application_initializers
      AbstractProfilePrinter.java:96:in `getMethodName': java.lang.ArrayIndexOutOfBoundsException: 105076
      from AbstractProfilePrinter.java:86:in `methodName'
      from FlatProfilePrinter.java:78:in `printProfile'
      from Ruby.java:2770:in `tearDown'
      from Ruby.java:2693:in `tearDown'
      from Main.java:201:in `internalRun'
      from Main.java:164:in `run'
      from Main.java:148:in `run'
      from Main.java:128:in `main'

      I guess that it must be confused by an anonymous Ruby class, or one that has been garbage-collected. I can reproduce this locally, but it does seem to be triggered by this application's code (or its sheer size). I haven't been able to reproduce it outside of the app environment.

        Activity

        Hide
        Charles Oliver Nutter added a comment -

        This seems like it's probably related to the limit on how many methods we'll profile; that limit is currently set to 100000, but it seems like it's not working quite right.

        I'll play with this a bit today and see if I can make the limit sufficiently high and working properly.

        Show
        Charles Oliver Nutter added a comment - This seems like it's probably related to the limit on how many methods we'll profile; that limit is currently set to 100000, but it seems like it's not working quite right. I'll play with this a bit today and see if I can make the limit sufficiently high and working properly.
        Hide
        Charles Oliver Nutter added a comment -

        I'm going to be optimistic and assume recent fixes on master have cured the last issues here.

        The primary of these fixes repaired how we limit the number of profiled methods, so that it would not blow up if it reached the upper limit. Another fix I'm making momentarily will work harder to get the "real" method being profiled, which should avoid intermediate wrappers (like aliases, etc) from confusing the profile. The last change allows configuring the upper bound of profilable methods.

        If you hit the upper bound, you should see the following message logged somewhere:

        warning: method count exceeds max of 100000; no new methods will be profiled
        

        You can bump up the limit by passing -Xprofile.max.methods=###### to JRuby or -J-Djruby.profile.max.methods=###### to the JVM where the default is 100000.

        Show
        Charles Oliver Nutter added a comment - I'm going to be optimistic and assume recent fixes on master have cured the last issues here. The primary of these fixes repaired how we limit the number of profiled methods, so that it would not blow up if it reached the upper limit. Another fix I'm making momentarily will work harder to get the "real" method being profiled, which should avoid intermediate wrappers (like aliases, etc) from confusing the profile. The last change allows configuring the upper bound of profilable methods. If you hit the upper bound, you should see the following message logged somewhere: warning: method count exceeds max of 100000; no new methods will be profiled You can bump up the limit by passing -Xprofile.max.methods=###### to JRuby or -J-Djruby.profile.max.methods=###### to the JVM where the default is 100000.
        Hide
        Charles Oliver Nutter added a comment -

        The additional change:

        commit c048cc34dd94958b7ec39b3ba37281b8e2be5b5e
        Author: Charles Oliver Nutter <headius@headius.com>
        Date:   Thu Aug 30 11:18:34 2012 -0500
        
            Make profiling dig deeper to get the "real" method being called.
        
        :100644 100644 6c49169... 3c149cf... M	src/org/jruby/internal/runtime/methods/ProfilingDynamicMethod.java
        
        Show
        Charles Oliver Nutter added a comment - The additional change: commit c048cc34dd94958b7ec39b3ba37281b8e2be5b5e Author: Charles Oliver Nutter <headius@headius.com> Date: Thu Aug 30 11:18:34 2012 -0500 Make profiling dig deeper to get the "real" method being called. :100644 100644 6c49169... 3c149cf... M src/org/jruby/internal/runtime/methods/ProfilingDynamicMethod.java
        Hide
        Marek Kowalcze added a comment -

        thanks Charles, is this commit going to be applied to 1.6.7 branch also?

        Show
        Marek Kowalcze added a comment - thanks Charles, is this commit going to be applied to 1.6.7 branch also?
        Hide
        Charles Oliver Nutter added a comment -

        I had not planned on it, but if you put together a working pull request I'll merge it.

        Show
        Charles Oliver Nutter added a comment - I had not planned on it, but if you put together a working pull request I'll merge it.

          People

          • Assignee:
            Charles Oliver Nutter
            Reporter:
            Rob Hunter
          • Votes:
            1 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: