В нашем проекте возникла серьёзная проблема.
Необходимо было обработать файл с данными, чуть больше ста мегабайт.
У нас уже была программа на ruby, которая умела делать нужную обработку.
Она успешно работала на файлах размером пару мегабайт, но для большого файла она работала слишком долго, и не было понятно, закончит ли она вообще работу за какое-то разумное время.
Я решил исправить эту проблему, оптимизировав эту программу.
Для того, чтобы понимать, дают ли мои изменения положительный эффект на быстродействие программы я придумал использовать такую метрику: Время выполнения программы с частичным объемом данных за вменяемое время
Программа поставлялась с тестом. Выполнение этого теста в фидбек-лупе позволяет не допустить изменения логики программы при оптимизации.
Для того, чтобы иметь возможность быстро проверять гипотезы я выстроил эффективный feedback-loop, который позволил мне получать обратную связь по эффективности сделанных изменений за 20-30 секунд.
Вот как я построил feedback_loop:
Измерив время выполнения программы на разном объеме дынных, алгоритмическая сложность получилась O(n^2), т.е. время выполнения в зависимости от объема данных возрастает квадратично.
- Нужно зафиксировать бюджет метрики, которую определили выше. То-есть выбрать объем данных, который выполняется за адекватное время, на первой итерации например 5 сек. (20_000 строк кода на моей машине)
- Защитить метрику от дальнейшей деградации, написать тест
- С помощью профилировщика найти главную точку роста (Профилируем с выключенным GC предварительно прогрев кеши)
- Внести оптимизационные правки
- С помощью профилировщика проверить есть ли улучшения
- Запустить тест, проверить, если улучшения есть тогда закоммитить.
Для того, чтобы найти "точки роста" для оптимизации я воспользовался rbspy (удобно, потому что встроен в rubymine), stackprof и ruby-prof в разных режимах отчетов
Вот какие проблемы удалось найти и решить
- stackprof cli и rbspy указали на одинаковую точку роста, 89% занимает
user_sessions = sessions.select { |session| session['user_id'] == user['id'] }
%Total %Self Total Self Wait Child Calls Name
89.15% 89.15% 7.19 7.19 0.00 0.00 3046 Array#select
- Заменил перебор всех сессий на хэш с группированные данных по user_id. В данном конкретном месте алгоритмическая сложность с O(n) изменилась на O(1)
- Метрика кратно уменьшилась при прогоне теста на перфоманс с средних 5 сек. до 0.4 сек. Это и было самым узким местом программы по всей видимости.
- Повторный запуск профилировщика показал, что вместо 89,15% теперь это место занимает 0.3%.
- В отчетах профилировщика эта точка роста перестала быть главной.
- Профилировщики указали на следующую точку роста:
%Total %Self Total Self Wait Child Calls Name
96.01% 43.30% 0.73 0.33 0.00 0.40 10 Array#each
- Заменил
sessions = sessions + [parse_session(line)] if cols[0] == 'session'наsessions = sessions << parse_session(line) if cols[0] == 'session'Известная проблема в ruby. Оператор << позволяет не создавать новую переменную каждый раз, а писать все в существующую. - При прогоне теста, среднее значение метрики упало с 0.4 сек. до 0.25 сек.
- В отчетах профилировщика эта точка роста перестала быть главной.
- Ради интереса прогнал тесты с разным объемом данных, 20к, 40к, 80к и так далее. В том числе и на полном файле. На данном этапе уже удалось избавится от O(n^2) благодаря первому шагу, теперь алгоритмическая сложность О(n).
- Профилировщики указали на следующую точку роста:
%Total %Self Total Self Wait Child Calls Name
93.26% 13.71% 0.44 0.06 0.00 0.37 10 Array#each
- Оптимизировал блок each, заменил '+' на Set.
- При прогоне теста, среднее значение метрики упало с 0.25 сек. до 0.18 сек.
- В отчетах профилировщика эта точка роста перестала быть главной.
- По отчетам профилировщиков нашел новую точку роста, это метод
def collect_stats_from_users
%Total %Self Total Self Wait Child Calls Name
89.28% 23.89% 1.43 0.38 0.00 1.05 10 Array#each
- Оптимизировал, а именно избавился от collect_stats_from_users и начал подготавливать данные для отчета за один проход.
- При прогоне теста, среднее значение метрики упало с 0.18 сек. до 0.14 сек. на 20_000 строк.
- В отчетах профилировщика эта точка роста перестала быть главной.
- stackprof показал на точку роста на строке с парсингом даты
dates = sessions.map { |s| Date.parse(s['date']) }
%Total %Self Total Self Wait Child Calls Name
28.57% 16.02% 0.09 0.05 0.00 0.04 16954 <Class::Date>#parse
- Поправил, Date.parse лишняя обработка.
- Среднее значение метрики упало с 0.14 до 0.2 сек.
- В отчетах профилировщика эта точка роста перестала быть главной.
- Уже правктически выполняется бюджет прогона файла data_large.txt, но профилировщик подсветил еще одну точку роста:
%Total %Self Total Self Wait Child Calls Name
30.73% 30.73% 0.06 0.06 0.00 0.00 40001 String#split
- Выпилил лишние String.split
- Так как выполнение теста на 20_000 строк очень мало, увеличил файл до 60_000 строк. Среднее значение прогода 60_000 строк = 0.3 сек.
- Среднее значение прогона всего файла с ~30 сек. упало до 27 сек.
- В отчетах профилировщика эта точка роста перестала быть главной.
- Вижу еще несколько точек роста, но решил на этом остановится =)
В результате проделанной оптимизации наконец удалось обработать файл с данными. Удалось улучшить метрику системы на 20_000 строк с 5 сек. до 0.1 сек., на 60_000 строк с 72 сек. до 0.3 сек, на полном объеме данных уменьшить время выполнения до 27 сек. и уложиться в заданный бюджет. Так же был переписан тест с minitest на rspec и вынесен в отдельный файл.
Для защиты от потери достигнутого прогресса при дальнейших изменениях программы было написано два performance теста, один для проверки на 60_000 строках, второй на полном объеме файла data_large.txt