diff --git a/case-study.md b/case-study.md new file mode 100644 index 0000000..6f77e8d --- /dev/null +++ b/case-study.md @@ -0,0 +1,189 @@ +# Task 8 + +## Introduction + +Я работаю в компании igooods - доставка продуктов на дом. У нас монолит на Ruby on Rails, который вот уже несколько месяцев потихоньку растаскиваем. У нас уже вынесена пользовательская фронтовая часть в отдельный проект на ReactJS. В монолите у нас осталась API (для реакта и мобильных приложений iOS & Android), админка сделаная в Rails-way стиле, а также есть еще пара Rails Engines с API сборщика и курьера. + +Проект начал разрабатываться в 2015 году аутсорсинговой компанией, но с недавнего времени руководство решило набрать штат разработчиков. Я пришел в компанию в середине Марта этого года. Сейчас работаю в команде мобильной разработки (iOS & Android apps), отвечаю за бекенд часть. +В качестве системы мониторинга и сбора логов используем DataDog. И по моим наблюдениям производительность приложения неуклонно деградирует. Никто особо не следит за производительностью, нет алертов на долгие ответы, часть эндпоинтов увеличило среднее время ответа в несколько раз (x2 x3) за время моего совсем не пристального наблюдения. + +В общем я думаю мне будет чем заняться как минимум до конца года. + +## Stack + +- Ruby on Rails +- PostgreSQL +- Elasticsearch +- DataDog +- rspec + test-prof + +## Choose case + +Для начала, я пошел к своему менеджеру, показал ему несколько проблемных эндпоинтов в датадоге, и сказал что готов их всех оптимизировать. Он выбрал наиболее критичную на его взгляд функциональность - это поиск в каталоге. + +Для поиска в API предусмотрено два эндпоинта и оба они отвечали в среднем примерно за 350 ms (p50), (p99 > 3 sec). + +Бюджетом метрики было выбрано время 200 мс. + +## Case 1 First search + +Поиск в каталоге у нас происходит по следующему принципу: сначала пользователю выдается часть результатов с разбивкой по категориям (1 запрос), а потом он может выбрать конкретную (или все) и посмотреть все там (2 запрос). + +Первым я решил оптимизировать первый запрос с разбивкой по категориям. + +### Step 1. Preparing + +Первое что я сделал - это настроил `local_production` окружение и потестил скорость на своем ноутбуке, с помощью утилиты Apach Benchmark. Оказалось что время ответа у нас с продом примерно одинаковое. Perfect! + +``` +Document Length: 41400 bytes + +Concurrency Level: 1 +Time taken for tests: 3.109 seconds +Complete requests: 10 +Failed requests: 0 +Total transferred: 418820 bytes +HTML transferred: 414000 bytes +Requests per second: 3.22 [#/sec] (mean) +Time per request: 310.853 [ms] (mean) +Time per request: 310.853 [ms] (mean, across all concurrent requests) +Transfer rate: 131.57 [Kbytes/sec] received + +Connection Times (ms) + min mean[+/-sd] median max +Connect: 0 0 0.0 0 0 +Processing: 294 311 14.7 307 339 +Waiting: 294 311 14.7 307 339 +Total: 294 311 14.7 307 339 + +Percentage of the requests served within a certain time (ms) + 50% 307 + 66% 307 + 75% 316 + 80% 334 + 90% 339 + 95% 339 + 98% 339 + 99% 339 + 100% 339 (longest request) +``` + +### Step 3. Using Ruby-prof + +Далее я начал профилировать и искать самый жирный по CPU участок кода. И нашел его практически сразу, это оказался не сам поиск, но подготовка ответа на клиент. +Посмотрев поближе, что происходит в самом жирном методе, я увидел, что после группировки записей на каждую группировку следует запрос количества в Elastic. т.е. здесь мы имели классический N+1, только в elastic. + +### Step 4.1 Elasticsearch to DataDog + +При просмотре логов локально, я видел запросы в эластик, но в датадоге их небыло. Поэтому следующим моим пулреквестом стало подключение эластика к датадогу. Картина в датадоге по этому эндпоинту стала более очевидной - запросы в эластик отжирали кучу времени. Плюс я увидел запросы, которые мне не показывались в development логе - `index_name/count`. + +### Step 4.2 Do you realy need it? + +У нас в компании не оказалось хороших специалистов по эластику, поэтому, вместо того чтобы думать об оптимизации самих запросов в эластик, я спросил у своей mobile команды, и команды frontend (web) используют ли они это количество из ответа. Оказалось, что кол-во товаров в каждой категории отображается после поиска в web, а ios и android этого не используют. Далее были не продолжительные переговоры с командой веба, и принято решение просто выпилить расчет количества из ответа, и за количеством они будут ходить по другому эндпоинту (который уже есть, но нуждается в небольшой доработке по входящим параметрам). + +### Step 5. Something else? + +Задачи были поставлены, и взяты в следующий спринт на исполнение. Я пока выпилил не нужную кучу запросов, и замерил время ответа с помощью ab. Оно сильно уменьшилось, и стало в районе 190 - 220 мс. Взглянув еще раз в логи, я увидел там N+1 запрос в базу на получение главной категории (у нас используется gem `ancestry`). Причем это все происходит в одном из основных сериалайзеров, и если убрать N+1 из него - получим небольшой прирост производительности почти в половине приложения и перестанем нагружать БД ненужной работой. + +### Step 6. Cache it stupid + +Ancestry не позволяет легко и просто предзагрузить данные, к тому же даже если сделать это, придется передавать их в сериалайзеры во множестве местах. Исходя из этого, я выбрал путь кеширования (хранения) нужной информации прямо в таблице БД. Тогда все решится обычным добавлением ассоциации в eager_load/includes +Для этого я сделал миграцию по добавлению поля, и отдельный rake-task для заполнения этого поля. Также внес необходимые изменения в код создания объекта. Выложил пулреквест. + +### Step 7. Finishing + +Теперь оставалось только внести изменения в сериалайзер, и убрать N+1, что я и сделал. +Бенчмарки обрадовали. В бюджет уложился. + +``` +Document Length: 41298 bytes + +Concurrency Level: 1 +Time taken for tests: 1.503 seconds +Complete requests: 10 +Failed requests: 0 +Total transferred: 417800 bytes +HTML transferred: 412980 bytes +Requests per second: 6.65 [#/sec] (mean) +Time per request: 150.269 [ms] (mean) +Time per request: 150.269 [ms] (mean, across all concurrent requests) +Transfer rate: 271.52 [Kbytes/sec] received + +Connection Times (ms) + min mean[+/-sd] median max +Connect: 0 0 0.0 0 0 +Processing: 130 150 17.4 152 179 +Waiting: 130 150 17.5 151 179 +Total: 130 150 17.4 152 179 + +Percentage of the requests served within a certain time (ms) + 50% 152 + 66% 154 + 75% 157 + 80% 178 + 90% 179 + 95% 179 + 98% 179 + 99% 179 + 100% 179 (longest request) +``` + +### Step 8. Waiting for deploy + +В данный момент команда web уже сдалала свое дело, и мой последний PR с оптимизацией уедет в продакшн в ближайшем релизе. + +## Case 2. Second search + +### Step 1. DataDog + +После подключения эластика к мониторингу я увидел что здесь в среднем делается 7! запросов в эластик. Это оказалось для меня неожиданностью. Поразбиравшись "а зачем так много ведь по идее достаточно одного?", я понял что одним тут не обойдешься (если опять таки не урезать ответ сервера), но тремя - вполне (это все с высоты моего поверхностного знания эластика, а так... может и можно в один уложиться). + +### Step 2. Reduce queries + +Я потратил некоторое количество времени на изучение вопроса как получить в одном запросе данные, в нужном мне порядке, и нашел ответ. В данный момент переписываю код на использование результатов нового запроса. По моим прогнозам - как раз останется 3 (и в некоторых случаях 4) необходимых запроса. По бенчмаркам пока не могу сказать, на сколько уменьшится время. + +### Step 3. Bug... + +При раскуривании всего этого дела, я обнаружил баг, что в некоторых случаях (применение доп. фильтров по поисковому запросу) вспомогательная информация, отправляемая в ответе по этому поиску - некорректна. Но при этом в приложениях этого бага не видно, т.е. имеем не всегда нужную работу на сервере. + +В планах обговорить это с командой, и вынести куда нибудь еще получение этой информации, т.к. она далеко не всегда полчается им нужна. + +### Step4 To be continued... + +## Case 3. CI + +### Step 1. Description + +У нас очень долго (от 7 до 10 минут) исполняется job по прогону тестов на CI. +В 7 домашке я пытался воткнуть нам parallel_tests и время было просто прекрасным - CI проходил за 4 минуты (и это без балансировки). Но к сожалению получили рандомно падающие тесты с ошибками нейминга. Команда бекендеров в целом оказалась против такого. + +### Step 2. Occasion + +На CI (да и на локалке тоже) периодически падали тесты, когда эластик по каким-то непонятным причинам оказывался недоступен. Обидно, когда из-за независящих от тебя причин падает CI, и приходится перезапускать его (а иногда и несколько раз). +Обращался к нашим девопсам - обещали посмотреть и решить проблему, но так и ни фига не сделали пока. + +И вот однажды после очередного падения, я решил залезть в тест и посмотреть, так ли нужен в нем эластик, т.к. судя по тесту было не понятно зачем он там. И в теле самого теста я никаких запросов в индекс не нашел. + +### Step 3. Holy shit!!! + +И внезапно оказалось что в spec_helper было установлено следующее `Chewy.strategy(:urgent)`. То есть мы дрючим эластик практически во всех тестах, где надо и где не надо. Каждое создание/обновление товара или даже позиции в корзине обновляло индекс в эластике. + +Я изменил стратегию на bypass, которая обновляет индекс только по явному требованию, отредактировал пару мест в приложении, чтобы учитывалась текущая установленная стратегия. + +### Step 4. Catshooting + +До кучи, я решил разобраться с проблемой котиков. Недавно у меня закончилось место на диске. При расследовании выяснилось что у меня очень много фотографий котиков в папке uploads (60Gb). Котик по умолчанию загружался в фабрике создания сотрудника, причем валидации на обязательность аватарки не было. Вынес в треит и после этого починил 2 теста, которые реально проверяли автарку. +Создал задачу на будущее об очистке артифактов после прогона тестов. + +### Step 5. Take Profit +Выложил пулреквест. Job с тестами теперь выполняется на CI за 4,5 - 5 минут. Нехилый профит как мне кажется. Заодно и уменьшили внезапные падения тестов из-за недоступности эластика. + +## Результаты + +Удалось применить полученные на курсе знания в своем проекте. +Ранее также занимался задачами оптимизации, но больше вслепую без использования профилировщиков. Одни раз использовал ruby-spy. Но в целом было все удачно. Но это скорее от безобразно написанного кода, и бездумных решений авторов (в том числе моих)). +Самый интересный кейс был с sidekiq воркером, который отжирал все 220 GB памяти сервера за 4 часа непрерывной и умирал, без результатов. +И мне удалось сделать так чтобы он на тех же данных работал 15 минут и жрал только 3,5 GB памяти (just memoization). + +Здесь же, мне помогли профилировщики и мониторинг, и без них было совсем не очевидно по коду где именно главная точка роста. +В планах и дальше заниматься оптимизацией API и не только. Кайф от этого получал всегда :)