How to Profile Rspec with Perftools and Bundler

How to profile RSpec with perftools and bundler?

I too had to dig around to get this. Here is what I did

1. Put this in spec_helper.rb:

   config.before :suite do
     PerfTools::CpuProfiler.start("/tmp/rspec_profile")
   end
   
   config.after :suite do
     PerfTools::CpuProfiler.stop
   end
   

2. Run your rspec

3. Run pprof to get your numbers

   pprof.rb --text  /tmp/rspec_profile
   

Use Ruby profile to track down slow execution in RSpec

There are so many questions like this. Some profile output is shown, and the question: "What's going on?"

There's no need to puzzle over the profile output. You can find the problem(s) right away. The more time they take, the easier they are to find.

Anything that deals in self-time, ms-per-call, call counts, etc. is stuck in the pit of performance myths.

Added: For example

• self time (exclusive) is based on the premise that the only way you can waste time is by not calling functions. When functions are called unnecessarily, that you'd like to find and get rid of, or if IO is done unnecessarily, it doesn't show up in self time. IO and other blocking time doesn't show up at all if samples are only taken when the program is unblocked.

• ms-per-call (inclusive), multiplied by call count of a function, divided by total time, gives fraction of time the function is responsible for. With only two of these three numbers you can't tell if the function is spending too much time or not.

• If you can tell if a function is responsible for a good fraction of time, you still need to find the lines within it that are responsible for the time.
  If the profiler acts like the only units you care about are functions, you're still left doing detective work.

SimpleCov reports not generating in Rails 3 app after running RSpec tests with Spork

I managed to get a working spec/spec_helper.rb configuration that executes SimpleCov correctly simply using the $ rspec spec/ command thanks to a comment on the Github issue that sent me to this blog entry, and its example spec/spec_helper.rb. All reasons why this works are contained in the (very detailed!) blog entry. Replace SampleApp with the name of your application.

spec/spec_helper.rb

require 'rubygems'
require 'spork'

Spork.prefork do
  unless ENV['DRB']
    require 'simplecov'
    SimpleCov.start 'rails'
  end

  require 'rails/application'
  require Rails.root.join("config/application")

  ENV["RAILS_ENV"] ||= 'test'
  require 'rspec/rails'
  require 'rspec/autorun'

  RSpec.configure do |config|
    config.mock_with :rspec
    config.fixture_path = "#{::Rails.root}/spec/fixtures"
    config.use_transactional_fixtures = false

    config.before :each do
      if Capybara.current_driver == :rack_test
        DatabaseCleaner.strategy = :transaction
      else
        DatabaseCleaner.strategy = :truncation
      end
      DatabaseCleaner.start
    end

    config.after do
      DatabaseCleaner.clean
    end

    config.infer_base_class_for_anonymous_controllers = false
  end
end

Spork.each_run do
  if ENV['DRB']
    require 'simplecov'
    SimpleCov.start 'rails'
    SampleApp::Application.initialize!
    class SampleApp::Application
      def initialize!; end
    end
  end

  Dir[Rails.root.join("spec/support/**/*.rb")].each {|f| require f}
end

Edit

If you use Travis-CI, don't use this code as-is because you'll likely get a undefined method 'root' for Rails:Module (NoMethodError) error. If you know how to fix this, please share.

Edit 2

I got Travis CI to work by essentially putting everything in the Spork.each_run block, which seems to have slowed down the tests significantly. There must be a better way to do this, or it just doesn't seem worth it for the sake of not having to run $ rspec --no-drb spec/ once to get the SimpleCov report...

spec/spec_helper.rb

require 'rubygems'
require 'spork'

Spork.prefork do
  unless ENV['DRB']
    require 'simplecov'
    SimpleCov.start 'rails'
  end

  require 'rails/application'
  ENV["RAILS_ENV"] ||= 'test'
end

Spork.each_run do
  if ENV['DRB']
    require 'simplecov'
    SimpleCov.start 'rails'
    require Rails.root.join("config/application")
    SampleApp::Application.initialize!
    class SampleApp::Application
      def initialize!; end
    end
  end

  unless ENV['DRB']
    require File.expand_path("../../config/environment", __FILE__)
  end

  require 'rspec/rails'
  require 'rspec/autorun'

  Dir[Rails.root.join("spec/support/**/*.rb")].each {|f| require f}

  RSpec.configure do |config|
    config.mock_with :rspec

    config.fixture_path = "#{::Rails.root}/spec/fixtures"
    config.use_transactional_fixtures = false
    config.before :each do
      if Capybara.current_driver == :rack_test
        DatabaseCleaner.strategy = :transaction
      else
        DatabaseCleaner.strategy = :truncation
      end
      DatabaseCleaner.start
    end

    config.after do
      DatabaseCleaner.clean
    end
    config.infer_base_class_for_anonymous_controllers = false
  end
end

