Week 8 - Alexander Belozerov

case_study.md

@@ -0,0 +1,98 @@
+# Case-study оптимизации
+
+## О нашем проекте
+Наш проект довольно большой, ему 12 лет, из них около 10 в бою, все это время код пишет команда в несколько человек, разработчики за это время часто менялись.
+Текущей команде досталось глубокое legacy со множеством проблем, в том числе с производительностью в production, устаревшими версиями, медленными тестами и деплоем.
+Мы сумели сдвинуть дело с мертвой точки, проапгрейдили Ruby (2.3 -> 2.6), Rails (3.2 -> 6.0), Postgres (9.6 -> 11), устранили самые проблемные места, ускорили деплой с 40 мин до 5, избавились от DatabaseCleaner, логов и анимации в тестах. Тем не менее, огромное количество проблем с производительностью еще осталось.
+
+## Актуальная проблема
+В рамках курса я попробовал много инструментов на рабочем проекте, настроил Skylight (мониторинг серверов в виде Prometheus / Grafana у нас уже был), rack-mini-profiler в production, попробовал WebPageTest, NewRelic. Нашел следующую главную точки роста производительности в production, однако, логика там непростая, и быстро переписать эту часть в рамках курса я не смогу.
+
+Другой большой проблемой являются медленные тесты. У нас их много: 17765 examples. Из них feature-тестов (Capybara): 2703 examples. Над производительностью тестов никто особо не думал, профилированием тестов не занимался. Даже без feature-тестов время выполнения локально - 210 минут (на CI мы, конечно, гоняем тесты в несколько потоков за меньшее время, но это не решает причину проблемы). Еще до курса было очевидно, что надо что-то с этим делать, но пока не брались.
+
+Я решил попробовать найти точки роста test-suite и оптимизировать их.
+
+Feature-тесты отложил на будущее, и начал профилировать остальные. Так как тестов тысячи, меня не очень интересовало ускорение одного конкретного теста, хотелось найти что-то общее у всех (например, медленные фабрики), тогда оптимизация общей точки роста может дать значитальное ускорение. 
+
+Я выделил набор тестов и проверил его с помощью FPROF:
+
+[TEST PROF INFO] Factories usage
+
+ Total: 16043
+ Total top-level: 7991
+ Total time: 22:17.417 (out of 31:52.484)
+ Total uniq factories: 126
+
+   total   top-level     total time      time per call      top-level time               name
+
+    2784          87        7.4269s            0.0027s             0.2208s       billing_plan
+    2717          14       44.0602s            0.0162s             1.6749s accounts_user_owner
+    2529        1354      544.5100s            0.2153s           291.0103s            account
+    1779        1380      348.3549s            0.1958s           220.7795s            listing
+     863         860      307.6894s            0.3565s           305.8707s            showing
+     515         515      113.7278s            0.2208s           113.7278s              user1
+     495         383       47.5119s            0.0960s            22.1478s           calendar
+     387         387       82.9471s            0.2143s            82.9471s               user
+     371         250       14.7314s            0.0397s            11.3327s        team_member
+     345          89        9.0071s            0.0261s             8.0340s            lockbox
+     217         198        2.0045s            0.0092s             1.9652s       feature_flag
+
+Стало очевидно, что фабрики не должны занимать столько времени, и я начал их профилировать.
+
+## Формирование метрики
+Для того, чтобы понимать, дают ли мои изменения положительный эффект на быстродействие программы я придумал использовать такую метрику: время выполнения набора тестов.
+
+## Гарантия корректности работы оптимизированной программы
+Проверка, что тесты не падают, позволяют не допустить изменения логики программы при оптимизации.
+
+## Feedback-Loop
+Для того, чтобы иметь возможность быстро проверять гипотезы я выстроил эффективный `feedback-loop`, который позволил мне получать обратную связь по эффективности сделанных изменений за пару минут.
+
+Вот как я построил `feedback_loop`:
+
+1. Измерял время создания с помощью FactoryBot N записей, и профилировал их с помощью RubyProf.
+2. После внесения изменений, проверял что тесты на модель проходят.
+3. Выделил небольшой набор тестов, который прогонял в режиме FPROF когда мне казалось, что изменения дают результат.
+4. Повторял.
+
+## Оптимизация
+
+### Находка №1
+Записи создаются медленно. В production это даже особо не заметно, потому что операции редкие.
+В тестах же дает сильный эффект.
+
+RubyProf с принтером CallStack позволил быстро найти точки роста.
+Я переписал создание записей более эффективным образом, и это сразу дало заметное ускорение всего test-suite.
+
+### Находка №2
+В одной часто используемой в тестах модил были after_commit коллбэки, которые занимали значительное время, при этом в тестах были абсолютно бесполезны. Отключение этих коллбэков в тестах дало второй очень заметный буст производительности.
+
+### Находка №3
+Проверка abilities в CanCanCan очень медленная. Мы кэшируем ее, и в production проблем нет. RubyProf с принтером Graph же показал, что на это уходит большое количество времени. Оказалось, что наш хитрый кэш в тестах не работает. Исправление этой проблемы дало самый заметный прирост производительности, при этом методом "пристального взгляда" эту проблему обнаружить было практически невозможно.
+
+## Результаты
+
+После оптимизации отчет FPROF на том же наборе тестов стал выглядеть так:
+
+[TEST PROF INFO] Factories usage
+
+ Total: 16045
+ Total top-level: 7993
+ Total time: 08:25.608 (out of 14:23.078)
+ Total uniq factories: 126
+
+   total   top-level     total time      time per call      top-level time               name
+
+    2784          87        7.4791s            0.0027s             0.2238s       billing_plan
+    2717          14       45.6794s            0.0168s             1.3903s accounts_user_owner
+    2529        1354      171.2999s            0.0677s            92.7004s            account
+    1779        1380      110.5442s            0.0621s            70.9234s            listing
+     865         862      110.2283s            0.1274s           109.6833s            showing
+     515         515       38.2237s            0.0742s            38.2237s              user1
+     495         383       16.9989s            0.0343s             7.4745s           calendar
+     387         387       26.5623s            0.0686s            26.5623s               user
+     371         250        9.6569s            0.0260s             6.8537s        team_member
+     345          89        3.5653s            0.0103s             2.6716s            lockbox
+     217         198       27.5467s            0.1269s            25.4168s       feature_flag
+
+А общее время выполнения всего test-suite упало с 210 минут до 150 минут, то есть мы выиграли целый час, при более чем адекватном количестве усилий. При этом я уверен, что можно ускорить все еще раза в два без переписывания каких-то больших кусков проекта.