Home → Support →

Thread related errors when run under Unicorn

mguterl

18 Jan, 2010 02:30 PM via web

Admin Functions

• Edit
• Remove

Our environment:
Rails 2.3.5
Ruby EE 1.8.7-2009.10
NewRelic RPM (we pulled from HEAD some time last week, but I had to remove, so I'm not sure of the exact version)

The author of Unicorn was kind enough to chime in here: http://rubyforge.org/pipermail/mongrel-unicorn/2010-January/000328.... but I'm not really sure what I need to do.

We see the issue right after we deploy, which involves re-forking all of the workers.

Backtrace:

ThreadError: stopping only thread note: use sleep to stop forever
/usr/local/lib/ruby/1.8/monitor.rb:285:in `stop'
/usr/local/lib/ruby/1.8/monitor.rb:285:in `mon_acquire'
/usr/local/lib/ruby/1.8/monitor.rb:214:in `mon_enter'
/usr/local/lib/ruby/1.8/monitor.rb:240:in `synchronize'
/usr/local/lib/ruby/1.8/logger.rb:496:in `write'
/usr/local/lib/ruby/1.8/logger.rb:326:in `add'
/usr/local/lib/ruby/1.8/logger.rb:374:in `info'
/home/deploy/public_html/rm/releases/20100115190903/vendor/plugins/newrelic_rpm/lib/new_relic/agent/agent.rb:46:in `ensure_worker_thread_started'
/home/deploy/public_html/rm/releases/20100115190903/vendor/plugins/newrelic_rpm/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:231:in `perform_action'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/base.rb:532:in `send'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/base.rb:532:in `process_without_filters'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/filters.rb:606:in `process'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/base.rb:391:in `process'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/base.rb:386:in `call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/routing/route_set.rb:437:in `call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/dispatcher.rb:87:in `dispatch'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/dispatcher.rb:121:in `_call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/dispatcher.rb:130:in `build_middleware_stack'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/activerecord/lib/active_record/query_cache.rb:29:in `call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/activerecord/lib/active_record/query_cache.rb:29:in `call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:34:in `cache'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/activerecord/lib/active_record/query_cache.rb:9:in `cache'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/activerecord/lib/active_record/query_cache.rb:28:in `call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:361:in `call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/string_coercion.rb:25:in `call'
/usr/local/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/head.rb:9:in `call'
/usr/local/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/methodoverride.rb:24:in `call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/params_parser.rb:15:in `call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/session/cookie_store.rb:93:in `call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/activesupport/lib/active_support/cache/strategy/local_cache.rb:24:in `call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/failsafe.rb:26:in `call'
/usr/local/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/lock.rb:11:in `call'
/usr/local/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/lock.rb:11:in `synchronize'
/usr/local/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/lock.rb:11:in `call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/actionpack/lib/action_controller/dispatcher.rb:106:in `call'
/home/deploy/public_html/rm/releases/20100115190903/vendor/rails/railties/lib/rails/rack/static.rb:31:in `call'
/usr/local/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/urlmap.rb:46:in `call'
/usr/local/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/urlmap.rb:40:in `each'
/usr/local/lib/ruby/gems/1.8/gems/rack-1.0.1/lib/rack/urlmap.rb:40:in `call'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/lib/unicorn.rb:585:in `process_client'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/lib/unicorn.rb:657:in `worker_loop'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/lib/unicorn.rb:655:in `each'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/lib/unicorn.rb:655:in `worker_loop'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/lib/unicorn.rb:547:in `spawn_missing_workers'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/lib/unicorn.rb:544:in `fork'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/lib/unicorn.rb:544:in `spawn_missing_workers'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/lib/unicorn.rb:540:in `each'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/lib/unicorn.rb:540:in `spawn_missing_workers'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/lib/unicorn.rb:554:in `maintain_worker_count'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/lib/unicorn.rb:216:in `start'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/lib/unicorn.rb:28:in `run'
/usr/local/lib/ruby/gems/1.8/gems/unicorn-0.96.0/bin/unicorn_rails:207
/usr/local/bin/unicorn_rails:19:in `load'
/usr/local/bin/unicorn_rails:19

1. Support Staff 2 Posted by Bill Kayser on 18 Jan, 2010 09:28 PM

   

   Where does this error show up? Does your app still report metrics to RPM? This is the first report we've had of this with Unicorn, maybe because not many people are using REE with Unicorn?

   I'm a little puzzled by this. I understand the suggestion. I don't understand how it would fix this problem.

   I'm researching. I copied you on the note I sent to Eric.

   Admin Functions

   • Edit
   • Remove

2. 3 Posted by mguterl on 18 Jan, 2010 09:35 PM

   

   The error shows up when we "upgrade" our Unicorn process. Which is detailed in "Procedure to replace a running unicorn executable" at http://unicorn.bogomips.org/SIGNALS.html

   Yes, the metrics are still reported, although we've had to turn off RPM to avoid the errors.

   I imagine most people using Unicorn will be using REE, because the memory conservation that is achieved through the use of REE + copy-on-write + fork.

   I too am puzzled by this, but my knowledge of the internals of Unicorn, RPM, and mixing threads + fork is limited. Eric is extremely responsive / helpful, so I'm hoping he may be able to provide more insight.

   Admin Functions

   • Edit
   • Split
   • Remove

3. 4 Posted by mguterl on 28 Jan, 2010 05:53 PM

   

   I have been using Eric's suggested monkey patch:

   require 'logger'
   class Logger::LogDevice
     def write(message)
       @dev.syswrite(message)
     end
   
     def close
       @dev.close
     end
   end
   

   for almost a week now and I can report that it fixes the issue. If this is something you eventually fix inside of the RPM plugin itself, please let me know directly so that I can remove the workaround.

   Thanks,
   Michael Guterl

   Admin Functions

   • Edit
   • Split
   • Remove

4. Support Staff 5 Posted by Bill Kayser on 28 Jan, 2010 06:22 PM

   

   I want to avoid having our gem monkey patch other libraries. I know from experience how maddening it is to have unexpected side effects on seemingly unrelated libraries by virtue of using some external utility.

   I think our workaround is going to be this: just don't do it. I think if I remove all logging calls but errors and extremely improbably warnings in the background threads then this should never occur.

   Your error above comes from an info message indicating rpm is intializing after a fork. I'll bet you could also work around the problem by changing the rpm log level to "error".

   Thanks for your help in tracking this down! I'll make the changes in the next release, due out hopefully next week.

   Admin Functions

   • Edit
   • Remove

5. Bill Kayser resolved this discussion on 28 Jan, 2010 06:22 PM.

6. mguterl re-opened this discussion on 08 Feb, 2010 03:27 PM

7. 6 Posted by mguterl on 08 Feb, 2010 03:27 PM

   

   Hi Bill, have the changes made it into the plugin yet? We're anxious to remove the monkey patch and we don't want to lose track of this issue.

   Admin Functions

   • Edit
   • Split
   • Remove

8. Support Staff 7 Posted by Bill Kayser on 08 Feb, 2010 04:22 PM

   

   I haven't pushed out the updates yet. Should be out by tomorrow.

   Admin Functions

   • Edit
   • Remove

9. Support Staff 8 Posted by Bill Kayser on 19 Feb, 2010 09:38 PM

   

   Michael, I'm going to close out this issue. I think I mentioned elsewhere the new agent gem has been released and contains the workaround for the unicorn problem.

   Please let us know if you experience any other unicorn problems. We still have some work to do to give this better support.

   Admin Functions

   • Edit
   • Remove

10. Bill Kayser resolved this discussion on 19 Feb, 2010 09:38 PM.

11. mguterl re-opened this discussion on 19 Feb, 2010 09:43 PM

12. 9 Posted by mguterl on 19 Feb, 2010 09:43 PM

    

    Go ahead, I thought it was already closed for some reason. I've been
    checking our log reports every day and I have not seen a segfault
    since upgrading. Thanks for the help!

    Admin Functions

    • Edit
    • Split
    • Remove

13. Bill Kayser resolved this discussion on 20 Feb, 2010 12:12 AM.

Comments are currently closed for this discussion. You can start a new one.