Skip to content

Instantly share code, notes, and snippets.

@filiptepper

filiptepper/profile #1

Created April 29, 2011 07:15
Show Gist options
  • Save filiptepper/947976 to your computer and use it in GitHub Desktop.
Save filiptepper/947976 to your computer and use it in GitHub Desktop.
Download ZIP
Bug in JRuby's profiler?
Raw
profile #1
main thread profile results:
Total time: 21.13
total self children calls method
----------------------------------------------------------------
18.16 0.00 18.16 1 RSpec::Core::Runner.run
18.01 0.01 18.00 189 Array#collect
17.95 0.00 17.95 1 RSpec::Core::Runner.run_in_process
17.95 0.00 17.95 1 RSpec::Core::CommandLine#run
16.90 0.00 16.90 1 RSpec::Core::Reporter#report
16.88 0.00 16.88 5 RSpec::Core::ExampleGroup.run
16.88 0.00 16.88 5 RSpec::Core::ExampleGroup.run_examples
16.87 0.00 16.87 3 RSpec::Core::Example#run
16.87 0.00 16.87 6 Kernel#catch
16.87 0.00 16.87 3 RSpec::Core::Example#with_pending_capture
16.87 0.00 16.87 3 RSpec::Core::Example#with_around_hooks
16.87 0.00 16.86 10 Kernel#instance_eval
13.85 0.21 13.64 1 Olap::RowSet#values
9.42 0.13 9.29 86840 Enumerable#collect
9.40 0.43 8.97 173679 Integer#upto
9.29 0.04 9.25 86839 Enumerable::Enumerator#each
8.97 8.97 0.00 173674 #<Class:0x1762589c3>#getString
3.89 3.89 0.00 86838 #<Class:0x1762589c3>#next
3.39 0.11 3.28 414 Kernel#require
3.01 0.00 3.01 3 #<Class:0x155f4c4a3>::Nested_1#rowset
2.43 0.00 2.43 1206 Class#new
1.93 0.00 1.93 3 #<Class:0x142101da9>::Nested_1#connection
1.93 0.00 1.92 3 Olap::Connection#initialize
1.90 1.90 0.00 3 Java::MondrianOlap4j::MondrianOlap4jDriver#connect
1.72 0.00 1.72 172 Kernel#require
1.66 0.01 1.64 2 Kernel#load
1.08 0.00 1.08 3 Olap::Connection#drillthrough
1.08 0.00 1.08 6 #<Class:0x11a779dce>#executeQuery
1.03 0.00 1.03 1 RSpec::Core::Configuration#load_spec_files
0.80 0.02 0.77 386 Array#each
0.69 0.01 0.68 9 Gem.activate
0.66 0.00 0.66 1 Kernel#gem
0.65 0.00 0.65 11 Gem.source_index
0.65 0.00 0.65 1 Gem::SourceIndex.from_installed_gems
0.60 0.01 0.59 158 Array#reverse_each
0.57 0.00 0.57 1 Gem::SourceIndex.from_gems_in
0.57 0.00 0.57 1 Gem::SourceIndex#refresh!
0.57 0.00 0.57 1 Gem::SourceIndex#load_gems_in
0.55 0.01 0.54 69 Gem::Specification.load
0.50 0.16 0.34 80 Kernel#eval
0.34 0.02 0.32 69 Gem::Specification#initialize
0.29 0.02 0.27 2027 Object.method_added
0.27 0.01 0.26 4059 Object.method_added
0.24 0.24 0.00 9 Time.now
0.21 0.00 0.21 1 RSpec::Core::ConfigurationOptions#parse_options
0.19 0.18 0.01 14 JavaUtilities#get_proxy_or_package_under_package
0.16 0.00 0.16 5 Java::Java.method_missing
0.15 0.00 0.14 4 Gem.try_activate
0.15 0.00 0.15 2 RSpec::Core::ConfigurationOptions#parse_options_file
0.14 0.00 0.14 1 RSpec::Core::ConfigurationOptions#parse_local_options
Raw
profile #2
main thread profile results:
Total time: 21.80
total self children calls method
----------------------------------------------------------------
18.26 0.00 18.26 1 RSpec::Core::Runner.run
18.15 0.01 18.14 189 Array#collect
18.07 0.00 18.07 1 RSpec::Core::Runner.run_in_process
18.07 0.00 18.07 1 RSpec::Core::CommandLine#run
17.04 0.00 17.04 1 RSpec::Core::Reporter#report
17.02 0.00 17.02 5 RSpec::Core::ExampleGroup.run
16.99 0.00 16.99 5 RSpec::Core::ExampleGroup.run_examples
16.98 0.00 16.98 3 RSpec::Core::Example#run
16.98 0.00 16.98 6 Kernel#catch
16.98 0.00 16.98 3 RSpec::Core::Example#with_pending_capture
16.98 0.00 16.98 3 RSpec::Core::Example#with_around_hooks
16.97 0.00 16.97 10 Kernel#instance_eval
13.91 0.23 13.68 1 Olap::RowSet#values
9.34 0.12 9.22 86840 Enumerable#collect
9.30 0.40 8.90 173679 Integer#upto
9.22 0.04 9.18 86839 Enumerable::Enumerator#each
8.90 0.06 8.84 347348 #<Class:0x112e6f711>#getString
4.02 4.02 0.00 86838 #<Class:0x112e6f711>#next
3.82 0.14 3.69 414 Kernel#require
3.05 0.00 3.05 3 #<Class:0x15c2bae98>::Nested_1#rowset
2.46 0.00 2.46 1206 Class#new
1.93 0.00 1.93 3 #<Class:0x10ea224b5>::Nested_1#connection
1.93 0.00 1.93 3 Olap::Connection#initialize
1.91 1.91 0.00 3 Java::MondrianOlap4j::MondrianOlap4jDriver#connect
1.74 0.00 1.74 172 Kernel#require
1.70 0.02 1.69 2 Kernel#load
1.11 0.00 1.11 3 Olap::Connection#drillthrough
1.11 0.00 1.11 6 #<Class:0x1796686c8>#executeQuery
1.01 0.00 1.01 1 RSpec::Core::Configuration#load_spec_files
0.87 0.03 0.85 386 Array#each
0.77 0.01 0.76 9 Gem.activate
0.74 0.00 0.74 1 Kernel#gem
0.72 0.00 0.72 11 Gem.source_index
0.72 0.00 0.72 1 Gem::SourceIndex.from_installed_gems
0.66 0.02 0.64 158 Array#reverse_each
0.62 0.00 0.62 1 Gem::SourceIndex.from_gems_in
0.62 0.00 0.62 1 Gem::SourceIndex#refresh!
0.62 0.00 0.62 1 Gem::SourceIndex#load_gems_in
0.60 0.01 0.58 69 Gem::Specification.load
0.55 0.21 0.34 80 Kernel#eval
0.34 0.03 0.31 69 Gem::Specification#initialize
0.26 0.02 0.24 2027 Object.method_added
0.24 0.00 0.23 4059 Object.method_added
0.21 0.19 0.02 14 JavaUtilities#get_proxy_or_package_under_package
0.19 0.19 0.00 9 Time.now
0.19 0.00 0.19 1 RSpec::Core::ConfigurationOptions#parse_options
0.17 0.00 0.17 5 Java::Java.method_missing
0.15 0.00 0.15 19 Regexp.new
0.15 0.15 0.00 19 Regexp#initialize
0.14 0.11 0.03 133 Module#module_eval
@filiptepper
Copy link
Author

Notice the difference in lines 22 in self collumn in both profiler outputs:

8.97 8.97 0.00 173674 #<Class:0x1762589c3>#getString

vs.

8.90 0.06 8.84 347348 #<Class:0x112e6f711>#getString

First one is a direct call to instance.getString, second is a call to instance.get_string (JRuby mapping of Java method).

Is that a bug?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment