How to debug a Rails asset precompile which is unbearably slow

Question

I'm working on a Rails 3.2 project and the assets have increased a fair bit in recent months although I wouldn't consider the project to be large. The assets consist of JS (no coffee-script), and SASS files; we've quite a few images but they've been there more less since the early days so I don't think they are a substantial factor. We may have about a dozen libs and most are small, the largest is Jquery UI JS. Deployment is done via Capistrano and it started to become apparent that deploying to staging was significantly faster than to production. To illustrate whilst avoiding factors about different servers and network effects I simply ran the following three commands in sequence on my laptop as follows:

$ time RAILS_ENV=production bundle exec rake assets:precompile
^Crake aborted!
[Note I aborted this run as I felt it was getting stupidly long...]
real    52m33.656s
user    50m48.993s
sys 1m42.165s

$ time RAILS_ENV=staging bundle exec rake assets:precompile
real    0m41.685s
user    0m38.808s
sys 0m2.803s

$ time RAILS_ENV=development bundle exec rake assets:precompile
real    0m12.157s
user    0m10.567s
sys 0m1.531s

So I'm left scratching my head. Why are there such massive differences between the various environments? I can understand the gap between development and staging, but our configs for staging and production are identical. (I should point out that the production compile will complete after about 2hrs!)

Whilst the end result is getting my precompile to be faster, I want to accomplish this by understanding where all the time is going and why there are such big differences between the Rails environments. I've seen other posts about using different compressors and such like but I can't find any information about how to debug these rake tasks to work out where the time is being spent and identify which settings may be causing such dramatic differences.

I don't know what additional information people may need so will update if and when comments ask. TIA

Update: additional information supplied below