Edit 3

After using this config for a few days, it doesn't seem to have slowed down things as much as I previously thought, so I'll consider this the accepted answer unless a more elegant one is posted.

Edit 4

After using this config for a few months, I've come to realize that it is slower than I thought. Part of that is the realisation that it seems that Spork can slow down test suites, and is best for fast iterative focused testing vs always running entire test suites with it. The following SO questions and blog posts got me to the spec_helper.rb file below, which can run SimpleCov with or without Spork, runs faster than before, and works with Capybara 2.0.

• Rails project using spork - always have to use spork?
• How to profile RSpec with perftools and bundler?
• Spork.trap_method Jujitsu
• When Spork puts a fork in your Cucumber and a spanner in yor specs
• Crank your specs
• Profiling Spork for faster start-up time
• Sane RSpec config for clean, and slightly faster, specs

spec/spec_helper.rb

require 'rubygems'
require 'spork'
require 'simplecov'
#uncomment the following line to use spork with the debugger
#require 'spork/ext/ruby-debug'

Spork.prefork do
  ENV["RAILS_ENV"] ||= 'test'
  unless ENV['DRB']
    SimpleCov.start 'rails'
    require File.expand_path("../../config/environment", __FILE__)
  end

  require 'rspec/rails'
  require 'rspec/autorun'
  require 'capybara/rails'
  require 'capybara/rspec'

  # files to preload based on results of Kernel override code below
  # ie they took more than 100 ms to load
  require "sprockets"
  require "sprockets/eco_template"
  require "sprockets/base"
  require "active_record/connection_adapters/postgresql_adapter"
  require "tzinfo"
  require "tilt"
  require "journey"
  require "journey/router"
  require "haml/template"

  RSpec.configure do |config|
    config.mock_with :rspec

    # If you're not using ActiveRecord, or you'd prefer not to run each of your
    # examples within a transaction, remove the following line or assign false
    # instead of true.
    config.use_transactional_fixtures = false

    # If true, the base class of anonymous controllers will be inferred
    # automatically. This will be the default behavior in future versions of
    # rspec-rails.
    config.infer_base_class_for_anonymous_controllers = false

    config.include FactoryGirl::Syntax::Methods

    config.before :suite do
      # PerfTools::CpuProfiler.start("/tmp/rspec_profile")
      DatabaseCleaner.strategy = :transaction
      DatabaseCleaner.clean_with(:truncation)
    end

    # Request specs cannot use a transaction because Capybara runs in a
    # separate thread with a different database connection.
    config.before type: :request do
      DatabaseCleaner.strategy = :truncation
    end

    # Reset so other non-request specs don't have to deal with slow truncation.
    config.after type: :request  do
      DatabaseCleaner.strategy = :transaction
    end

    RESERVED_IVARS = %w(@loaded_fixtures)
    last_gc_run = Time.now

    config.before(:each) do
      GC.disable
    end

    config.before do
      DatabaseCleaner.start
    end

    config.after do
      DatabaseCleaner.clean
    end

    # Release instance variables and trigger garbage collection
    # manually every second to make tests faster
    # http://blog.carbonfive.com/2011/02/02/crank-your-specs/
    config.after(:each) do
      (instance_variables - RESERVED_IVARS).each do |ivar|
        instance_variable_set(ivar, nil)
      end
      if Time.now - last_gc_run > 1.0
        GC.enable
        GC.start
        last_gc_run = Time.now
      end
    end

    config.after :suite do
      # PerfTools::CpuProfiler.stop

      # REPL to query ObjectSpace
      # http://blog.carbonfive.com/2011/02/02/crank-your-specs/
      # while true
      #   '> '.display
      #   begin
      #     puts eval($stdin.gets)
      #   rescue Exception => e
      #     puts e.message
      #   end
      # end
    end
  end

  # Find files to put into preload
  # http://www.opinionatedprogrammer.com/2011/02/profiling-spork-for-faster-start-up-time/
  # module Kernel
  #   def require_with_trace(*args)
  #     start = Time.now.to_f
  #     @indent ||= 0
  #     @indent += 2
  #     require_without_trace(*args)
  #     @indent -= 2
  #     Kernel::puts "#{' '*@indent}#{((Time.now.to_f - start)*1000).to_i} #{args[0]}"
  #   end
  #   alias_method_chain :require, :trace
  # end
end

Spork.each_run do
  # This code will be run each time you run your specs.
  if ENV['DRB']
    SimpleCov.start 'rails'
    SampleApp::Application.initialize!
    class SampleApp::Application
      def initialize!; end
    end
  end

  # Requires supporting ruby files with custom matchers and macros, etc,
  # in spec/support/ and its subdirectories.
  Dir[Rails.root.join("spec/support/**/*.rb")].each {|f| require f}
  FactoryGirl.reload
  I18n.backend.reload!
end

---

Related Topics