Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Week 1 #158

Open
wants to merge 3 commits into
base: master
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 10 additions & 0 deletions Gemfile
Original file line number Diff line number Diff line change
@@ -0,0 +1,10 @@
# frozen_string_literal: true

source 'https://rubygems.org'

gem 'ruby-prof'
gem 'rspec-benchmark'
gem 'ruby-progressbar'
gem 'stackprof'
gem 'pry'
gem 'minitest'
48 changes: 48 additions & 0 deletions Gemfile.lock
Original file line number Diff line number Diff line change
@@ -0,0 +1,48 @@
GEM
remote: https://rubygems.org/
specs:
benchmark-malloc (0.2.0)
benchmark-perf (0.6.0)
benchmark-trend (0.4.0)
coderay (1.1.3)
diff-lcs (1.5.1)
method_source (1.1.0)
minitest (5.25.4)
pry (0.14.2)
coderay (~> 1.1)
method_source (~> 1.0)
rspec (3.13.0)
rspec-core (~> 3.13.0)
rspec-expectations (~> 3.13.0)
rspec-mocks (~> 3.13.0)
rspec-benchmark (0.6.0)
benchmark-malloc (~> 0.2)
benchmark-perf (~> 0.6)
benchmark-trend (~> 0.4)
rspec (>= 3.0)
rspec-core (3.13.2)
rspec-support (~> 3.13.0)
rspec-expectations (3.13.3)
diff-lcs (>= 1.2.0, < 2.0)
rspec-support (~> 3.13.0)
rspec-mocks (3.13.2)
diff-lcs (>= 1.2.0, < 2.0)
rspec-support (~> 3.13.0)
rspec-support (3.13.2)
ruby-prof (1.6.3)
ruby-progressbar (1.13.0)
stackprof (0.2.27)

PLATFORMS
x86_64-linux

DEPENDENCIES
minitest
pry
rspec-benchmark
ruby-prof
ruby-progressbar
stackprof

BUNDLED WITH
2.4.13
116 changes: 116 additions & 0 deletions case-study.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,116 @@
# Case-study оптимизации

## Актуальная проблема
В нашем проекте возникла серьёзная проблема.

Необходимо было обработать файл с данными, чуть больше ста мегабайт.

У нас уже была программа на `ruby`, которая умела делать нужную обработку.

Она успешно работала на файлах размером пару мегабайт, но для большого файла она работала слишком долго, и не было понятно, закончит ли она вообще работу за какое-то разумное время.

Я решил исправить эту проблему, оптимизировав эту программу.

## Формирование метрики
Для того, чтобы понимать, дают ли мои изменения положительный эффект на быстродействие программы я придумал использовать такую метрику: Время выполнения программы с частичным объемом данных за вменяемое время
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍


## Гарантия корректности работы оптимизированной программы
Программа поставлялась с тестом. Выполнение этого теста в фидбек-лупе позволяет не допустить изменения логики программы при оптимизации.

## Feedback-Loop
Для того, чтобы иметь возможность быстро проверять гипотезы я выстроил эффективный `feedback-loop`, который позволил мне получать обратную связь по эффективности сделанных изменений за 20-30 секунд.

Вот как я построил `feedback_loop`:
Измерив время выполнения программы на разном объеме дынных, алгоритмическая сложность получилась O(n^2), т.е. время выполнения в зависимости от объема данных возрастает квадратично.

- Нужно зафиксировать бюджет метрики, которую определили выше.
То-есть выбрать объем данных, который выполняется за адекватное время, на первой итерации например 5 сек. (20_000 строк кода на моей машине)
- Защитить метрику от дальнейшей деградации, написать тест
- С помощью профилировщика найти главную точку роста (Профилируем с выключенным GC предварительно прогрев кеши)
- Внести оптимизационные правки
- С помощью профилировщика проверить есть ли улучшения
- Запустить тест, проверить, если улучшения есть тогда закоммитить.

## Вникаем в детали системы, чтобы найти главные точки роста
Для того, чтобы найти "точки роста" для оптимизации я воспользовался rbspy (удобно, потому что встроен в rubymine), stackprof и ruby-prof в разных режимах отчетов

Вот какие проблемы удалось найти и решить

### Ваша находка №1
- 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)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

- Метрика кратно уменьшилась при прогоне теста на перфоманс с средних 5 сек. до 0.4 сек. Это и было самым узким местом программы по всей видимости.
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

это было место которое делало разницу между O(N^2) и O(N)

- Повторный запуск профилировщика показал, что вместо 89,15% теперь это место занимает 0.3%.
- В отчетах профилировщика эта точка роста перестала быть главной.

### Ваша находка №2
- Профилировщики указали на следующую точку роста:
```
%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'`
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

не совсем понятно как именно от Array#each пришли именно к этому изменению

обычно можно поковыряться с другими отчётами / порефачить код, чтобы стало всё-таки более конкретно понятно в чём проблема

Известная проблема в ruby. Оператор << позволяет не создавать новую переменную каждый раз, а писать все в существующую.
- При прогоне теста, среднее значение метрики упало с 0.4 сек. до 0.25 сек.
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

для профилирования лучше несколько секунд хотя бы чтобы runtime был (если мы говорим о процессе, который в целом идёт мнооого секунд)

- В отчетах профилировщика эта точка роста перестала быть главной.

### Ваша находка №3
- Ради интереса прогнал тесты с разным объемом данных, 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 сек.
- В отчетах профилировщика эта точка роста перестала быть главной.

### Ваша находка №4
- По отчетам профилировщиков нашел новую точку роста, это метод `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 строк.
- В отчетах профилировщика эта точка роста перестала быть главной.

### Ваша находка №5
- 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 лишняя обработка.
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

- Среднее значение метрики упало с 0.14 до 0.2 сек.
- В отчетах профилировщика эта точка роста перестала быть главной.

### Ваша находка №6
- Уже правктически выполняется бюджет прогона файла 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 сек.
- В отчетах профилировщика эта точка роста перестала быть главной.
- Вижу еще несколько точек роста, но решил на этом остановится =)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍


## Результаты
В результате проделанной оптимизации наконец удалось обработать файл с данными.
Удалось улучшить метрику системы на 20_000 строк с 5 сек. до 0.1 сек., на 60_000 строк с 72 сек. до 0.3 сек,
на полном объеме данных уменьшить время выполнения до 27 сек. и уложиться в заданный бюджет.
Так же был переписан тест с minitest на rspec и вынесен в отдельный файл.

## Защита от регрессии производительности
Для защиты от потери достигнутого прогресса при дальнейших изменениях программы было написано два performance теста, один для проверки на 60_000 строках,
второй на полном объеме файла data_large.txt
11 changes: 11 additions & 0 deletions ruby-prof.rb
Original file line number Diff line number Diff line change
@@ -0,0 +1,11 @@
require 'ruby-prof'
require_relative './task-1'

RubyProf.measure_mode = RubyProf::WALL_TIME

result = RubyProf.profile do
work('./spec/fixtures/files/dataN.txt')
end

printer = RubyProf::GraphHtmlPrinter.new(result)
printer.print(File.open('./ruby-prof.html', 'w+'))
File renamed without changes.
Loading