Как в Redash заметили и исправили проблему, вызвавшую деградацию производительности Python-кода

Автор оригинала: Omer Lachish
  • Перевод
Недавно в Redash приступили к смене одной системы выполнения задач на другую. А именно — они начали переход с Celery на RQ. На первом этапе на новую платформу перевели лишь те задания, которые не выполняют запросы напрямую. Среди таких заданий — отправка электронных писем, выяснение того, какие запросы должны быть обновлены, запись пользовательских событий и другие вспомогательные задачи.



После развёртывания всего этого было замечено, что RQ-воркеры требуют гораздо больше вычислительных ресурсов для решения того же объёма задач, который раньше решали средствами Celery.

Материал, перевод которого мы сегодня публикуем, посвящён рассказу о том, как в Redash выяснили причину проблемы и справились с ней.

Пара слов о различиях Celery и RQ


В Celery и в RQ имеется концепция процессов-воркеров. И там и там для организации параллельного выполнения заданий используется создание форков. Когда запускается воркер Celery — создаётся несколько процессов-форков, каждый из которых автономно обрабатывает задачи. В случае с RQ экземпляр воркера содержит лишь один подпроцесс (известный как «рабочая лошадка»), который выполняет одну задачу, а потом уничтожается. Когда воркер загружает очередное задание из очереди — он создаёт новую «рабочую лошадку».

При работе с RQ можно достичь того же уровня параллелизма, что и при работе с Celery, просто запуская больше процессов-воркеров. Однако между Celery и RQ есть одно тонкое различие. В Celery воркер создаёт множество экземпляров подпроцессов при запуске, после чего многократно их использует для выполнения множества заданий. А в случае с RQ для каждого задания нужно создавать новый форк. И тот и другой подходы имеют свои плюсы и минусы, но здесь мы об этом говорить не будем.

Измерение производительности


Прежде чем я приступил к профилированию, я решил замерить производительность системы, выяснив, сколько времени воркер-контейнеру нужно для обработки 1000 заданий. Я решил сосредоточиться на задании record_event, так как это — часто встречающаяся легковесная операция. Для измерения производительности я воспользовался командой time. Это потребовало внести в код проекта пару изменений:

  1. Для измерения производительности выполнения 1000 задач я решил использовать пакетный режим RQ, в котором, после обработки заданий, осуществляется выход из процесса.
  2. Мне хотелось избежать влияния на мои измерения других заданий, которые могли быть запланированы на то время, когда я измерял производительность системы. Поэтому я переместил record_event в отдельную очередь, названную benchmark, заменив @job(‘default’) на @job(‘benchmark’). Сделано это было сразу перед объявлением record_event в tasks/general.py.

Теперь можно было приступать к измерениям. Для начала мне хотелось узнать о том, сколько времени занимает запуск и остановка воркера без нагрузки. Это время можно было вычесть из итоговых результатов, полученных позже.

$ docker-compose exec worker bash -c "time ./manage.py rq workers 4 benchmark"

real	
0m14.728s
user	
0m6.810s
sys	
0m2.750s

Инициализация воркера на моём компьютере заняла 14.7 секунд. Я это запомнил.

Затем я поместил 1000 тестовых заданий record_event в очередь benchmark:

$ docker-compose run --rm server manage shell <<< "from redash.tasks.general import record_event; [record_event.delay({ 'action': 'create', 'timestamp': 0, 'org_id': 1, 'user_id': 1, 'object_id': 0, 'object_type': 'dummy' }) for i in range(1000)]"

После этого я запустил систему так же, как делал это раньше, и узнал о том, сколько времени занимает обработка 1000 заданий.

$ docker-compose exec worker bash -c "time ./manage.py rq workers 4 benchmark"

real	
1m57.332s
user	
1m11.320s
sys	
0m27.540s

Вычтя из того, что получилось, 14.7 секунд, я узнал о том, что 4 воркера обрабатывают 1000 заданий в течение 102 секунд. Теперь попытаемся узнать о том, почему это так. Для этого мы, в то время, пока воркеры заняты делом, исследуем их с помощью py-spy.

Профилирование


Добавим в очередь ещё 1000 заданий (сделать это нужно из-за того, что в ходе ранее проведённых измерений все задания были обработаны), запустим воркеры и пошпионим за ними.

$ docker-compose run --rm server manage shell <<< "from redash.tasks.general import record_event; [record_event.delay({ 'action': 'create', 'timestamp': 0, 'org_id': 1, 'user_id': 1, 'object_id': 0, 'object_type': 'dummy' }) for i in range(1000)]"
$ docker-compose exec worker bash -c 'nohup ./manage.py rq workers 4 benchmark & sleep 15 && pip install py-spy && rq info -u "redis://redis:6379/0" | grep busy | awk "{print $3}" | grep -o -P "\s\d+" | head -n 1 | xargs py-spy record -d 10 --subprocesses -o profile.svg -p'
$ open -a "Google Chrome" profile.svg

