Task8 Work Cases

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 и не только. Кайф от этого получал всегда :)