За ранее прошу прощения за все грамматические, пунктуационные и орфографические ошибки.
На фоне темы о том, что хабр умер выяснилось, что нечего писать. Нету интересных тем. Но я потом подумал и нашел интересную тему, правда с одной проблемой. Это скорее не тема, а вопрос — ищите ответ сами. Не уверен будет ли это интересно слушателям…
Итак предистория. Есть приложение на RoR. Есть стандартный sidekiq для обработки задач в фоне. И все прекрасно работает. SomeClass.perform_later и магия происходит.
И вот в один прекрасный солнечный декабрьский день мы случайно обнаружили, что наша фоновая задача вроде отработала, но ничего не сделала. Мы решили что был глюк и просто проигнорировали. Далее в январе случилось еще два похожих случая и мы решили поколупать глубже. Читали логи heroku (где у нас приложение) и заметили что heroku раз в сутки просто рестартит ваше приложение, и если фоновая задача не доработала, то она умрет и запись в базе о том что она еще работает останется (в нашем случае). Решаем проблему через хуки sidekiq’а. На стопе записываем что не доделалась задача, на старте проверяем есть ли что доделать и запускаем. Все в целом идеально:
Sidekiq.configure_server do |config| config.on(:startup) do OurJob.find_not_finished.restart! end config.on(:shutdown) do OurJob.find_unfinished.save_for_restart end end
Но от клиентов все равно поступают жалобы что «задача запустилась и вечно работает». Расследуем дальше…
Многочисленные попытки поймать косяк долго ничего не приносили. И вот в один прекрасный день удалось локально его поймать — sidekiq просто завис. Отправив ему сигнал TTIN чтобы узнать где он завис мы увидели что все потоки висят на IO.select. Примерно так (некоторые на чтении не из редиса, а из amazon s3):
TID-owkc753x4 WARN: ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/connection/ruby.rb:52:in `select' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/connection/ruby.rb:52:in `rescue in _read_from_socket' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/connection/ruby.rb:48:in `_read_from_socket' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/connection/ruby.rb:41:in `gets' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/connection/ruby.rb:273:in `read' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:249:in `block in read' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:237:in `io' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:248:in `read' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:113:in `block in call' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:218:in `block (2 levels) in process' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:354:in `ensure_connected' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:208:in `block in process' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:293:in `logging' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:207:in `process' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:113:in `call' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:196:in `block in call_with_timeout' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:267:in `with_socket_timeout' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis/client.rb:195:in `call_with_timeout' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis.rb:1097:in `block in _bpop' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis.rb:57:in `block in synchronize' ~/.rvm/rubies/ruby-2.3.0/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis.rb:57:in `synchronize' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis.rb:1094:in `_bpop' ~/.rvm/gems/ruby-2.3.0/gems/redis-3.2.2/lib/redis.rb:1139:in `brpop' ~/.rvm/gems/ruby-2.3.0/gems/sidekiq-4.1.0/lib/sidekiq/fetch.rb:35:in `block in retrieve_work' ~/.rvm/gems/ruby-2.3.0/gems/sidekiq-4.1.0/lib/sidekiq.rb:84:in `block in redis' ~/.rvm/gems/ruby-2.3.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:64:in `block (2 levels) in with' ~/.rvm/gems/ruby-2.3.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:63:in `handle_interrupt' ~/.rvm/gems/ruby-2.3.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:63:in `block in with' ~/.rvm/gems/ruby-2.3.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:60:in `handle_interrupt' ~/.rvm/gems/ruby-2.3.0/gems/connection_pool-2.2.0/lib/connection_pool.rb:60:in `with' ~/.rvm/gems/ruby-2.3.0/gems/sidekiq-4.1.0/lib/sidekiq.rb:81:in `redis' ~/.rvm/gems/ruby-2.3.0/gems/sidekiq-4.1.0/lib/sidekiq/fetch.rb:35:in `retrieve_work' ~/.rvm/gems/ruby-2.3.0/gems/sidekiq-4.1.0/lib/sidekiq/processor.rb:85:in `get_one' ~/.rvm/gems/ruby-2.3.0/gems/sidekiq-4.1.0/lib/sidekiq/processor.rb:95:in `fetch' ~/.rvm/gems/ruby-2.3.0/gems/sidekiq-4.1.0/lib/sidekiq/processor.rb:78:in `process_one' ~/.rvm/gems/ruby-2.3.0/gems/sidekiq-4.1.0/lib/sidekiq/processor.rb:67:in `run' ~/.rvm/gems/ruby-2.3.0/gems/sidekiq-4.1.0/lib/sidekiq/util.rb:16:in `watchdog' ~/.rvm/gems/ruby-2.3.0/gems/sidekiq-4.1.0/lib/sidekiq/util.rb:24:in `block in safe_thread'
Как я понял этот IO.select сразу уходит через биндинги в libc. И в итоге, по какой-то причине, мы отловили deadlock.
Далее я попытался изолировать проблему и пришел к выводу что такое происходит только в связке sidekiq + fog (пример тут) и воспроизводится только очень иногда.
Также нашелся баг внутри fog’а, который с 2014-го года не смогли поправить. Далее были попытки дебажить через gdb, попытки узнать количество дескрипторов и т.д. Ничего в итоге не получилось. В данный момент просто надеемся что эта проблема будет вылазить не часто.
Вот такая получилась статья. Интересно, но без итогов.
P.S. Да потоки в руби это боль.
ссылка на оригинал статьи https://habrahabr.ru/post/278385/
Добавить комментарий