diff --git a/case-study.md b/case-study.md new file mode 100644 index 0000000..232823b --- /dev/null +++ b/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`. diff --git a/chronograph.png b/chronograph.png new file mode 100644 index 0000000..475dd6b Binary files /dev/null and b/chronograph.png differ