Deadlock в RSpec

on Rails

Недавно на глаза попался pull request с исправлением бага в RSpec - между двумя процессами возникал deadlock, который приводил к зависанию. Я не мог пройти мимо и не покопаться в деталях - не каждый же день встречаешь deadlock в Ruby-коде.

RSpec поддерживает опцию командной строки --bisect (документация), которая помогает бороться со случайно падающими тестами. Иногда падение теста зависит от того, какие тесты уже выполнились перед ним. В этом случае есть минимальная последовательность тестов, а возможно и несколько, которая приводит к падению. Определить такие последовательности как раз и помогает опция --bisect. В этом режиме RSpec перезапускает тесты несколько раз уменьшая их количество вдвое. Таким образом, RSpec должен запускать тесты изолированно друг от друга, а такую изоляцию гарантирует только запуск тестов в новом процессе.

Иногда запуск RSpec с опцией --bisect может закончиться зависанием. Впервые это зарепортили maintainer‘ы Puppet’а. Более того, они еще и разобрались в причине зависания:

Meanwhile the main process is hanging in waitpid at

Process.waitpid(pid)

A common reason why this might not show up in testing is if the result report in the tests is smaller than the underlying OS’s buffer size. In that case the runner process exits after writing to the buffer and the parent continues happily reading from the buffer. In my case the testsuite results are ~93kB and the processes deadlock.

Давайте разберемся в чем же здесь дело.

Как работает --bisect

RSpec запускает тесты двумя способами - используя shell-команду, что приводит к системным вызовам fork + exec, или делая fork своего процесса. В обоих случаях создается новый дочерний процесс. В первом варианте результат выполнения тестов пишется дочерним процессом в stdout, который доступен родителю. Во втором варианте для передачи данных между процессами используется системный неименованный pipe. Проблема возникает только в варианте с fork‘ом.

Для чтения и записи в pipe RSpec использует блокирующие операции - дочерний процесс записывает в pipe данные, а главный процесс ожидает завершения дочернего и далее читает данные из pipe‘а. Давайте остановимся на этом подробнее.

Блокирующее чтение означает, что если нужно прочитать n байт, но в системном буфере доступно меньше данных, операция чтения будет ожидать пока не придут остальные данные.

Блокирующая запись означает, что если нужно записать n байт, а в системном буфере не хватает свободного места (размер буфера же конечный и фиксированной длины), то операция записи будет ожидать пока из буфера не прочитают часть данных и не освободят место.

Родительский процесс делает системный вызов waitpid, чтобы дождаться завершения дочернего. После завершения процесс переходит в состояние “зомби” - системные ресурсы уже освобождены, но родительский процесс еще не узнал о завершении процесса. Родительский процесс обязан получить статус завершения дочернего процесса вызовом waitpid. После этого дочерний процесс окончательно удаляется из системы.

Проиллюстрируем это sequence-диаграммой:

Parent process создает новый дочерний процесс и ожидает его завершения. В новом процессе запускаются тесты и результат записывается в Pipe. Дочерний процесс завершается и операционная система (Kernel) возвращает статус завершения Parent process‘у как результат вызова waitpid. Далее Parent process читает данные из Pipe и продолжает операцию bisect.

Разбираем баг

Зависание RSpec’а легко воспроизводится следующим тестом:

RSpec.describe "a bunch of nothing" do
  (0...3000).each do |t|
    it { expect(t).to eq t }
  end
end

Команда rspec --bisect=verbose будет каждый раз зависать.

Запуск тестов в дочернем процессе и передача результатов родителю упрощенно выглядит так:

@read_io, @write_io = IO.pipe

# write into pipe some data
def run_specs
  packet = '*' * 1000
  @write_io.write("#{packet.bytesize}\n#{packet}")
end

# create a child process
pid = fork { run_specs }

# wait for its terminating
Process.waitpid(pid)

# read result
packet_size = Integer(@read_io.gets)
packet = @read_io.read(packet_size)

