Workers crash when processing jobs #115

Closed
brandonhilkert opened this Issue Apr 6, 2012 · 16 comments

7 participants

@brandonhilkert
Collaborator

I have a job that I run during the night for each of our users. I'm attempting to queue the job with Resque and process them with Sidekiq to ease the transition.

Here is the job:

class MatchesAlgoForAlertsJob
  include Sidekiq::Worker
  @queue = :nightly

  def perform(user_id)
    user = User.find(user_id)
    Algorithm.matches_algo_for_alerts(user)
  end
end

It appears as though it starts to process them and then dies. The rescue worker has always worked.

2012-04-06T11:20:27Z 28000 TID-ov8hgfl94 INFO: Booting sidekiq 0.11.1 with Redis at localhost:6379
2012-04-06T11:20:27Z 28000 TID-ov8hgfl94 INFO: Running in ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.3.0]
2012-04-06T11:20:27Z 28000 TID-ov8gl6gnk INFO: Starting processing, hit Ctrl-C to stop
2012-04-06T11:20:27Z 28000 TID-ov8hngan8 INFO: MatchesAlgoForAlertsJob MSG-ov8hnw3ts start
2012-04-06T11:20:27Z 28000 TID-ov8ho2jiw INFO: MatchesAlgoForAlertsJob MSG-ov8hnvrpo start
2012-04-06T11:20:27Z 28000 TID-ov8ho2yjg INFO: MatchesAlgoForAlertsJob MSG-ov8hnvgak start
2012-04-06T11:20:27Z 28000 TID-ov8hng57o INFO: MatchesAlgoForAlertsJob MSG-ov8hnuxok start
2012-04-06T11:20:28Z 28000 TID-ov8hng7dg INFO: MatchesAlgoForAlertsJob MSG-ov8hntf9o start
2012-04-06T11:20:28Z 28000 TID-ov8hng9j8 INFO: MatchesAlgoForAlertsJob MSG-ov8hnmj10 start
2012-04-06T11:20:28Z 28000 TID-ov8hnfr9g INFO: MatchesAlgoForAlertsJob MSG-ov8hn7qhw start
2012-04-06T11:20:28Z 28000 TID-ov8ho2o28 INFO: MatchesAlgoForAlertsJob MSG-ov8hn2y10 start
2012-04-06T11:20:28Z 28000 TID-ov8ho35hg INFO: MatchesAlgoForAlertsJob MSG-ov8hn47co start
2012-04-06T11:20:28Z 28000 TID-ov8hnflv0 INFO: MatchesAlgoForAlertsJob MSG-ov8hnrsm0 start
2012-04-06T11:20:28Z 28000 TID-ov8hnfo0s INFO: MatchesAlgoForAlertsJob MSG-ov8hn92oc start
2012-04-06T11:20:28Z 28000 TID-ov8hnfq6k INFO: MatchesAlgoForAlertsJob MSG-ov8hn875c start
2012-04-06T11:20:28Z 28000 TID-ov8gsxceo INFO: MatchesAlgoForAlertsJob MSG-ov8hn7ltk start
2012-04-06T11:20:28Z 28000 TID-ov8ho2z6s INFO: MatchesAlgoForAlertsJob MSG-ov8hnnp9k start
2012-04-06T11:20:28Z 28000 TID-ov8ho3a8k INFO: MatchesAlgoForAlertsJob MSG-ov8hnldto start
2012-04-06T11:20:28Z 28000 TID-ov8gsx70s INFO: MatchesAlgoForAlertsJob MSG-ov8hnaz20 start
2012-04-06T11:20:28Z 28000 TID-ov8gsx96k INFO: MatchesAlgoForAlertsJob MSG-ov8hnx9go start
2012-04-06T11:20:28Z 28000 TID-ov8gsxbcc INFO: MatchesAlgoForAlertsJob MSG-ov8hntksk start
2012-04-06T11:20:28Z 28000 TID-ov8hn83l0 INFO: MatchesAlgoForAlertsJob MSG-ov8hnl9i4 start
2012-04-06T11:20:28Z 28000 TID-ov8go7ons INFO: MatchesAlgoForAlertsJob MSG-ov8hn8pbs start
2012-04-06T11:20:28Z 28000 TID-ov8go7qtk INFO: MatchesAlgoForAlertsJob MSG-ov8hn1vrs start
2012-04-06T11:20:28Z 28000 TID-ov8hnsq7g INFO: MatchesAlgoForAlertsJob MSG-ov8hfgtb4 start
2012-04-06T11:20:28Z 28000 TID-ov8hnkwcs INFO: MatchesAlgoForAlertsJob MSG-ov8hf9jfw start
2012-04-06T11:20:28Z 28000 TID-ov8hn7gqs INFO: MatchesAlgoForAlertsJob MSG-ov8hnoabc start
2012-04-06T11:20:28Z 28000 TID-ov8hgfaj0 INFO: MatchesAlgoForAlertsJob MSG-ov8hnf3ao start
2012-04-06T11:20:30Z 28000 TID-ov8hngan8 INFO: MatchesAlgoForAlertsJob MSG-ov8hnw3ts done: 2.294 sec
2012-04-06T11:20:30Z 28000 TID-ov8ho2jiw INFO: MatchesAlgoForAlertsJob MSG-ov8hnvrpo done: 2.291 sec
2012-04-06T11:20:30Z 28000 TID-ov8hng57o INFO: MatchesAlgoForAlertsJob MSG-ov8hnuxok done: 2.463 sec
2012-04-06T11:20:30Z 28000 TID-ov8ho2yjg INFO: MatchesAlgoForAlertsJob MSG-ov8hnvgak done: 2.489 sec
2012-04-06T11:20:30Z 28000 TID-ov8hng7dg INFO: MatchesAlgoForAlertsJob MSG-ov8hntf9o done: 2.438 sec
2012-04-06T11:20:30Z 28000 TID-ov8hng9j8 INFO: MatchesAlgoForAlertsJob MSG-ov8hnmj10 done: 2.437 sec
2012-04-06T11:20:30Z 28000 TID-ov8hnfr9g INFO: MatchesAlgoForAlertsJob MSG-ov8hn7qhw done: 2.451 sec
2012-04-06T11:20:30Z 28000 TID-ov8hnflv0 INFO: MatchesAlgoForAlertsJob MSG-ov8hnrsm0 done: 2.362 sec
2012-04-06T11:20:30Z 28000 TID-ov8ho35hg INFO: MatchesAlgoForAlertsJob MSG-ov8hn47co done: 2.365 sec
2012-04-06T11:20:30Z 28000 TID-ov8hnfo0s INFO: MatchesAlgoForAlertsJob MSG-ov8hn92oc done: 2.363 sec
2012-04-06T11:20:30Z 28000 TID-ov8hnfq6k INFO: MatchesAlgoForAlertsJob MSG-ov8hn875c done: 2.305 sec
2012-04-06T11:20:30Z 28000 TID-ov8gsx70s INFO: MatchesAlgoForAlertsJob MSG-ov8hnaz20 done: 2.211 sec
2012-04-06T11:20:30Z 28000 TID-ov8gsxceo INFO: MatchesAlgoForAlertsJob MSG-ov8hn7ltk done: 2.305 sec
2012-04-06T11:20:30Z 28000 TID-ov8ho2z6s INFO: MatchesAlgoForAlertsJob MSG-ov8hnnp9k done: 2.23 sec
2012-04-06T11:20:30Z 28000 TID-ov8ho3a8k INFO: MatchesAlgoForAlertsJob MSG-ov8hnldto done: 2.228 sec
2012-04-06T11:20:30Z 28000 TID-ov8gsx96k INFO: MatchesAlgoForAlertsJob MSG-ov8hnx9go done: 2.222 sec
2012-04-06T11:20:30Z 28000 TID-ov8gsxbcc INFO: MatchesAlgoForAlertsJob MSG-ov8hntksk done: 2.27 sec
2012-04-06T11:20:30Z 28000 TID-ov8go7ons INFO: MatchesAlgoForAlertsJob MSG-ov8hn8pbs done: 2.212 sec
2012-04-06T11:20:30Z 28000 TID-ov8hnsq7g INFO: MatchesAlgoForAlertsJob MSG-ov8hfgtb4 done: 2.144 sec
2012-04-06T11:20:30Z 28000 TID-ov8hnkwcs INFO: MatchesAlgoForAlertsJob MSG-ov8hf9jfw done: 2.143 sec
2012-04-06T11:20:30Z 28000 TID-ov8hn7gqs INFO: MatchesAlgoForAlertsJob MSG-ov8hnoabc done: 2.142 sec
2012-04-06T11:20:30Z 28000 TID-ov8hgfaj0 INFO: MatchesAlgoForAlertsJob MSG-ov8hnf3ao done: 2.141 sec
2012-04-06T11:20:36Z 28000 TID-ov8ho2o28 INFO: MatchesAlgoForAlertsJob MSG-ov8hn2y10 done: 7.871 sec
2012-04-06T11:20:39Z 28000 TID-ov8hn83l0 INFO: MatchesAlgoForAlertsJob MSG-ov8hnl9i4 done: 11.071 sec
/Users/bhilkert/.rbenv/versions/1.9.2-p290/bin/sidekiq:19: stack level too deep (SystemStackError)
@brandonhilkert
Collaborator

