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)


  1. 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. Когда он залазит в своп — то адско тормозит и не может ответить и у меня было на практике что он совсем вис (причём не один раз).


        1. ptQa
          02.03.2016 22:52
          #8791341
          +1

          Интересная цепочка: "Многопоточное программирование везде — боль" -> "Нет же, вот же Go" -> "Нельзя сравнивать Ruby с Go"

          facepalm


          1. youlose
            02.03.2016 23:33
            #8791405

            Специально для пейсателей: «И использовать очереди для раздачи задач потокам можно и в Руби».
            И «Нет же, вот же Go» такого не может быть потому что кроме строгой типизации (и вследствие этого большей скорости работы кода, хотя Руби используют не там где нужна суперскорость, его используют там где надо БЫСТРО написать работающий и оттестированный код, чего в Go никогда не будет) он не имеет никаких фич, которых нет в том же Руби, а вот у Руби есть невероятное количество особенностей и парадигм, которые для Go либо не реализованы, либо недостижимы из-за костноязычности синтаксиса.


            1. develop7
              03.03.2016 00:21
              #8791489
              +1

              его используют там где надо БЫСТРО написать работающий и оттестированный код
              вот как ни брался за руби (+ рельсы по ситуации) для этих целей, так всё время что-то мешало. В случае же с Go (в 2014) мне удалось доизучить ЯП, подобрать подходящие библиотеки (вебсервер + router, amqp, json) и запилить работающий (в раз 50 быстрее руби) код за один рабочий день.


    1. develop7
      02.03.2016 22:22
      #8791265
      +1

      1. в erlang оно вполне себе прямолинейное


      1. youlose
        02.03.2016 22:51
        #8791333

        Да, в функциональных языках код проще в разных потоках исполнять, но всякие race condition'ы и там встречаются.
        Совокупность инженерных решений принятых в Эрланге меня очень впечатляют.


        1. develop7
          03.03.2016 00:14
          #8791465

          встречаются, но сильно реже, да и отлавливаются не в пример быстрее (это я по опыту работы с обоими, если что)


  1. jehy
    02.03.2016 21:41
    #8791195
    +4

    Не могу придумать, что может быть интересно читателям в этой публикации. Заголовок для привлечения внимания, длинное описание проблемы в конкретным проекте безо всяких итогов и пояснений. "Баги случаются".


  1. ToSHiC
    02.03.2016 22:44
    #8791315

    Если хотите поймать дедлок, то вам нужно получить стектрейсы всех тредов, и дальше просто глазами можно найти проблемный мьютекс. А чтобы получить все стектрейсы делайте так:

    gdb -ex "set pagination 0" -ex "thread apply all bt" --batch -p <PID>


  1. mgyk
    02.03.2016 23:09
    #8791371

    Попробуйте коммерческий Sidekiq там как раз закрыта проблема с недовыполненными задачами