diff --git a/case_study.md b/case_study.md new file mode 100644 index 0000000..1089695 --- /dev/null +++ b/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 минут, то есть мы выиграли целый час, при более чем адекватном количестве усилий. При этом я уверен, что можно ускорить все еще раза в два без переписывания каких-то больших кусков проекта.