Хабр мертв или еще пинать будем? Deadlock via ruby / forpes.ru

Главная
Хабр мертв или еще пинать будем? Deadlock via ruby

Хабр мертв или еще пинать будем? Deadlock via ruby

02.03.2016 15:00

sl_bug 12 5300 Источник

За ранее прошу прощения за все грамматические, пунктуационные и орфографические ошибки.

На фоне темы о том, что хабр умер выяснилось, что нечего писать. Нету интересных тем. Но я потом подумал и нашел интересную тему, правда с одной проблемой. Это скорее не тема, а вопрос — ищите ответ сами. Не уверен будет ли это интересно слушателям…

Итак, предистория. Есть приложение на 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. Да, потоки в руби — это боль.

Комментарии (12)

youlose
02.03.2016 19:53
#8791027
1. Многопоточное программирование везде — боль
2. На той строчке где редис висит — он там может и не висеть совсем, это же блок обработки исключения, проблема может быть скорее всего в операции чтения из сокета с редисом(выше) и возникнуть из-за того, что редис залип (такое может быть если памяти нехватает, например).
3. Как вы поняли что тут дедлок где-то в руби не понятно.
1. antarx
  02.03.2016 21:00
  #8791117
  1. В Go многопоточное программирование радует, в основном проблемы возникают после неаккуратных оптимизаций.
  2. На моём опыте, редис при нехватке памяти на сервере без особых проблем залезает в своп. Если у редиса указан max-memory и отсутствие eviction, то при окончании памяти на попытку добавления записи редис просто отдаёт false.
  1. youlose
    02.03.2016 22:44
    #8791317
    +1
    1. Go вообще другой язык для других задач и сравнивать его с Руби или Питоном в принципе неверно. И использовать очереди для раздачи задач потокам можно и в Руби. Да и в Go проектах багов не меньше (сейчас вот с Grafana ковыряюсь, очень глючный проект, но полезный).
    2. Когда он залазит в своп — то адско тормозит и не может ответить и у меня было на практике что он совсем вис (причём не один раз).
    
    ptQa
    02.03.2016 22:52
    #8791341
    +1
    Интересная цепочка: "Многопоточное программирование везде — боль" -> "Нет же, вот же Go" -> "Нельзя сравнивать Ruby с Go"
    
    facepalm
    
    youlose
    02.03.2016 23:33
    #8791405
    Специально для пейсателей: «И использовать очереди для раздачи задач потокам можно и в Руби».
    И «Нет же, вот же Go» такого не может быть потому что кроме строгой типизации (и вследствие этого большей скорости работы кода, хотя Руби используют не там где нужна суперскорость, его используют там где надо БЫСТРО написать работающий и оттестированный код, чего в Go никогда не будет) он не имеет никаких фич, которых нет в том же Руби, а вот у Руби есть невероятное количество особенностей и парадигм, которые для Go либо не реализованы, либо недостижимы из-за костноязычности синтаксиса.
    
    develop7
    03.03.2016 00:21
    #8791489
    +1
    его используют там где надо БЫСТРО написать работающий и оттестированный код
    вот как ни брался за руби (+ рельсы по ситуации) для этих целей, так всё время что-то мешало. В случае же с Go (в 2014) мне удалось доизучить ЯП, подобрать подходящие библиотеки (вебсервер + router, amqp, json) и запилить работающий (в раз 50 быстрее руби) код за один рабочий день.
1. develop7
  02.03.2016 22:22
  #8791265
  +1
  в erlang оно вполне себе прямолинейное
  1. youlose
    02.03.2016 22:51
    #8791333
    Да, в функциональных языках код проще в разных потоках исполнять, но всякие race condition'ы и там встречаются.
    Совокупность инженерных решений принятых в Эрланге меня очень впечатляют.
    
    develop7
    03.03.2016 00:14
    #8791465
    встречаются, но сильно реже, да и отлавливаются не в пример быстрее (это я по опыту работы с обоими, если что)

jehy
02.03.2016 21:41
#8791195
+4
Не могу придумать, что может быть интересно читателям в этой публикации. Заголовок для привлечения внимания, длинное описание проблемы в конкретным проекте безо всяких итогов и пояснений. "Баги случаются".

ToSHiC
02.03.2016 22:44
#8791315
Если хотите поймать дедлок, то вам нужно получить стектрейсы всех тредов, и дальше просто глазами можно найти проблемный мьютекс. А чтобы получить все стектрейсы делайте так:
```
gdb -ex "set pagination 0" -ex "thread apply all bt" --batch -p <PID>
```

mgyk
02.03.2016 23:09
#8791371
Попробуйте коммерческий Sidekiq там как раз закрыта проблема с недовыполненными задачами