search

noahd1 / oink

Log parser to identify actions which significantly increase VM heap size
MIT License
1.18k stars 71 forks source link

Update active_record instantiated_hash to default to {} instead of nil #23

Closed gabecoyne closed 11 years ago

gabecoyne commented 11 years ago

I started getting this on image requests where ActiveRecord is not loaded.

NoMethodError (undefined method sort' for nil:NilClass): oink (0.10.0) lib/oink/utils/hash_utils.rb:5:into_sorted_array' oink (0.10.0) lib/oink/middleware.rb:48:in log_activerecord' oink (0.10.0) lib/oink/middleware.rb:21:incall' warden (1.2.1) lib/warden/manager.rb:35:in block in call' warden (1.2.1) lib/warden/manager.rb:34:incatch' warden (1.2.1) lib/warden/manager.rb:34:in call' actionpack (3.2.1) lib/action_dispatch/middleware/best_standards_support.rb:17:incall' rack (1.4.1) lib/rack/etag.rb:23:in call' rack (1.4.1) lib/rack/conditionalget.rb:25:incall' actionpack (3.2.1) lib/action_dispatch/middleware/head.rb:14:in call' remotipart (1.0.2) lib/remotipart/middleware.rb:30:incall' actionpack (3.2.1) lib/action_dispatch/middleware/params_parser.rb:21:in call' actionpack (3.2.1) lib/action_dispatch/middleware/flash.rb:242:incall' rack (1.4.1) lib/rack/session/abstract/id.rb:205:in context' rack (1.4.1) lib/rack/session/abstract/id.rb:200:incall' rack-p3p (0.5.0) lib/rack-p3p.rb:11:in call' actionpack (3.2.1) lib/action_dispatch/middleware/cookies.rb:338:incall' activerecord (3.2.1) lib/active_record/query_cache.rb:64:in call' activerecord (3.2.1) lib/active_record/connection_adapters/abstract/connection_pool.rb:443:incall' actionpack (3.2.1) lib/action_dispatch/middleware/callbacks.rb:28:in block in call' activesupport (3.2.1) lib/active_support/callbacks.rb:405:in_run4079966539919658034call3128255809264830011callbacks' activesupport (3.2.1) lib/active_support/callbacks.rb:405:in __run_callback' activesupport (3.2.1) lib/active_support/callbacks.rb:385:in_run_call_callbacks' activesupport (3.2.1) lib/active_support/callbacks.rb:81:in run_callbacks' actionpack (3.2.1) lib/action_dispatch/middleware/callbacks.rb:27:incall' actionpack (3.2.1) lib/action_dispatch/middleware/reloader.rb:65:in call' actionpack (3.2.1) lib/action_dispatch/middleware/remote_ip.rb:31:incall' actionpack (3.2.1) lib/action_dispatch/middleware/debug_exceptions.rb:16:in call' actionpack (3.2.1) lib/action_dispatch/middleware/show_exceptions.rb:56:incall' railties (3.2.1) lib/rails/rack/logger.rb:26:in call_app' railties (3.2.1) lib/rails/rack/logger.rb:16:incall' actionpack (3.2.1) lib/action_dispatch/middleware/request_id.rb:22:in call' rack (1.4.1) lib/rack/methodoverride.rb:21:incall' rack (1.4.1) lib/rack/runtime.rb:17:in call' activesupport (3.2.1) lib/active_support/cache/strategy/local_cache.rb:72:incall' rack (1.4.1) lib/rack/lock.rb:15:in call' railties (3.2.1) lib/rails/engine.rb:479:incall' railties (3.2.1) lib/rails/application.rb:220:in call' railties (3.2.1) lib/rails/railtie/configurable.rb:30:inmethod_missing' rack (1.4.1) lib/rack/deflater.rb:13:in call' rack (1.4.1) lib/rack/content_length.rb:14:incall' railties (3.2.1) lib/rails/rack/log_tailer.rb:14:in call' rack (1.4.1) lib/rack/handler/webrick.rb:59:inservice' /Users/gabe/.rvm/rubies/ruby-1.9.3-p125/lib/ruby/1.9.1/webrick/httpserver.rb:138:in service' /Users/gabe/.rvm/rubies/ruby-1.9.3-p125/lib/ruby/1.9.1/webrick/httpserver.rb:94:inrun' /Users/gabe/.rvm/rubies/ruby-1.9.3-p125/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

noahd1 commented 11 years ago

Hi Gabe:

Looks valuable, but is there a way to reproduce this behavior in a test? It looks like instantiated_hash only gets set when something is actually instantiated...so it seems like it would be a problem, though looking at the tests, seems like that case is covered and green.

joshgoebel commented 11 years ago

Please commit this.

Try: rspec ./spec/oink/middleware_spec.rb

Running the single test it does fail... I bet they only pass in aggregate because your previous tests are changing the behavior of later tests (likely by using AR and resulting in the hash being setup already).

joshgoebel commented 11 years ago

You can work around this for now by putting this in the same initializer you use to setup your middlewarE:

  Oink.extend_active_record!
  ActiveRecord::Base.instantiated_hash={}
joshgoebel commented 11 years ago

Actually that seems to work for pow, but not rackup... different threads?

noahd1 commented 11 years ago

Thanks for the help reproducing it. I merged it - thought I don't know offhand what the difference would be between pow and rackup.

joshgoebel commented 11 years ago

No idea. I found another hack that worked for both, just monkey patching the entire log_activerecord routine to inject the ||= there, but it's major ugly.

When can we get a new gem pushed?

noahd1 commented 11 years ago

Ready to push, now just waiting on rubygems:

https://twitter.com/qrush/status/296647479397609472

noahd1 commented 11 years ago

Finally pushed now that rubygems is back up.