Rails: execution expired on time_zone_select

Question

The following exception comes up intermittently:

An ActionView::Template::Error occurred

execution expired
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/dependencies.rb:251:in `require'

This is the full trace:

vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/dependencies.rb:251:in `require'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/dependencies.rb:251:in `block in require'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/dependencies.rb:236:in `load_dependency'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/dependencies.rb:251:in `require'
vendor/bundle/ruby/1.9.1/gems/tzinfo-0.3.37/lib/tzinfo/timezone.rb:103:in `get'
vendor/bundle/ruby/1.9.1/gems/tzinfo-0.3.37/lib/tzinfo/timezone_proxy.rb:80:in `real_timezone'
vendor/bundle/ruby/1.9.1/gems/tzinfo-0.3.37/lib/tzinfo/timezone_proxy.rb:52:in `period_for_utc'
vendor/bundle/ruby/1.9.1/gems/tzinfo-0.3.37/lib/tzinfo/timezone.rb:458:in `current_period'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/core_ext/object/try.rb:36:in `try'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/values/time_zone.rb:212:in `utc_offset'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/values/time_zone.rb:226:in `<=>'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/values/time_zone.rb:334:in `sort'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/values/time_zone.rb:334:in `all'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.13/lib/action_view/helpers/form_options_helper.rb:507:in `time_zone_options_for_select'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.13/lib/action_view/helpers/form_options_helper.rb:612:in `to_time_zone_select_tag'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.13/lib/action_view/helpers/form_options_helper.rb:277:in `time_zone_select'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.13/lib/action_view/helpers/form_options_helper.rb:654:in `time_zone_select'

When I navigate to the page in question, it loads fine. It seems to load fine for most people, and only intermittently (rarely) crash like so. I've noticed that whenever it happens, the user agent is a bot; the most recent is Mozilla/5.0 (compatible; Baiduspider/2.0; +http://www.baidu.com/search/spider.html). But I'm concerned that it might happen to a human one day, so I'm wondering if anyone knows anything I can do about this?

Update

This came up today, with a user logged in (luckily, that user was me... wasn't able to replicate it though).

execution expired
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/visitor.rb:15:in `visit'

Trace:

vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/visitor.rb:15:in `visit'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/visitor.rb:5:in `accept'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/emitter.rb:36:in `block in visit_Psych_Nodes_Sequence'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/emitter.rb:36:in `each'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/emitter.rb:36:in `visit_Psych_Nodes_Sequence'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/visitor.rb:15:in `visit'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/visitor.rb:5:in `accept'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/emitter.rb:26:in `block in visit_Psych_Nodes_Document'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/emitter.rb:26:in `each'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/emitter.rb:26:in `visit_Psych_Nodes_Document'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/visitor.rb:15:in `visit'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/visitor.rb:5:in `accept'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/emitter.rb:20:in `block in visit_Psych_Nodes_Stream'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/emitter.rb:20:in `each'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/emitter.rb:20:in `visit_Psych_Nodes_Stream'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/visitor.rb:15:in `visit'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/visitors/visitor.rb:5:in `accept'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/nodes/node.rb:46:in `yaml'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych.rb:243:in `dump'
vendor/bundle/ruby/1.9.1/gems/psych-1.3.4/lib/psych/core_ext.rb:14:in `psych_to_yaml'
/usr/local/lib/ruby/1.9.1/syck/rubytypes.rb:110:in `to_yaml'
vendor/bundle/ruby/1.9.1/gems/dalli-delete-matched-1.1.0/lib/dalli-delete-matched.rb:13:in `write_entry'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/cache/strategy/local_cache.rb:140:in `write_entry'
vendor/bundle/ruby/1.9.1/gems/dalli-2.6.2/lib/active_support/cache/dalli_store.rb:102:in `block in write'
vendor/bundle/ruby/1.9.1/gems/dalli-2.6.2/lib/active_support/cache/dalli_store.rb:279:in `block in instrument'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.13/lib/active_support/notifications.rb:125:in `instrument'
vendor/bundle/ruby/1.9.1/gems/dalli-2.6.2/lib/active_support/cache/dalli_store.rb:279:in `instrument'
vendor/bundle/ruby/1.9.1/gems/dalli-2.6.2/lib/active_support/cache/dalli_store.rb:101:in `write'
vendor/bundle/ruby/1.9.1/gems/dalli-2.6.2/lib/active_support/cache/dalli_store.rb:78:in `fetch'
app/models/concerns/roleable.rb:11:in `roles'

Again, any insights would be really welcome!

I'm hosting this on Heroku, and using Unicorn following the instructions at https://blog.heroku.com/archives/2013/2/27/unicorn_rails

Answer 1

Answering this question:

I'm really really keen to get this fixed, but I really don't have any idea where to start :/

You can start to rescue this error, log it, send one e-mail to you and since it happens only some times, retry (using the "retry" command). After this, you might want to check the last actions that this IP executed and see if it is related. Log also log the session variables.

Maybe you are getting timeouts in high server usage - try to use one tool lime newrelic or even log memory usage, cpu usage and disk usage yourself along with the other info.

EDIT:

Since it is not only one action, you can get every error on ApplicationController like this:

class ApplicationController < ActionController::Base
  rescue_from MyException, :with => :handle_my_exception

  def handle_my_exception
     grab_data
     send_mail
     retry
  end
 end

I thought it was on an specific action, so I'm not sure if retry works here. But even if you can't retry, you can still getting more info and sending by e-mail to yourself this way. Of course you will want to add a retry counter logic, or else you will be in trouble.

EDIT again:

Thinking better, you can simulate a retry from there with a redirect_to based on the request parameters. In this answer he explains how to get it. Don't forget to send the params too.

How do I get the current absolute URL in Ruby on Rails?

Answer 2

As the two stacktraces are completely different, I'll venture that page rendering takes a lot of time generally and is unrelated to what is shown in the specific stacktrace: ActionView will just stop wherever it was when the timeout occurred.

You should try speeding up the rendering process, for example by using the cache: have bots only hit non-dynamic content that's served from cache to reduce server load. Even splitting up large pages into partials and caching those may help a bit.

If you still run into this - especially since it's very infrequent - you could always go for an automatic re-rendering of the page when this exception occurs. See this blog entry for some sample code.

Answer 3

This problem (on Heroku anyway) boils down to the following code:

ActiveSupport::TimeZone::MAPPING.each do |key,val|
  TZInfo::Timezone.get(val)
end

All the time zone information is loaded up from a rather large set of files (one for each time zone) and then parsed. For some reason, this operation is very heavy. Maybe a combination of Ruby not being very efficient at file based IO (?) and the Heroku dynos having random issues hitting the file system.

My current fix is to pre-load the time zone information (basically running the above code) in all Unicorn workers (after_fork). Now at least the problem is deterministic instead of happening randomly...