Optimise performance 7

case-study.md

@@ -0,0 +1,87 @@
+# Case-study оптимизации
+
+## Актуальная проблема
+
+Нужно оптимизировать test-suite `dev.to`, а именно время выполнения всех тестов в пакете.
+
+Для оптимизации нам понадобится ряд инструментов профилирования и метрика для оценки и сравнения итераций.
+
+## Формирование метрики
+
+В качестве основной метрики имеет смысл рассматривать общее время прохождения всех тестов в секундах.
+Чтобы обеспечить наблюдение за итоговыми результатами, а так же прогрессом оптимизации, будем использовать сбор метрики в базу `InfluxDB` и выводить график в `Chronograf`.
+
+## Вникаем в детали системы, чтобы найти главные точки роста
+
+После того, как мы создали график отслеживания времени прохождения тестов и получили отправную точку (523 секунды), пора переходить к исследованию тестов с помощью профилировщиков.
+
+Предварительно мы сразу можем исключить из пакета тестов системные (в папке `spec/features`), т.к. они обрабатываются наиболее медленно, симулируя пользовательский ввод в браузере. Важно заметить, что они игнорируются только при запуске всего пакета тестов (цель - feedback-loop), но будут выполняться, если мы укажем целенаправленно папку с ними как объект тестирования.
+
+Следующим подготовительным шагом станет изменение конфигурации для запуска тестов параллельно, что тоже должно сократить время полного прохождения всего пакета тестов. Сама библиотека для решения этой задачи уже была установлена в проекте (и был отдельный исполняемый файл для обращения к ней), но я решил обновить версию на более актуальную и сделать доступной отдельную базу для каждого потока выполнения тестов.
+
+Пришлось установить более старую версию chromedriver `brew reinstall --cask https://raw.githubusercontent.com/Homebrew/homebrew-cask/3ae9f9127a7863a581b79a78a739fb8613442491/Casks/chromedriver.rb` из-за невозможности обновить gem selenium в проекте до версий, работающих с более новым драйвером. Сам Chrome должен совпадать с версией драйвера, поэтому необходимо было откатить и его. После этого пришлось разобраться с тем, что Capybara открывала Chrome и выполняла автоматизированные тесты в окне, а не в фоне (headless). Помогла замена `Capybara.javascript_driver = :selenium_chrome_headless`.
+
+На текущем этапе время выполнения всех тестов составило 169 секунд.
+
+Из-за ряда неудачных запусков в Influx успели попасть нулевые значения. Потребовалось время, чтобы разобраться, как их можно удалить. И из рабочих способов подошел только один:
+```
+curl -G 'http://localhost:8086/query?db=db&epoch=ns' \
+  --data-urlencode "q=SELECT * FROM test WHERE run_time_seconds=0" |\
+  jq -r "(.results[0].series[0].values[][0])" > delete_timestamps.txt
+```
+```
+for i in $(cat delete_timestamps.txt); do
+  echo $i;
+  curl -G 'http://localhost:8086/query?db=db&epoch=ns' \
+    --data-urlencode "q=DELETE FROM test WHERE time=$i";
+done
+```
+
+После активации параллельных тестов первоначальное исключение тестов внутри папки `features` перестало функционировать (видимо, внутри каждый процесс вызывал конкретные списки папок, разделив их между собой, что привело к принудительному запуску тестов с браузерным взаимодействием, т.к. мы оставили для этого функционал). Пришлось уточнить вызов параллельных тестов, исключив папку уже как параметр запуска после числа процессов.
+
+На текущем этапе время прохождения пакета тестов (с выключенными относящимися к Capybara) снизилось до 85 секунд.
+
+Имеет смысл так же отключить в процессе тестирования создание аватаров как часть пользовательской модели (внутри соответствующей фабрики). Тесты не связаны с их наличием.
+
+Заключительным подготовительным этапом перед, собственно, профилированием отдельных тестов стало отключение `database_cleaner` и использование штатных средств Rails (при запуске тестов в рамках одного процесса с одним подключением к БД этого должно быть достаточно)
+
+### Ваша находка №1
+
+- какой отчёт показал главную точку роста
+  - `rspec --profile` показал, что самая медленная группа тестов
+    Top 10 slowest example groups: internal/users
+    2.16 seconds average (15.15 seconds / 7 examples) ./spec/controllers/internal_users_controller_spec.rb:3
+    Нашей точкой роста будет оптимизация данного теста.
+  - `TEST_STACK_PROF=1 TEST_STACK_PROF_FORMAT=json bundle exec rspec spec/controllers/internal_users_controller_spec.rb` и анализ отчета в speedscope.app показали, что из общего времени выполнения теста 15,7 секунд порядка 7,7 секунды занимает блок `RSpec::ExampleGroups::InternalUsers#dependents_for_offending_user_article` и далее идут `Delayed::Worker#work_off` по 6,5 секунды.
+- как вы решили её оптимизировать
+  - Имеет смысл разобраться, а нужно ли в этом тесте выполнять `Delayed::Worker` методы вместо моков. Сюда же относятся и `let`, которые тратят время на создание записей в БД.
+  - Режим отображения Sandwich дает помимо этого информацию, что много времени занимают соответственно
+    * 3.36s (20%)	ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
+    * 2.22s (13%)	2.22s (13%)	Rails::BacktraceCleaner#initialize
+    * 1.18s (7.1%)	1.18s (7.1%)	Rails::BacktraceCleaner#add_gem_filters
+  - QCacheGrind отчет показывает, что вызовы Rails::BacktraceCleaner происходят из HoneycombRails. Судя по найденному описанию библиотеки на https://github.com/honeycombio/honeycomb-rails, это сервис для сбора аналитики с production.
+  - Начнем оптимизацию с того, что перенесем библиотеку в группу production, чтобы не использовать ее в других окружениях. Еще остается проверить использование библиотеки в других файлах, в частности нужно установить guard на конфигурацию Honeycomb, чтобы библиотека не загружалась в тестовом окружении.
+- как изменилась метрика
+  - Метрика снизилась с 15,7 секунд до 9 секунд для конкретно исследуемого файла и до 53 секунд для всего тестового бандла! (без браузерных тестов)
+- как изменился отчёт профилировщика
+  - Honeycomb и BacktraceCleaner предполагаемо пропали из отчетов.
+
+### Ваша находка №2
+
+- какой отчёт показал главную точку роста
+  - `RD_PROF=1 bundle exec rspec` показал, что для общего времени тестирования 01:36 из них блоки `let` занимают 46 секунд, а `before(:each)` 31.5 секунды.
+  - для нашего контрольного длинного по времени теста `spec/controllers/internal_users_controller_spec.rb` из общих 8 секунд `let` длится 1.4 секунды, а `before(:each)` 6 секунд.
+- как вы решили её оптимизировать
+  - при проверке самого файла на возможные причины долгих инициализаций бросается в глаза многократный вызов `Delayed::Worker.new(quiet: true).work_off`, который, как мы видели в предыдущем шаге, занимает по несколько секунд. Имеет смысл удалить все подобные вызовы (с учетом того, что тесты продолжат проходить)
+  - следующая оптимизация состоит в том, чтобы инициализировать объекты, используемые в тестах, один раз в "головной" транзакции с помощью метода `before_all`. Одновременно мы можем изменить использование `let` на `let_it_be`, чтобы создание записей в БД тоже происходило однократно в рамках `before_all`.
+  - по аналогии был проведен быстрый рефакторинг для следующих в списке по времени выполнения тестах:
+    * `spec/requests/notifications_spec.rb`
+    * `spec/models/comment_spec.rb`
+    * `spec/models/article_spec.rb`
+- как изменилась метрика
+ - Метрика снизилась для контрольного файла до 0.6 сек, а для всего пакета до 52 секунд.
+
+## Результаты
+
+В результате проделанной оптимизации удалось существенно ускорить время выполнения основных релевантных тестов (без задействия браузера) в 10 раз: 523 секунды превратились в 58.
+В качестве работы на будущее следует провести оптимизацию с помощью Factory Doctor (Total (potentially) bad examples: 123, Total wasted time: 00:05.565), например начав с тестов моделей Article, Notification, User, и продолжив на основании процентного соотношения выполнения тестов рефакторинг с помощью `before_all` и `let_it_be`.