puts "packet size: #{packet.size}"

Здесь создается pipe и два IO объекта для записи (@write_io) и чтения из pipe‘а (@read_io). Далее вызовом метода fork создается новый дочерний процесс, в котором выполняется переданный блок. Дочерний процесс наследует файловые дескрипторы родительского, в том числе и дескрипторы для pipe‘а. Метод run_specs выполняется в дочернем процессе и записывает в pipe данные (1000 символов, т.е. байт). Родительский процесс после создания дочернего ожидает завершения делая вызов waitpid и затем читает данные из pipe‘а.

Если запустить этот код, передача данных отработает без ошибок и в консоль выведется сообщение “packet size: 1000”.

Но если увеличить 1000 до 66000, т.е. дочерний процесс будет записывать не 1000 байт, а 66000, то RSpec зависнет.

Причина лежит на поверхности - размер буфера pipe‘а ограничен. Если записать в pipe больше данных, чем он может вместить, то блокирующая операция записи будет ждать, пока из pipe‘а не прочитают часть данных и не освободят место. Но никто не читает из буфера. Родительский процесс будет читать, но только после завершения работы дочернего. А дочерний не может завершиться, потому что не может записать оставшиеся данные в pipe. Чтобы воспроизвести проблему объем данных (66000) должен быть заведомо больше размера буфера pipe‘а.

Эту ситуацию иллюстрирует следующая диаграмма:

Оба процесса сделали блокирующие вызовы (запись в pipe и ожидание завершения дочернего процесса) и попали в deadlock.

Таким образом, если RSpec в дочернем процессе записывает в stdout данные размером меньше чем 64 Kb, то ошибка не воспроизводится. Но если размер данных превышает 64 Kb, то получается deadlock и RSpec зависает.

Размер буфера pipe’а

Размер буфера никак не определяется ни стандартом POSIX ни документацией операционных систем. Величина зависит от реализации и, более того, может быть не фиксированной.

Согласно экспериментам буфер в pipe имеет следующие размеры (в байтах):

Darwin 13.4.0 65536
Linux 3.16.0 65536
Linux 4.4.59 65536
Solaris 10 20480
Solaris 11.3 25599

В то же время на MacOS размер буфера по умолчанию составляет 16 Kb, но если нужно операционная система увеличит его до 64 Kb.

Заглянем в код RSpec

В реализации --bisect интерес представляют два файла:

  • lib/rspec/core/bisect/fork_runner.rb (source) и
  • lib/rspec/core/bisect/utilities.rb (source)

Здесь реализован запуск тестов через fork (класс ForkRunner) и обмен данными через pipe (вспомогательный класс Channel).

Запуск тестов выполняется следующим образом:

def dispatch_run(run_descriptor)
  @run_dispatcher.dispatch_specs(run_descriptor)
  @channel.receive.tap do |result|
    if result.is_a?(String)
      raise BisectFailedError.for_failed_spec_run(result)
    end
  end
end

Первым делом запускаются сами тесты:

@run_dispatcher.dispatch_specs(run_descriptor)

а затем данные читаются из pipe‘а используя @channel. Рассмотрим метод dispatch_specs подробнее:

def dispatch_specs(run_descriptor)
  pid = fork { run_specs(run_descriptor) }
  Process.waitpid(pid)
end

Здесь форкается дочерний процесс, а родительский дожидается его завершения.

PS

Баг пофиксили убрав вызов Process.waitpid(pid). Теперь родительский процесс сразу переходит к чтению данных избегая deadlock‘а.

С одной стороны решили проблему с deadlock‘ом, но с другой - создали новую. Теперь дочерний процесс остается в состоянии “зомби”, так как никто не получает его статус завершения системным вызовом waitpid, а это означает утечку дескрипторов процессов. Когда количества процессов в операционной системе достигнет лимита, а он не такой уж и большой, нельзя будет создать новый дочерний процесс.

Ссылки