Я знаю о том, что предыдущая команда получилась очень длинной. В идеале, чтобы улучшить её читабельность, её стоило бы разбить на отдельные фрагменты, разделив её в тех местах, где встречаются последовательности символов &&. Но команды должны выполняться последовательно внутри одной сессии docker-compose exec worker bash, поэтому всё выглядит именно так. Вот описание того, что делает эта команда:

  1. Запускает 4 пакетных воркера в фоне.
  2. Ждёт 15 секунд (примерно столько нужно для того, чтобы закончилась их загрузка).
  3. Устанавливает py-spy.
  4. Запускает rq-info и выясняет PID одного из воркеров.
  5. Записывает сведения о работе воркера с ранее полученным PID в течение 10 секунд и сохраняет данные в файле profile.svg

В результате получен следующий «пламенный график».


Визуализация данных, собранных py-spy

Проанализировав эти данные, я заметил, что задание record_event тратит большой отрезок времени его выполнения в sqlalchemy.orm.configure_mappers. Это происходит при выполнении каждого задания. Из документации я узнал о том, что в интересующее меня время происходит инициализация отношений всех ранее созданных мапперов.

Подобные вещи совершенно не обязаны происходить с каждым форком. Мы можем один раз инициализировать отношения в родительском воркере и избежать повторного выполнения этой задачи в «рабочих лошадках».

В результате я добавил в код вызов sqlalchemy.org.configure_mappers() до запуска «рабочей лошадки» и снова провёл измерения.

$ docker-compose run --rm server manage shell <<< "from redash.tasks.general import record_event; [record_event.delay({ 'action': 'create', 'timestamp': 0, 'org_id': 1, 'user_id': 1, 'object_id': 0, 'object_type': 'dummy' }) for i in range(1000)]
$ docker-compose exec worker bash -c "time ./manage.py rq workers 4 benchmark"

real	
0m39.348s
user	
0m15.190s
sys	
0m10.330s

Если вычесть из этих результатов 14.7 секунд, то окажется, что мы улучшили время, необходимое 4 воркерам на обработку 1000 заданий, со 102 секунд до 24.6 секунд. Это — четырёхкратное улучшение производительности! Благодаря этому исправлению мы смогли вчетверо сократить продакшн-ресурсы RQ и сохранить ту же пропускную способность системы.

Итоги


Из всего этого я сделал следующий вывод: стоит помнить о том, что приложение ведёт себя по-разному в том случае, если оно представляет собой единственный процесс, и в том случае, если речь идёт о форках. Если при выполнении каждого задания приходится решать какие-то тяжёлые служебные задачи, то решить их лучше заблаговременно, сделав это один раз до выполнения форка. Подобные вещи не выявляются в ходе тестирования и разработки, поэтому, почувствовав, что с проектом что-то не так, замерьте его быстродействие и дойдите до конца в ходе поиска причин проблем с его производительностью.

Уважаемые читатели! Сталкивались ли вы с проблемами в производительности Python-проектов, которые можно было решить, тщательно проанализировав работающую систему?


  • +33
  • 3,5k
  • 5
RUVDS.com
1 520,27
RUVDS – хостинг VDS/VPS серверов
Поделиться публикацией

Похожие публикации

Комментарии 5

    +1

    Зачем все переходят с celery на rq? Мне кажется, это странная тенденция :(

      0
      Люди «хотят нового», «новое» не обязано быть лучше.
        0
        При чем здесь «новое»? RQ совершенно не новее celery. Он просто легче в освоении, вероятно поэтому люди и пробуют.
      +3

      Вы просто не понимаете, это же новое слово в производительности вычислений!


      Смотрите:


      1. Запуск воркера — всего-то какие-то жалкие 15 секунд. Но давайте не будем это учитывать.
      2. тестируем на
        на задании record_event, так как это — часто встречающаяся легковесная операция.
      3. улучшили время, необходимое 4 воркерам на обработку 1000 заданий, со 102 секунд до 24.6 секунд.

      4. Считаем:
        1000 заданий / 4 воркера / 25 секунд == 1 воркер сохраняет умопомрачительные 10 записей в секунду!!!
      5. К тому же мы сохраняем не абы что, а сложную структуру: 6 полей, 2 типа данных, 106 байт (если включать пробелы и служебные символы JSON)
        { 'action': 'create', 'timestamp': 0, 'org_id': 1, 'user_id': 1, 'object_id': 0, 'object_type': 'dummy' }
      6. Пропускная способность (оптимизированного в 4 раза) воркера поражает: 106 байт * 10 rec/sec = ~1 Килобайт в секунду!!!

      Вдумайтесь в эти цифры, уважаемые покупатели. Запустив 4 воркера (извиним автора за англицизмы — он англоговорящий), мы достигаем 4кб в секунду! Страшно подумать, что будет, если запустить 16 воркеров. Не у каждого в 2019 году есть столько ядер в процессоре! ...


      </sarcasm OFF>


      Я не знаю, куда эти воркеры сохраняют эти "dummy" записи (судя по скорости — печатают на принтере), и какая конфигурация компьютера у автора статьи (по крайней мере, на нем можно писать статьи и выкладывать их в интернет), но рекомендую всем срочно бросать Celery и переходить на RQ (извините, снова сарказм).

        0
        Я всё же думаю, что они не просто сохраняют эти «записи», а используют их как аргумент для выполнения каких-то более ресурсозатратных операций.

      Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

      Самое читаемое