Is this the behavior that supposedly indicates a problem with a particular action? Mongrel in development mode randomly hangs on random actions. Further requests cause USR1 logs like: Mon Sep 18 13:04:03 PDT 2006: 0 threads sync_waiting for /, 2 still active in mongrel. Mon Sep 18 13:07:52 PDT 2006: 1 threads sync_waiting for /public/stylesheets/table.css, 3 still active in mongrel. Mon Sep 18 13:08:21 PDT 2006: 2 threads sync_waiting for /, 4 still active in mongrel. 0 threads sync_waiting? Isn''t that good? Sync waiting for a file? Is that supposed to happen? I thought that the USR1 output was supposed to help point out which action(s) had a problem, but the (random) action that actually caused the hang is never displayed, just whatever was the latest request after the hang. This doesn''t seem to happen in production mode, at least it hasn''t so far. It happens every few minutes in development, and sending INT to the process causes this: Thread #<Thread:0x3388f10 sleep> is too old, killing.Mon Sep 18 13:16:44 PDT 2006: Error calling Dispatcher.dispatch #<Sync_m::Err::UnknownLocker: Thread(#<Thread:0x3388f10 run>) not locked.> /usr/local/lib/ruby/1.8/sync.rb:57:in `Fail'' /usr/local/lib/ruby/1.8/sync.rb:63:in `Fail'' /usr/local/lib/ruby/1.8/sync.rb:183:in `sync_unlock'' /usr/local/lib/ruby/1.8/sync.rb:231:in `synchronize'' /usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/rails.rb:83:in `process'' /usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:580:in `process_client'' /usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:579:in `process_client'' /usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:686:in `run'' /usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:686:in `run'' /usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:673:in `run'' /usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/configurator.rb:267:in `run'' /usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/configurator.rb:266:in `run'' /usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/bin/mongrel_rails:127:in `run'' /usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/command.rb:211:in `run'' /usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/bin/mongrel_rails:231/usr/local/bin/mongrel_rails:18 Thread #<Thread:0x338df38 sleep> is too old, killing.Mon Sep 18 13:16:44 PDT 2006: Error calling Dispatcher.dispatch #<Sync_m::Err::UnknownLocker: Thread(#<Thread:0x338df38 run>) not locked.> [same backtrace as above] Has anybody else even seen this? Steve
On Mon, 2006-09-18 at 13:22 -0700, Steven Lumos wrote:> Is this the behavior that supposedly indicates a problem with a > particular action? Mongrel in development mode randomly hangs on > random actions. Further requests cause USR1 logs like: > > Mon Sep 18 13:04:03 PDT 2006: 0 threads sync_waiting for /, 2 still active in mongrel. > Mon Sep 18 13:07:52 PDT 2006: 1 threads sync_waiting for /public/stylesheets/table.css, 3 still active in mongrel. > Mon Sep 18 13:08:21 PDT 2006: 2 threads sync_waiting for /, 4 still active in mongrel. >Looks like / is blocking. Is this a Rails action? Also, you should probably run this in production mode as in development mode it''s kind of slow and won''t give you reasonable results.> 0 threads sync_waiting? Isn''t that good? Sync waiting for a file? > Is that supposed to happen? >Yep, 0 is what you want, but you really want to start this up in production mode and then thrash the suspect action with something httperf. As for the file, this means that your apache instance isn''t serving files but mongrel is. I suspect since you were running in development mode that you weren''t behind a web server though.> I thought that the USR1 output was supposed to help point out which > action(s) had a problem, but the (random) action that actually caused > the hang is never displayed, just whatever was the latest request > after the hang. >The log doesn''t display whichever is stuck, it just periodically lists how many requests are waiting for which actions. You gotta pound it or run it in heavy production to get a better sense.> This doesn''t seem to happen in production mode, at least it hasn''t so > far. It happens every few minutes in development, and sending INT to > the process causes this: >Yep, that''s something blocking your threads. See what happens is you have a Rails action that''s got things locked with Sync. A bunch of Mongrel threads pile up behind this sync lock waiting for rails to finish. Eventually when you shutdown with INT mongrel tries to do a graceful shutdown. It goes through all the active threads, sees that you''ve got a bunch that are really old, and then it starts killing them so you can get a stack trace. Hope that helps. -- Zed A. Shaw, MUDCRAP-CE Master Black Belt Sifu http://www.zedshaw.com/ http://mongrel.rubyforge.org/ http://www.lingr.com/room/3yXhqKbfPy8 -- Come get help.
Zed Shaw <zedshaw at zedshaw.com> writes:> On Mon, 2006-09-18 at 13:22 -0700, Steven Lumos wrote: >> Is this the behavior that supposedly indicates a problem with a >> particular action? Mongrel in development mode randomly hangs on >> random actions. Further requests cause USR1 logs like: >> >> Mon Sep 18 13:04:03 PDT 2006: 0 threads sync_waiting for /, 2 still active in mongrel. >> Mon Sep 18 13:07:52 PDT 2006: 1 threads sync_waiting for /public/stylesheets/table.css, 3 still active in mongrel. >> Mon Sep 18 13:08:21 PDT 2006: 2 threads sync_waiting for /, 4 still active in mongrel. >> > > Looks like / is blocking. Is this a Rails action? Also, you should > probably run this in production mode as in development mode it''s kind of > slow and won''t give you reasonable results. > >> 0 threads sync_waiting? Isn''t that good? Sync waiting for a file? >> Is that supposed to happen? >> > Yep, 0 is what you want, but you really want to start this up in > production mode and then thrash the suspect action with something > httperf.So far it hasn''t happened in production mode.> As for the file, this means that your apache instance isn''t serving > files but mongrel is. I suspect since you were running in development > mode that you weren''t behind a web server though.Right. In production Apache is serving files. But does it make sense that Mongrel is failing to serve files? I thought only Rails was locked.>> I thought that the USR1 output was supposed to help point out which >> action(s) had a problem, but the (random) action that actually caused >> the hang is never displayed, just whatever was the latest request >> after the hang. >> > > The log doesn''t display whichever is stuck, it just periodically lists > how many requests are waiting for which actions. You gotta pound it or > run it in heavy production to get a better sense. > >> This doesn''t seem to happen in production mode, at least it hasn''t so >> far. It happens every few minutes in development, and sending INT to >> the process causes this: >> > > Yep, that''s something blocking your threads. See what happens is you > have a Rails action that''s got things locked with Sync. A bunch of > Mongrel threads pile up behind this sync lock waiting for rails to > finish. Eventually when you shutdown with INT mongrel tries to do a > graceful shutdown. It goes through all the active threads, sees that > you''ve got a bunch that are really old, and then it starts killing them > so you can get a stack trace. > > Hope that helps.In this case only Mongrel is in the stack trace. I was especially wondering about #<Sync_m::Err::UnknownLocker: Thread(#<Thread:0x3388f10 run>) not locked.> Is that expected? Thanks for the help. Steve> -- > Zed A. Shaw, MUDCRAP-CE Master Black Belt Sifu > http://www.zedshaw.com/ > http://mongrel.rubyforge.org/ > http://www.lingr.com/room/3yXhqKbfPy8 -- Come get help.