config/environments/production.rb and config/environments/staging.rb (they're exactly the same):

MyRailsApp::Application.configure do
  # Code is not reloaded between requests
  config.cache_classes = true

  # Full error reports are disabled and caching is turned on
  config.consider_all_requests_local       = false
  config.action_controller.perform_caching = true

  # Disable Rails's static asset server (Apache or nginx will already do this)
  config.serve_static_assets = true
  config.static_cache_control = "public, max-age=31536000"
  config.action_controller.asset_host = "//#{MyRailsApp::CONFIG[:cdn]}"

  # Compress JavaScripts and CSS
  config.assets.compress = true

  # Don't fallback to assets pipeline if a precompiled asset is missed
  config.assets.compile = false

  # Generate digests for assets URLs
  config.assets.digest = true

  # Enable locale fallbacks for I18n (makes lookups for any locale fall back to
  # the I18n.default_locale when a translation can not be found)
  config.i18n.fallbacks = true

  # Send deprecation notices to registered listeners
  config.active_support.deprecation = :notify
end

The base config/application.rb is:

require File.expand_path('../boot', __FILE__)

require 'rails/all'

if defined?(Bundler)
  # If you precompile assets before deploying to production, use this line
  Bundler.require(*Rails.groups(:assets => %w(development test)))
  # If you want your assets lazily compiled in production, use this line
  # Bundler.require(:default, :assets, Rails.env)
end
module MyRailsApp
  CONFIG = YAML.load_file(File.join(File.dirname(__FILE__), 'config.yml'))[Rails.env]

  class Application < Rails::Application

    # Custom directories with classes and modules you want to be autoloadable.
    config.autoload_paths += %W(#{config.root}/lib)
    config.autoload_paths += %W(#{config.root}/app/workers)

    # Configure the default encoding used in templates for Ruby 1.9.
    config.encoding = "utf-8"

    # Configure sensitive parameters which will be filtered from the log file.
    config.filter_parameters += [:password]

    # Enable the asset pipeline
    config.assets.enabled = true

    # Stop precompile from looking for the database
    config.assets.initialize_on_precompile = false

    # Version of your assets, change this if you want to expire all your assets
    config.assets.version = '1.0'

    # Fix fonts in assets pipeline
    # http://stackoverflow.com/questions/6510006/add-a-new-asset-path-in-rails-3-1
    config.assets.paths << Rails.root.join('app','assets','fonts')

    config.middleware.insert 0, 'Rack::Cache', {
      :verbose     => true,
      :metastore   => URI.encode("file:#{Rails.root}/tmp/dragonfly/cache/meta"),
      :entitystore => URI.encode("file:#{Rails.root}/tmp/dragonfly/cache/body")
    } # unless Rails.env.production?  ## uncomment this 'unless' in Rails 3.1,
                                      ## because it already inserts Rack::Cache in production

    config.middleware.insert_after 'Rack::Cache', 'Dragonfly::Middleware', :images

    config.action_mailer.default_url_options = { :host => CONFIG[:email][:host] }
    config.action_mailer.asset_host = 'http://' + CONFIG[:email][:host]
  end
end

Gem file:

source 'http://rubygems.org'

gem 'rails', '3.2.13'   
gem 'mysql2'
gem 'dragonfly', '>= 0.9.14'
gem 'rack-cache', :require => 'rack/cache'
gem 'will_paginate'
gem 'dynamic_form'
gem 'amazon_product' # for looking up Amazon ASIN codes of books
gem 'geoip'
gem 'mobile-fu'
gem 'airbrake'
gem 'newrelic_rpm'
gem 'bartt-ssl_requirement', '~>1.4.0', :require => 'ssl_requirement'
gem 'dalli' # memcache for api_cache
gem 'api_cache'
gem 'daemons'
gem 'delayed_job_active_record'
gem 'attr_encrypted'
gem 'rest-client'
gem 'json', '>= 1.7.7'
gem 'carrierwave' # simplify file uploads
gem 'net-scp'

# Gems used only for assets and not required
# in production environments by default.
group :assets do
  gem 'therubyracer'
  gem 'sass-rails',   '~> 3.2.3'
  gem 'compass', '~> 0.12.alpha'
  gem 'uglifier', '>= 1.0.3'
  gem 'jquery-fileupload-rails'
end

gem 'jquery-rails'
gem 'api_bee', :git => 'git://github.com/ismasan/ApiBee.git', :ref => '3cff959fea5963cf46b3d5730d68927cebcc59a8'
gem 'httparty', '>= 0.10.2'
gem 'twitter'

# Auth providers
gem 'omniauth-facebook'
gem 'omniauth-twitter'
gem 'omniauth-google-oauth2'
gem 'omniauth-identity'
gem 'omniauth-readmill'
gem 'bcrypt-ruby', "~> 3.0.0" # required for omniauth-identity
gem 'mail_view'

# To use ActiveModel has_secure_password
# gem 'bcrypt-ruby', '~> 3.0.0'

# Deploy with Capistrano
group :development do
  gem 'capistrano'
  gem 'capistrano-ext'
  gem 'capistrano_colors'
  gem 'rvm-capistrano'

  # requirement for Hoof, Linux equivalent of Pow
  gem 'unicorn'
end

group :test, :development do  
  gem 'rspec-rails'
  gem 'pry'
  gem 'pry-rails'
end

group :test do
  gem 'factory_girl_rails'
  gem 'capybara'
  gem 'cucumber-rails'
  gem 'database_cleaner'
  gem 'launchy'
  gem 'ruby-debug19'
  # Pretty printed test output
  gem 'shoulda-matchers'
  gem 'simplecov', :require => false
  gem 'email_spec'
  gem 'show_me_the_cookies'
  gem 'vcr'
  gem 'webmock', '1.6'
end

Solution 1

This may not entirely answer your question, but I believe it is a decent enough start. As you'll see, the precise answer will depend on the individual application, gem versions and so on.

So. For asset-related work, as you know, Rails uses a library called Sprockets, which in newer versions of Rails is, I believe, hooked into Rails as a Railtie. It initializes a Sprockets "environment" that can do things like look at your asset manifest, load those files, compress them, give the compiled assets sensible names, etc.

By default, that Sprockets::Environment logs its activity to STDERR with a log level of FATAL, which isn't very useful in these situations. Fortunately, the Sprockets::Environment (as of 2.2.2) has a writeable logger attribute that you can patch in via Rails, using an initializer.

---

So, here's what I suggest, to start:

In config/initializers, create a file, something like asset_logging.rb. In it, put:

Rails.application.config.assets.logger = Logger.new($stdout)

This overwrites the default logger with one that will spit more information out to STDOUT. Once you've got this set up, then run your asset pre-compilation task:

rake RAILS_ENV=production assets:precompile

And you should see slightly more interesting output, such as:

...
Compiled jquery.ui.core.js  (0ms)  (pid 66524)
Compiled jquery.ui.widget.js  (0ms)  (pid 66524)
Compiled jquery.ui.accordion.js  (10ms)  (pid 66524)
...

---

But, in the end, the final answer will depend on:

• how "deep" you want to go with logging this asset stuff
• what specific version of Rails, Sprockets, etc. you're using
• and what you find along the way

As you've already learned, log spelunking at the Rake task level, or even at the Rails level, doesn't give much information. And even making Sprockets itself verbose (see above) doesn't tell you too terribly much.

If you wanted to go deeper than Sprockets, you can probably monkey patch the various engines and processors that Sprockets dutifully chains together to make the asset pipeline work. For example, you could look into the logging capabilities of these components:

• Sass::Engine (converts SASS to CSS)
• Uglifier (JavaScript compressor wrapper)
• ExecJS (runs JavaScript in Ruby; a dependency of both Sprockets and Uglifier)
• therubyracer (V8 embedded in Ruby; used by ExecJS)
• etc.

But I will leave all that as "an exercise for the reader." If there's a silver bullet, I'd certainly like to know about it!

Solution 2

there is a bunch of possible causes to this issue.

for a possible cause, i would like to know how the time of compiling the assets increased in the several environments for your last deploys. this might indicate if the problem is just on the environments or within the asset compilation itself. you could use git bisect for that. i usually have my apps deployed to staging via a jenkins or another ci system so that i can see any variations in deploy time and when they were introduced.

it might boil down to extensive use of resources CPU, MEMORY (any swap?), IO. if you compile the assets on the production systems they might be busy serving your applications request. go to your system, do a top for resources, maybe there are too many file handles at the same time (lsof is good for that).

another thing might be that you load or cache some data for your application. databases are usually much larger in staging and production environments then they are on dev boxes. you could just put some Rails.logger calls in your initializers or whaterver.

Solution 3

I think you need to see the cpu usage parameters on your Prod server.

Moreover, there may be a possibility that assets are getting precompiled multiple times. I would suggest creating a assets directory in shared directory created by capistrano, copying your changes in the same and link it to your apps while deploying.

Heres how I do it,

  after "deploy:update_code" do
    run "export RAILS_ENV=production"
    run "ln -nfs #{shared_path}/public/assets #{release_path}/public/assets"
    # Also for logs and temp section.
    # run "ln -nfs #{shared_path}/log #{release_path}/log"
    # run "ln -nfs #{shared_path}/tmp #{release_path}/tmp"
    #sudo "chmod -R 0777 #{release_path}/tmp/"
    #sudo "chmod -R 0777 #{release_path}/log/"
  end

Comments

[arooaroo]

Of course I'm bisecting to discover if there are any particular assets or changes that cause a drop-off. Note that I'm doing all benchmarking on my laptop - and I'm not doing much else in the background - by setting RAILS_ENV and in the application config I have config.assets.initialize_on_precompile = false which takes the database out of the equation.

[kik]

+1 for trying to see logs. The problem smells like a circular dependencies one. Carefully checking for doubles in logs may help.

[amoebe]

In recent rails versions you have to put in an extra .assets like this: Rails.application.config.assets.logger = Logger.new($stdout)

[mountriv99]

i wasn't able to get those "interesting output", anybody else had any luck?

[Shan]

No luck on Rails 4.2.3

[Nathan B]

Doesn't work for me. I'm on rails 4.2.11. anyone knows why?

[Nathan B]

rake RAILS_ENV=production assets:precompile --trace