[jruby-dev] [jira] (JRUBY-6766) --profile slows down Array#join , which distorts profiling results

[Andrew Grimm (JIRA)]

Andrew Grimm created JRUBY-6766 --profile slows down Array#join , which distorts profiling results Issue Type: Bug Affects Versions: JRuby 1.6.7 Assignee: Unassigned Components: Performance Created: 09/Jul/12 12:21 AM Description: When code is being profiled, Array#join becomes slower. In addition, the slowness of Array#join is recorded in the profile data, rather than treated as overhead. cat > array_join.rb array = Array.new(100_000, nil) array.join $ cat > array_to_s.rb array = Array.new(100_000, nil) array.map(&:to_s) $ ruby --1.9 --version jruby 1.6.7.2 (ruby-1.9.2-p312) (2012-05-01 26e08ba) (Java HotSpot(TM) 64-Bit Server VM 1.7.0_04) [darwin-x86_64-java] $ time ruby --1.9 /dev/null real 0m1.000s user 0m1.471s sys 0m0.089s $ time ruby --1.9 array_join.rb real 0m1.099s user 0m1.834s sys 0m0.095s $ time ruby --1.9 array_to_s.rb real 0m1.173s user 0m1.741s sys 0m0.092s $ time ruby --1.9 --profile /dev/null 2> dev_null.txt real 0m1.316s user 0m2.128s sys 0m0.110s $ time ruby --1.9 --profile array_join.rb 2> array_join.txt real 0m5.769s user 0m7.145s sys 0m0.141s $ time ruby --1.9 --profile array_to_s.rb 2> array_to_s.txt real 0m1.430s user 0m2.410s sys 0m0.108s # array_join.txt main thread profile results: Total time: 5.19 total self children calls method ---------------------------------------------------------------- 4.47 0.30 4.17 4 Array#join 4.07 4.04 0.03 100002 BasicObject#method_missing 0.69 0.10 0.59 56 Kernel#require 0.29 0.00 0.29 15 Kernel#require 0.08 0.06 0.02 200014 Kernel#respond_to? 0.06 0.06 0.00 1 Time.now 0.05 0.01 0.04 53 Object.method_added 0.04 0.00 0.04 111 Object.method_added 0.03 0.01 0.03 6 Array#each 0.03 0.03 0.00 100002 NoMethodError#initialize 0.02 0.01 0.01 12 JavaUtilities#get_proxy_or_package_under_package 0.02 0.02 0.00 100000 NilClass#to_s 0.02 0.01 0.01 30 Module#module_eval 0.02 0.02 0.00 200013 Kernel#respond_to_missing? 0.02 0.00 0.02 13 Class#new 0.02 0.02 0.00 32 Module#initialize_copy 0.02 0.02 0.00 184 String#=~ 0.01 0.01 0.00 1 Array#initialize 0.01 0.00 0.01 5 Java::Java.method_missing 0.01 0.00 0.01 1 Gem.win_platform? 0.01 0.00 0.01 1 Enumerable#find 0.01 0.01 0.00 16 Module#private 0.01 0.01 0.00 1 Kernel#trap 0.01 0.01 0.00 85 Module#alias_method 0.01 0.00 0.00 25 Gem::Deprecate#deprecate 0.00 0.00 0.00 1 Java::OrgJrubyLexerYacc.method_missing 0.00 0.00 0.00 31 Module#attr_accessor 0.00 0.00 0.00 18 JavaUtilities#get_package_module_dot_format 0.00 0.00 0.00 1 Module#instance_methods 0.00 0.00 0.00 14 Module#include 0.00 0.00 0.00 2 Java::OrgJruby.method_missing 0.00 0.00 0.00 70 Module#undef_method 0.00 0.00 0.00 16 Kernel#java 0.00 0.00 0.00 2 Gem::Requirement.default 0.00 0.00 0.00 1 Java::JavaUtil.method_missing 0.00 0.00 0.00 2 Gem::Requirement#initialize 0.00 0.00 0.00 1 Hash#reject 0.00 0.00 0.00 10 JavaPackageModuleTemplate.__block__ 0.00 0.00 0.00 87 BasicObject#!= 0.00 0.00 0.00 1 Java::JavaNio.method_missing 0.00 0.00 0.00 2 JavaInterfaceTemplate.append_features 0.00 0.00 0.00 1 Java::Org.method_missing 0.00 0.00 0.00 2 Array#map! 0.00 0.00 0.00 2 Gem::Requirement.parse 0.00 0.00 0.00 32 Module#define_method 0.00 0.00 0.00 2 Kernel#org 0.00 0.00 0.00 4 Kernel.method_added 0.00 0.00 0.00 1 Enumerable#sort_by 0.00 0.00 0.00 1 JavaUtilities#get_package_module 0.00 0.00 0.00 2 Gem::Version#initialize # array_to_s.txt main thread profile results: Total time: 0.84 total self children calls method ---------------------------------------------------------------- 0.70 0.11 0.59 56 Kernel#require 0.29 0.00 0.29 15 Kernel#require 0.12 0.08 0.03 4 Array#collect 0.06 0.06 0.00 1 Time.now 0.04 0.01 0.04 53 Object.method_added 0.04 0.00 0.04 111 Object.method_added 0.03 0.01 0.03 6 Array#each 0.03 0.03 0.00 100000 NilClass#to_s 0.02 0.01 0.01 12 JavaUtilities#get_proxy_or_package_under_package 0.02 0.02 0.01 30 Module#module_eval 0.02 0.02 0.00 32 Module#initialize_copy 0.02 0.00 0.02 13 Class#new 0.02 0.02 0.00 184 String#=~ 0.01 0.01 0.00 1 Array#initialize 0.01 0.00 0.01 5 Java::Java.method_missing 0.01 0.00 0.01 1 Gem.win_platform? 0.01 0.00 0.01 1 Enumerable#find 0.01 0.01 0.00 16 Module#private 0.01 0.01 0.00 1 Kernel#trap 0.01 0.01 0.00 85 Module#alias_method 0.01 0.00 0.00 25 Gem::Deprecate#deprecate 0.00 0.00 0.00 2 Java::OrgJruby.method_missing 0.00 0.00 0.00 1 Java::OrgJrubyLexerYacc.method_missing 0.00 0.00 0.00 1 Hash#reject 0.00 0.00 0.00 31 Module#attr_accessor 0.00 0.00 0.00 18 JavaUtilities#get_package_module_dot_format 0.00 0.00 0.00 87 BasicObject#!= 0.00 0.00 0.00 1 Module#instance_methods 0.00 0.00 0.00 14 Module#include 0.00 0.00 0.00 70 Module#undef_method 0.00 0.00 0.00 16 Kernel#java 0.00 0.00 0.00 2 Gem::Requirement.default 0.00 0.00 0.00 2 Gem::Requirement#initialize 0.00 0.00 0.00 1 Java::JavaUtil.method_missing 0.00 0.00 0.00 10 JavaPackageModuleTemplate.__block__ 0.00 0.00 0.00 1 Java::JavaNio.method_missing 0.00 0.00 0.00 1 Java::Org.method_missing 0.00 0.00 0.00 2 JavaInterfaceTemplate.append_features 0.00 0.00 0.00 2 Array#map! 0.00 0.00 0.00 2 Gem::Requirement.parse 0.00 0.00 0.00 32 Module#define_method 0.00 0.00 0.00 1 Enumerable#sort_by 0.00 0.00 0.00 2 Kernel#org 0.00 0.00 0.00 4 Kernel.method_added 0.00 0.00 0.00 1 JavaUtilities#get_package_module 0.00 0.00 0.00 2 Gem::Version#initialize 0.00 0.00 0.00 223 Class#inherited 0.00 0.00 0.00 2 Comparable#== 0.00 0.00 0.00 432 Module#method_added 0.00 0.00 0.00 2 Gem::Requirement#<=> Environment: jruby 1.6.7.2 (ruby-1.9.2-p312) (2012-05-01 26e08ba) (Java HotSpot(TM) 64-Bit Server VM 1.7.0_04) [darwin-x86_64-java] Project: JRuby Labels: jruby Priority: Major Reporter: Andrew Grimm

This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators. For more information on JIRA, see: http://www.atlassian.com/software/jira

--------------------------------------------------------------------- To unsubscribe from this list, please visit: http://xircles.codehaus.org/manage_email