Details

    • Type: Bug Bug
    • Status: Closed Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: JRuby 1.6RC1
    • Fix Version/s: JRuby 1.6RC2
    • Component/s: None
    • Labels:
      None
    • Number of attachments :
      0

      Description

      For example, the output of `ruby --profile.graph -rubygems -e'require "bundler"'`

      https://gist.github.com/779066

      Note the entries for 'Date.new!' and 'Gem.searcher', and the definition of Gem.searcher:

        def self.searcher
          MUTEX.synchronize do
            @searcher ||= Gem::GemPathSearcher.new
          end
        end
      

      It seems clear that where 'Date.new!' appears in the profile output, it should actually be 'Gem::GemPathSearcher.new'.

        Activity

        Hide
        Charles Oliver Nutter added a comment -

        I think the problem here is that the the new! method for Date and the new method for GemPathSearcher are resolving to the same actual method object in-memory in JRuby. As a result, we go with the first one defined, and report all future results with that method's name.

        Looking into it.

        Show
        Charles Oliver Nutter added a comment - I think the problem here is that the the new! method for Date and the new method for GemPathSearcher are resolving to the same actual method object in-memory in JRuby. As a result, we go with the first one defined, and report all future results with that method's name. Looking into it.
        Hide
        Charles Oliver Nutter added a comment -

        Ok, this might be tricky to fix, but it would be nice. I think what we need to do is expand the profile gathering to consider both the target class's ID and the method serial number. The issue is something like this:

        Given the following code

        class Foo
          def something; end
        end
        
        class Bar < Foo; end
        class Baz < Foo; end
        

        calls to Bar#something or Baz#something will show up in profiles as always being Foo#something. In this case, it's not as misleading, but in the case of core methods inherited by user-created classes, it can be very strange.

        Consider, for example, the following:

        ~/projects/jruby &#10132; jruby --profile -e "class Foo; end; class Bar; end; 10000.times { Foo.new; Bar.new }"
        Total time: 0.03
        
             total        self    children       calls  method
        ----------------------------------------------------------------
              0.03        0.02        0.01           1  Fixnum#times
              0.01        0.01        0.00       20000  Class#new
              0.00        0.00        0.00       20000  Object#initialize
              0.00        0.00        0.00         147  Class#inherited
        

        Here, there are two different classes' objects being constructed: Foo and Bar instances. But they both use the default "new" implementation from JRuby, which results in only that method class+name showing up in profiles.

        Now this may actually be appropriate, if sometimes confusing. It's most tricky in the case of class methods like "new", since they're almost always shared across many different classes. But there's really only one method, and so profiles showing different methods could also be misleading.

        It also occurs to me as I write this that we may be unconditionally redefining the class+name for a given method, which causes Date.new! to get used for several other "new" calls. I'll look into that now as well.

        Show
        Charles Oliver Nutter added a comment - Ok, this might be tricky to fix, but it would be nice. I think what we need to do is expand the profile gathering to consider both the target class's ID and the method serial number. The issue is something like this: Given the following code class Foo def something; end end class Bar < Foo; end class Baz < Foo; end calls to Bar#something or Baz#something will show up in profiles as always being Foo#something. In this case, it's not as misleading, but in the case of core methods inherited by user-created classes, it can be very strange. Consider, for example, the following: ~/projects/jruby &#10132; jruby --profile -e "class Foo; end; class Bar; end; 10000.times { Foo.new; Bar.new }" Total time: 0.03 total self children calls method ---------------------------------------------------------------- 0.03 0.02 0.01 1 Fixnum#times 0.01 0.01 0.00 20000 Class#new 0.00 0.00 0.00 20000 Object#initialize 0.00 0.00 0.00 147 Class#inherited Here, there are two different classes' objects being constructed: Foo and Bar instances. But they both use the default "new" implementation from JRuby, which results in only that method class+name showing up in profiles. Now this may actually be appropriate, if sometimes confusing. It's most tricky in the case of class methods like "new", since they're almost always shared across many different classes. But there's really only one method, and so profiles showing different methods could also be misleading. It also occurs to me as I write this that we may be unconditionally redefining the class+name for a given method, which causes Date.new! to get used for several other "new" calls. I'll look into that now as well.
        Hide
        Charles Oliver Nutter added a comment -

        Ok, as neat as it might be to see the actual class against which a method is being called, I've decided that's out of scope for this bug.

        In the original case, the method being called is actually the default "new", indicated by Class#new normally. Because Date aliased that new to new!, it took over the serial number we use to identify that unique method, and all subsequent calls to the default new showed up as Date::new!.

        I made a minor modification to the name-gathering part of profiling to only use the first name encountered for a given serial number, since subsequent uses of the same serial number are all still the same method body. With this change, profiles are now making a lot more sense, and the Date.new! that was reported as a problem shows up properly as Class#new.

        commit 04ce8b7d9d93135fcf274389be392875a5b2d8cb
        Author: Charles Oliver Nutter <headius@headius.com>
        Date: Tue Jan 25 18:19:09 2011 -0600

        Fix JRUBY-5356: --profile.graph sometimes shows wrong methods

        • Only use the first name encountered for a given method serial, since aliases/etc will re-use them.
        Show
        Charles Oliver Nutter added a comment - Ok, as neat as it might be to see the actual class against which a method is being called, I've decided that's out of scope for this bug. In the original case, the method being called is actually the default "new", indicated by Class#new normally. Because Date aliased that new to new!, it took over the serial number we use to identify that unique method, and all subsequent calls to the default new showed up as Date::new!. I made a minor modification to the name-gathering part of profiling to only use the first name encountered for a given serial number, since subsequent uses of the same serial number are all still the same method body. With this change, profiles are now making a lot more sense, and the Date.new! that was reported as a problem shows up properly as Class#new. commit 04ce8b7d9d93135fcf274389be392875a5b2d8cb Author: Charles Oliver Nutter <headius@headius.com> Date: Tue Jan 25 18:19:09 2011 -0600 Fix JRUBY-5356 : --profile.graph sometimes shows wrong methods Only use the first name encountered for a given method serial, since aliases/etc will re-use them.

          People

          • Assignee:
            Charles Oliver Nutter
            Reporter:
            John Firebaugh
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: