-
-
Save dnagir/2bea805664bfb6491d1d to your computer and use it in GitHub Desktop.
Profiling enabled; ^C shutdown will now dump profile info | |
main thread profile results: | |
Total time: 54.43 | |
total self children calls method | |
---------------------------------------------------------------- | |
50.17 0.00 50.17 1 RSpec::Core::Runner.run | |
50.13 0.00 50.13 1 RSpec::Core::Runner.run_in_process | |
50.13 0.00 50.13 1 RSpec::Core::CommandLine#run | |
50.08 0.03 50.05 29243 Array#collect | |
39.27 0.23 39.03 96551 Array#each | |
29.11 0.15 28.95 4545 BasicObject#instance_eval | |
28.86 0.00 28.86 1 RSpec::Core::Reporter#report | |
28.77 0.00 28.77 158 RSpec::Core::ExampleGroup.run | |
28.67 0.00 28.67 158 RSpec::Core::ExampleGroup.run_examples | |
28.65 0.01 28.64 220 RSpec::Core::Example#run | |
28.53 0.01 28.52 219 RSpec::Core::Example#with_around_hooks | |
26.36 0.05 26.31 9342 Kernel#require | |
24.45 0.06 24.39 156383 Kernel#send | |
21.34 0.05 21.29 41 Kernel#load | |
21.20 0.00 21.20 1 RSpec::Core::Configuration#load_spec_files | |
20.23 0.00 20.23 1 Spork.prefork | |
19.38 0.00 19.38 2339 ActiveSupport::Dependencies::Loadable#load_dependency | |
17.40 0.00 17.40 2301 ActiveSupport::Dependencies::Loadable#require | |
15.03 0.11 14.92 23460 Proc#call | |
13.96 0.03 13.93 32139 Kernel#catch | |
13.90 0.02 13.87 2686 <unknown> | |
13.45 0.02 13.44 1867 ActiveSupport::Callbacks#run_callbacks | |
11.31 0.00 11.31 56 <unknown> | |
11.31 0.00 11.31 56 <unknown> | |
11.29 0.00 11.29 56 <unknown> | |
11.29 0.01 11.28 56 <unknown> | |
10.91 0.00 10.91 56 <unknown> | |
10.89 0.00 10.89 56 AbstractController::Rendering#process | |
10.89 0.00 10.89 58 AbstractController::Base#process | |
10.73 0.00 10.72 56 ActiveRecord::Railties::ControllerRuntime#process_action | |
10.72 0.00 10.72 56 ActionController::ParamsWrapper#process_action | |
10.72 0.01 10.71 56 ActionController::Instrumentation#process_action | |
10.67 0.00 10.66 277 ActiveSupport::Notifications.instrument | |
10.59 0.00 10.59 56 ActionController::Rescue#process_action | |
10.59 0.00 10.59 56 AbstractController::Callbacks#process_action | |
10.20 0.01 10.20 1482 ActiveSupport::Dependencies#new_constants_in | |
10.07 0.00 10.07 1 Bundler.require | |
10.07 0.00 10.07 1 Bundler::Runtime#require | |
9.22 0.00 9.22 53 ActionController::Rendering#process_action | |
9.22 0.00 9.22 55 AbstractController::Base#process_action | |
9.21 0.00 9.21 53 ActionController::ImplicitRender#send_action | |
8.96 0.00 8.96 219 RSpec::Core::Example#run_before_each | |
8.62 0.00 8.62 38 ActionController::Instrumentation#render | |
8.62 0.00 8.62 38 ActiveRecord::Railties::ControllerRuntime#cleanup_view_runtime | |
8.62 0.00 8.62 38 ActionController::Instrumentation#cleanup_view_runtime | |
8.62 0.00 8.62 38 Benchmark.ms | |
8.62 0.00 8.62 76 Benchmark#realtime | |
8.61 0.00 8.61 38 ActionController::Rendering#render | |
8.61 0.00 8.61 38 AbstractController::Rendering#render | |
8.53 0.00 8.53 38 ActionController::Compatibility#render_to_body |
Thanks @chuckremes for the comments.
RE:
Kernel#load taking up 21s out of your 54s runtime, that's an indication that you need a longer sample otherwise you are mostly benchmarking the startup time.
Isn't a minute enough? Its the whole test suite. I'm not sure how I can wrap the whole test suite to run multiple times.
call it like 50.times {} so that the JIT has a chance to warm up and optimize out some of this stuff.
Than unfortunately defeats the point. Specs run-time is what I want to optimise.
Since the specs run pretty slow I'm also not sure what the bottleneck is.
Is it JRuby? Maybe neo4j database clean-up?
If that's JRuby, then probably nothing I can do. Otherwise I probably can fix some of the perf issues.
I just want to find out what causes the slowdown.
Here is the result of jruby --profile.graph bin/rspec spec 1> profile.graph.log
: http://dl.dropbox.com/u/15819974/profile.graph.log
Does it tell you anything?
What is going on here:
0.00 0.00 0.00 1/5752 Kernel#require 0.00 0.00 0.00 1/5752 Formtastic::Helpers::InputsHelper#content_columns 0.20 0.19 0.00 219/5752 0.44 0.44 0.00 216/5752 Kernel#eval 1.29 1.29 0.00 646/5752 NilClass#method_missing 6.62 6.61 0.00 4669/5752 Array#join 16% 16% 8.55 8.55 0.01 5752 BasicObject#method_missing 0.01 0.01 0.00 5317/5317 NoMethodError#initialize 0.00 0.00 0.00 435/555 NameError#initialize
Here's what it does:
def content_columns #:nodoc:
model_name.constantize.content_columns.collect { |c| c.name.to_sym }.compact rescue []
end
But why does it matter? The timing is 0 for it. Also it seems to be happening from require
(or not?) that is done only once.
https://github.com/justinfrench/formtastic/blob/master/lib/formtastic/helpers/inputs_helper.rb
# Collects content columns (non-relation columns) for the current form object class.
def content_columns #:nodoc:
model_name.constantize.content_columns.collect { |c| c.name.to_sym }.compact rescue []
end
Try adding a content_columns method that returns an empty array to all your models. ( add it to Neo4j::Model)
Timing is 0? doesn't it say 16% and 8.55 seconds?
Do you think it's rescue
slowing everything?
I'll then better submit a pull request to Formtastic.
Yeah. Right, but it's on BasicObject#method_missing
that is probably called by content_columns
Try this first. In https://github.com/andreasronge/neo4j/blob/master/lib/neo4j/rails/model.rb add a
def content_columns
[]
end
to the public methods and try it again.
On second thought, I think you are right about sending Formtastic a pull request. Monkey patch to content_columns and if it speeds it up, send them a patch.
Something like this:
def content_columns #:nodoc:
if model_name.constantize.responds_to?(:content_columns)
model_name.constantize.content_columns.collect { |c| c.name.to_sym }.compact rescue []
else
[]
end
end
But if formtastic expects it to be there maybe other gems do too? So should it also be added to neo4j/rails/model.rb?
I monkey patched and it looks like won almost 3 seconds or so:
> time bin/rspec spec/controllers # It's used in controller only
Finished in 36.17 seconds
63 examples, 0 failures, 7 pending
real 0m39.500s
user 0m42.745s
sys 0m3.569s
# Monkey patch
> time bin/rspec spec/controllers # It's used in controller only
Finished in 33.89 seconds
63 examples, 0 failures, 7 pending
real 0m37.137s
user 0m43.226s
sys 0m3.586s
I see similar numbers after running it multiple times.
Will submit PR to formtastic. (UPDATE: pul request is here)
3 secs is a good win. But still hope to catch a big fish :)
Cool. Let's see another profile run and maybe something new will pop-up.
Thanks a lot for the help! Appreciate it.
Here's another run that includes the monkey patch http://dl.dropbox.com/u/15819974/profile.graph-2.log
Hum... nothing jumping out at me other than bundler.
http://stackoverflow.com/questions/4736546/rails-3-osx-speed-up-console-loading-time << trying to see which gems are taking a long time to load could be interesting.
puts Benchmark.measure("require #{file}") {
Kernel.require file
}.format("%n: %t %r")
It looks like requiring neo4j gem takes most of the time.
But I'm very much in doubt that 1.7 sec (is it in secs?) time is an issue here.
Relatively small gem (draper) takes 1.2 secs to load. Also at the rails gem seems to take the least amont of time.
The results don't seem to be representative unfortunately.
> sort --reverse require.log
(1.709000) for require neo4j: 1.709000
(1.188000) for require draper: 1.189000
(0.683000) for require sass-rails: 0.683000
(0.651000) for require inherited_resources: 0.651000
(0.543000) for require pry: 0.542000
(0.527000) for require capybara-webkit: 0.527000
(0.520000) for require capybara: 0.520000
(0.474000) for require compass: 0.474000
(0.444000) for require haml-rails: 0.444000
(0.355000) for require devise-neo4j: 0.355000
(0.305000) for require shoulda-matchers: 0.305000
(0.214000) for require launchy: 0.214000
(0.171000) for require factory_girl: 0.171000
(0.150000) for require coffee-rails: 0.150000
(0.082000) for require dragonfly: 0.082000
(0.079000) for require jasmine: 0.079000
(0.036000) for require paper_trail: 0.037000
(0.025000) for require allowy: 0.025000
(0.019000) for require no_peeping_toms: 0.019000
(0.018000) for require database_cleaner: 0.018000
(0.016000) for require ruby_gntp: 0.016000
(0.015000) for require jquery-rails: 0.014000
(0.015000) for require factory_girl_rails: 0.015000
(0.012000) for require rb-fsevent: 0.012000
(0.011000) for require uglifier: 0.011000
(0.010000) for require formtastic: 0.010000
(0.008000) for require rack/cache: 0.008000
(0.007000) for require guard: 0.007000
(0.003000) for require rspec-rails: 0.003000
(0.002000) for require spork: 0.002000
(0.001000) for require rails: 0.001000
Saw your question on jruby irc...
Unfortunately, flat profiles are only one piece of the puzzle. IME, it's best to have both a flat and a graph profile. For example, this flat profile tells you that you are spending 39s in the children of Array#each but it's impossible to tell what those children are doing. The graph profile would let you find out.
Also, when you see something like Kernel#load taking up 21s out of your 54s runtime, that's an indication that you need a longer sample otherwise you are mostly benchmarking the startup time. Try putting this inside of a small script and wrapping it in a call to something like 50.times {} so that the JIT has a chance to warm up and optimize out some of this stuff.