Here's another:

2012-04-06T11:27:40Z 28365 TID-ow97a4vsk INFO: Booting sidekiq 0.11.1 with Redis at localhost:6379
2012-04-06T11:27:40Z 28365 TID-ow97a4vsk INFO: Running in ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.3.0]
2012-04-06T11:27:40Z 28365 TID-ow96mxsyc INFO: Starting processing, hit Ctrl-C to stop
2012-04-06T11:27:40Z 28365 TID-ow97nt4qg INFO: MatchesAlgoForAlertsJob MSG-ow97non94 start
2012-04-06T11:27:40Z 28365 TID-ow97noirg INFO: MatchesAlgoForAlertsJob MSG-ow97nbj14 start
2012-04-06T11:27:40Z 28365 TID-ow97nsax4 INFO: MatchesAlgoForAlertsJob MSG-ow97m5kl0 start
2012-04-06T11:27:40Z 28365 TID-ow97nt560 INFO: MatchesAlgoForAlertsJob MSG-ow97ijv5k start
2012-04-06T11:27:41Z 28365 TID-ow97nt7bs INFO: MatchesAlgoForAlertsJob MSG-ow97i07yo start
2012-04-06T11:27:41Z 28365 TID-ow97nt9hk INFO: MatchesAlgoForAlertsJob MSG-ow97hyxxg start
2012-04-06T11:27:41Z 28365 TID-ow97nnv6k INFO: MatchesAlgoForAlertsJob MSG-ow97bf7xc start
2012-04-06T11:27:41Z 28365 TID-ow97nokl0 INFO: MatchesAlgoForAlertsJob MSG-ow97b6fmo start
2012-04-06T11:27:41Z 28365 TID-ow97nseik INFO: MatchesAlgoForAlertsJob MSG-ow97b1v3c start
2012-04-06T11:27:41Z 28365 TID-ow96p4rqc INFO: MatchesAlgoForAlertsJob MSG-ow97bedh8 start
2012-04-06T11:27:41Z 28365 TID-ow96p4tw4 INFO: MatchesAlgoForAlertsJob MSG-ow97mmjxw start
2012-04-06T11:27:41Z 28365 TID-ow96p4w1w INFO: MatchesAlgoForAlertsJob MSG-ow97hwdss start
2012-04-06T11:27:41Z 28365 TID-ow97no0is INFO: MatchesAlgoForAlertsJob MSG-ow97bebts start
2012-04-06T11:27:41Z 28365 TID-ow97a4vsk ERROR: Manager#processor_died died
2012-04-06T11:27:41Z 28365 TID-ow97a4vsk ERROR: task was terminated
2012-04-06T11:27:41Z 28365 TID-ow97a4vsk ERROR: /Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/celluloid-0.10.0/lib/celluloid/task.rb:23:in `suspend'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/celluloid-0.10.0/lib/celluloid/actor.rb:45:in `call'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/celluloid-0.10.0/lib/celluloid/actor_proxy.rb:76:in `method_missing'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/celluloid-0.10.0/lib/celluloid.rb:115:in `new_link'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/manager.rb:95:in `block in processor_died'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/util.rb:42:in `watchdog'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/manager.rb:91:in `processor_died'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/celluloid-0.10.0/lib/celluloid/actor.rb:225:in `handle_exit_event'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/celluloid-0.10.0/lib/celluloid/actor.rb:146:in `block in run'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/celluloid-0.10.0/lib/celluloid/task.rb:45:in `block in initialize'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/1.9.1/thread.rb:71: stack level too deep (SystemStackError)
2012-04-06T11:27:41Z 28365 TID-ow97noirg INFO: MatchesAlgoForAlertsJob MSG-ow97nbj14 fail: 0.434 sec
2012-04-06T11:27:41Z 28365 TID-ow97noirg WARN: exception class/object expected
2012-04-06T11:27:41Z 28365 TID-ow97noirg WARN: /Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/mongo_mapper-0.11.0/lib/mongo_mapper/plugins/associations/belongs_to_association.rb:15:in `proxy_class'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/mongo_mapper-0.11.0/lib/mongo_mapper/plugins/associations.rb:68:in `build_proxy'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/mongo_mapper-0.11.0/lib/mongo_mapper/plugins/associations.rb:76:in `get_proxy'
(eval):8:in `user='
/Users/bhilkert/Dropbox/code/meeteor/app/models/analytic_log.rb:591:in `create_log_entry'
/Users/bhilkert/Dropbox/code/meeteor/app/models/analytic_log.rb:572:in `method_missing'
/Users/bhilkert/Dropbox/code/meeteor/app/lib/algorithm/base.rb:120:in `matches_algo'
/Users/bhilkert/Dropbox/code/meeteor/app/lib/algorithm/base.rb:73:in `block in matches_algo_for_alerts'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/mongo_mapper-0.11.0/lib/mongo_mapper/plugins/associations/proxy.rb:104:in `each'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/mongo_mapper-0.11.0/lib/mongo_mapper/plugins/associations/proxy.rb:104:in `method_missing'
/Users/bhilkert/Dropbox/code/meeteor/app/lib/algorithm/base.rb:71:in `matches_algo_for_alerts'
/Users/bhilkert/Dropbox/code/meeteor/app/lib/algorithm.rb:63:in `matches_algo_for_alerts'
/Users/bhilkert/Dropbox/code/meeteor/app/workers/matches_algo_for_alerts_job.rb:7:in `perform'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/processor.rb:35:in `block (2 levels) in process'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/chain.rb:75:in `call'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/chain.rb:75:in `block in invoke'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/chain.rb:77:in `block in invoke'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/server/retry_jobs.rb:28:in `call'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/chain.rb:77:in `block in invoke'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/server/unique_jobs.rb:6:in `call'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/chain.rb:77:in `block in invoke'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/server/logging.rb:9:in `call'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/chain.rb:77:in `block in invoke'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/server/exception_handler.rb:9:in `call'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/chain.rb:77:in `block in invoke'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/chain.rb:80:in `call'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/middleware/chain.rb:80:in `invoke'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/processor.rb:34:in `block in process'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/processor.rb:63:in `stats'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/sidekiq-0.11.1/lib/sidekiq/processor.rb:33:in `process'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/celluloid-0.10.0/lib/celluloid/calls.rb:98:in `dispatch'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/celluloid-0.10.0/lib/celluloid/actor.rb:212:in `block in handle_message'
/Users/bhilkert/.rbenv/versions/1.9.2-p290/lib/ruby/gems/1.9.1/gems/celluloid-0.10.0/lib/celluloid/task.rb:45:in `block in initialize'
@ryanlecompte

This looks like you're using mongo mapper here. Is that library thread-safe?

@mperham
Owner

It looks like the Processor is running out of stack. This could be caused by infinite recursion in your worker. Second stack shows a problem with the manager that I haven't a clue how could happen. @tarcieri might need to swing by and lend us his wisdom.

@brandonhilkert
Collaborator

Good question about it being thread-safe....I'll reach out to the maintainer to confirm.

@brandonhilkert
Collaborator

Haven't heard back, but from poking around message boards and event machine gems, it would appear that MongoMapper is not thread-safe. Guess this is a deal-breaker huh?

@krainboltgreene

Mongoid is working on being Threadsafe it seems: https://github.com/mongoid/mongoid/issues/1291

@tarcieri
Collaborator

Celluloid runs all methods in fibers, and it looks like you're exceeding the 4k stack size limitations that fibers impose. That's orthogonal to the issue of not using a thread-safe library, which won't work either.

A quick fix is to try to run the code outside of a fiber using defer { ... your code here ... }, however that won't help you if it's not thread safe.

@fbjork

Try using the Ruby mongo driver directly and see if that helps.

@mperham
Owner

I know this sounds crazy, but you could also run Sidekiq in single-threaded mode with -c 1 and see if the error still occurs. You lose all of the benefits of Sidekiq of course but it will tell you if thread-safety is the issue. You'll need to configure Redis like in #116 or use master to make it work though.

@brandonhilkert
Collaborator

It appears that doing one job worked better (it processed many more). Still got the stack error, but after @tarcieri explanation, seems like these jobs in particular aren't the best candidate because it's doing a LOT of crunching that would likely go over the stack size limitation.

[02:16:52] bhilkert [~/Dropbox/code/meeteor] (sidekiq *) $ bundle exec sidekiq -q nightly -c 1
2012-04-06T18:17:37Z 32453 TID-oxs5ozuss INFO: Booting sidekiq 0.11.1 with Redis at localhost:6379
2012-04-06T18:17:37Z 32453 TID-oxs5ozuss INFO: Running in ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin11.3.0]
2012-04-06T18:17:37Z 32453 TID-oxs4h1hag INFO: Starting processing, hit Ctrl-C to stop
2012-04-06T18:17:37Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5c6980 start
2012-04-06T18:17:37Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5c6980 done: 0.292 sec
2012-04-06T18:17:37Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p0hi0 start
2012-04-06T18:17:37Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p0hi0 done: 0.094 sec
2012-04-06T18:17:37Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p0aog start
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p0aog done: 0.094 sec
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p03fc start
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p03fc done: 0.118 sec
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p55ws start
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p55ws done: 0.094 sec
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p02qc start
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p02qc done: 0.226 sec
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5pdz3o start
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5pdz3o done: 0.109 sec
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5ow8ds start
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5ow8ds done: 0.082 sec
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p0nuw start
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p0nuw done: 0.104 sec
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p0xxo start
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p0xxo done: 0.09 sec
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nszls start
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nszls done: 0.082 sec
2012-04-06T18:17:38Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nut2g start
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nut2g done: 0.088 sec
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nx1vw start
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nx1vw done: 0.09 sec
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5ny6kw start
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5ny6kw done: 0.163 sec
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p60l8 start
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p60l8 done: 0.025 sec
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5ni81k start
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5ni81k done: 0.154 sec
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5oymxc start
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5oymxc done: 0.08 sec
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nxqx0 start
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nxqx0 done: 0.15 sec
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p0f50 start
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p0f50 done: 0.091 sec
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p0g7w start
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p0g7w done: 0.026 sec
2012-04-06T18:17:39Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nrpw8 start
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nrpw8 done: 0.103 sec
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p00f0 start
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p00f0 done: 0.094 sec
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nwz50 start
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nwz50 done: 0.021 sec
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5d05o8 start
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5d05o8 done: 0.105 sec
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5oycb4 start
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5oycb4 done: 0.081 sec
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5pbylo start
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5pbylo done: 0.092 sec
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p1w34 start
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p1w34 done: 0.028 sec
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nexgo start
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5nexgo done: 0.149 sec
2012-04-06T18:17:40Z 32453 TID-oxs5ozmvs INFO: MatchesAlgoForAlertsJob MSG-oxs5p1mi4 start
/Users/bhilkert/.rbenv/versions/1.9.2-p290/bin/sidekiq:19: stack level too deep (SystemStackError)
@ryanlecompte

That's an unfortunate limitation of wrapping all Celluloid async calls in a fiber. :-(

@ryanlecompte

Hopefully @mperham's old issue for dynamically increasing the Fiber stack size will get some love, although it was filed 2 years ago. :-(

http://bugs.ruby-lang.org/issues/3187

@mperham mperham closed this in e832145 Apr 6, 2012
@mperham
Owner

Try master now. I'm unclear on what happens if an error is raised in Processor#stats but @tarcieri and I will figure it out.

@brandonhilkert
Collaborator

Yup, that worked for me when running with -c 1.

@tarcieri
Collaborator

I've opened an issue for this on the Celluloid tracker if you'd like to discuss further:

celluloid/celluloid#45

@jackbit

I haven't solution yet, please follow Issue #327: Stack Level Too Deep

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment