Skip to content

task-1(cpu): use benchmarks and profilers for finding speed points #143

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

Open
wants to merge 9 commits into
base: master
Choose a base branch
from
22 changes: 22 additions & 0 deletions .gitignore
Original file line number Diff line number Diff line change
@@ -0,0 +1,22 @@
# See https://help.github.com/articles/ignoring-files for more about ignoring files.
#
# If you find yourself ignoring temporary files generated by your text editor
# or operating system, you probably want to add a global ignore instead:
# git config --global core.excludesfile '~/.gitignore_global'

# Ignore bundler config.
/.bundle

# Ignore all logfiles and tempfiles.
.idea
.DS_Store

# Ignore specific file extensions in all directories.
*.txt
Copy link
Collaborator

Choose a reason for hiding this comment

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

👍

*.html
*.json
*.dump
*.out.*

# Ignore the Gemfile.lock file.
Gemfile.lock
1 change: 1 addition & 0 deletions .rspec
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
--format doc
19 changes: 19 additions & 0 deletions .rubocop.yml
Original file line number Diff line number Diff line change
@@ -0,0 +1,19 @@
require:
- rubocop-performance
AllCops:
SuggestExtensions: false
NewCops: enable
Style/Documentation:
Enabled: false
Style/AsciiComments:
Enabled: false
Layout/LineLength:
Max: 200
Metrics/MethodLength:
Enabled: false
Metrics/ClassLength:
Max: 140
Metrics/AbcSize:
Enabled: false
Metrics/CyclomaticComplexity:
Max: 20
1 change: 1 addition & 0 deletions .ruby-gemset
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
optimization.homework
1 change: 1 addition & 0 deletions .ruby-version
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
3.3.0
Copy link
Collaborator

Choose a reason for hiding this comment

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

👍

27 changes: 27 additions & 0 deletions Gemfile
Original file line number Diff line number Diff line change
@@ -0,0 +1,27 @@
source 'https://rubygems.org'
git_source(:github) { |repo| "https://github.com/#{repo}.git" }

ruby '3.3.0'

gem 'benchmark'
gem 'benchmark-ips'
gem 'kalibera'
gem 'memory_profiler'
gem 'ruby-prof'
gem 'ruby-prof-speedscope'
gem 'stackprof'
gem 'vernier'
Copy link
Collaborator

Choose a reason for hiding this comment

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

👍👍

gem 'profile-viewer'

gem 'rubocop', require: false
gem 'rubocop-performance', require: false

gem 'pry'

gem 'minitest'
gem 'rspec'
gem 'rspec-benchmark'
gem 'rubocop-minitest'
gem 'rubocop-rspec'

gem 'ruby-progressbar'
2 changes: 1 addition & 1 deletion README.md
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
### Note
*Для работы скрипта требуется Ruby 2.4+*
*Для работы скрипта требуется Ruby 3.3+*

# Задание №1
В файле `task-1.rb` находится ruby-программа, которая выполняет обработку данных из файла.
Expand Down
46 changes: 46 additions & 0 deletions benchmark_compare_methods.rb
Original file line number Diff line number Diff line change
@@ -0,0 +1,46 @@
# frozen_string_literal: true

require 'benchmark'

n = 100
arr = Array.new(10_000) { 'x' * 100 }

Benchmark.bmbm do |x|
%i[count size].each do |method|
x.report(method.to_s) do
n.times do
arr.send(method)
end
end
end
end
# Rehearsal -----------------------------------------
# count 0.000015 0.000001 0.000016 ( 0.000013)
# size 0.000009 0.000001 0.000010 ( 0.000010)
# -------------------------------- total: 0.000026sec
# user system total real
# count 0.000011 0.000000 0.000011 ( 0.000010)
# size 0.000009 0.000001 0.000010 ( 0.000010)

Benchmark.bmbm do |x|
x.report('123.to_s') do
n.times do
123.to_s
end
end

# rubocop:disable all
x.report('#{123}') do
n.times do
"#{123}"
end
end
# rubocop:enable all
end
# Rehearsal --------------------------------------------
# 123.to_s 0.000009 0.000001 0.000010 ( 0.000009)
# #{123} 0.000012 0.000000 0.000012 ( 0.000012)
# ----------------------------------- total: 0.000022sec
# user system total real
# 123.to_s 0.000009 0.000000 0.000009 ( 0.000008)
# #{123} 0.000011 0.000000 0.000011 ( 0.000011)
197 changes: 179 additions & 18 deletions case-study-template.md
Original file line number Diff line number Diff line change
Expand Up @@ -18,39 +18,200 @@
Программа поставлялась с тестом. Выполнение этого теста в фидбек-лупе позволяет не допустить изменения логики программы при оптимизации.

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

Вот как я построил `feedback_loop`: *как вы построили feedback_loop*
Вот как я построил `feedback_loop`:

## Вникаем в детали системы, чтобы найти главные точки роста
Для того, чтобы найти "точки роста" для оптимизации я воспользовался *инструментами, которыми вы воспользовались*

Вот какие проблемы удалось найти и решить
1) запускал написанный bash скрипт который выполнял выгрузку профалеров
2) в браузере смотрел точку роста
3) правил код на основе точки роста
4) запускал снова скрипт
5) смотрел к чему привело, если откату, то возвращал обратно
6) и тд

### Ваша находка №1
## Вникаем в детали системы, чтобы найти главные точки роста
Для того, чтобы найти "точки роста" для оптимизации я воспользовался всеми профайлерами из лекции, чтобы получить опыт.
Copy link
Collaborator

Choose a reason for hiding this comment

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

👍


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

### находка №1

1) Написал тест задав бюджет: 30 секунд и линейной асимптотикой.
2) При выполнении на маленьком data.txt получил логарифмическую асимптотику.
Copy link
Collaborator

Choose a reason for hiding this comment

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

логарифмическая это лучше линейной (либо опечатка, либо тест некорректный результат показал)

3) Создал файлы с разным количеством строк и убедился, что уже на 40тыс строк все долго виснет.
4) Чтобы понять затратные операции, решил посмотреть отчеты всех профилировщиков
5) Из отчета в `task-1_graph_data_file_data10000.txt_disable_gc_true.html` увидел:
- что 10 раз вызывается Array#each и в нем 1536/1536 Array#select что занимает 97.29% времени
- сам Array#select потребляет 52.22% и в нем Hash#[] 26001408/26144384 26.01% и String#== 13000704/13861980 13.91%
Таким образом главная точка раста - разобраться для начала с Array#select.
6) Сравнил время выполнения benchmark/ips на разных объемах строк в файлах:
```
Comparison:
data5000.txt: 1.6 i/s
data10000.txt: 0.5 i/s - 3.06x (± 0.19) slower
data15000.txt: 0.3 i/s - 6.29x (± 0.36) slower
data20000.txt: 0.1 i/s - 11.31x (± 0.61) slower
with 95.0% confidence
```
Видно, что обработка 10тыс. строк в ~3 раз медленнее чем 5 тыс.
После 10 тыс. с увеличением на 5 тыс. в 2x раза увеличвается время выполнения.
7) Запоминаю время обработки:
- выставляю в тесте rspec текущее время выполнения 10 секунд на файл 5 тыс., чтобы не скатиться ниже
- измеряю время в benchmark:
```
1 - Before refactoring:
"data5000.txt finish in 1.07"
"data10000.txt finish in 2.48"
"data15000.txt finish in 5.48"
"data20000.txt finish in 9.69"
```
8) Начинаю рефактор Array#select, а именно `user_sessions = sessions.select { |session| session['user_id'] = }`
```ruby
# Преобразовываю массив сессий в хэш-таблицу по 'user_id'
sessions_by_user_id = sessions.group_by { |session| session['user_id'] }

users.each do |user|
attributes = user

# user_sessions = sessions.select { |session| session['user_id'] = }
# Ищу из созданного хеша
user_sessions = sessions_by_user_id[user['id']] || []

user_object = User.new(attributes:, sessions: user_sessions)
users_objects += [user_object]
progressbar.increment
end
```
9) Снова измеряю время в benchmark, получаю утешительную картину, время уменьшилось в ~8 раз
```
2 - After refactoring:
user_sessions = sessions.select { |session| session['user_id'] = }
"data5000.txt finish in 0.17"
"data10000.txt finish in 0.29"
"data15000.txt finish in 0.55"
"data20000.txt finish in 0.77"
```
10) Теперь самое время бы почить на лаврах, но надо проверить выполнится ли заданная метрика (30 s) на `data_large.txt`,
но увы обработка будто виснет, значит ищем дальше точки раста в профайлерах.

### находка №2
- какой отчёт показал главную точку роста
- как вы решили её оптимизировать
rubyprof - flat
Copy link
Collaborator

Choose a reason for hiding this comment

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

в чём была проблема - не понятно, как поправили, тоже не понятно

- как решил её оптимизировать
``` ruby
file_lines.each do |line|
cols = line.split(',')
case cols[0]
when 'user'
users << parse_user(line)
when 'session'
sessions << parse_session(line)
end
end
```
- как изменилась метрика
```
"data5000.txt finish in 0.15"
"data10000.txt finish in 0.2"
"data15000.txt finish in 0.3"
"data20000.txt finish in 0.38"
```
- как изменился отчёт профилировщика - исправленная проблема перестала быть главной точкой роста?
Да, появилась новая точка роста

### Ваша находка №2
### Ваша находка №3
- какой отчёт показал главную точку роста
- как вы решили её оптимизировать
rp-flat
%self total self wait child calls name location
33.98 0.240 0.240 0.000 0.000 1 <Class::IO>#write
11.74 0.388 0.083 0.000 0.305 17 *Array#each
7.94 0.056 0.056 0.000 0.000 1 <Class::IO>#read
7.26 0.150 0.051 0.000 0.099 33508 Array#map
5.48 0.039 0.039 0.000 0.000 307946 Hash#[]
rp-graph
0.26 0.05 0.00 0.21 7/17 Object#collect_stats_from_users 39
75.45% 15.82% 0.38 0.08 0.00 0.30 17 *Array#each
rp-callstack
49.18% (100.00%) Array#each [7 calls, 17 total]
26.14% (53.15%) Array#map [33506 calls, 33508 total]
13.41% (51.29%) <Class::Date>#parse [16954 calls, 16954 total]
2.15% (16.01%) Regexp#match [33908 calls, 33908 total]
2.05% (15.32%) String#gsub! [16954 calls, 16954 total]
1.28% (9.57%) MatchData#begin [16954 calls, 16954 total]
sp-cli
Mode: wall(1000)
Samples: 180 (3.23% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
180 (100.0%) 26 (14.4%) Object#work
45 (25.0%) 23 (12.8%) Date.parse
23 (12.8%) 23 (12.8%) Array#include?
22 (12.2%) 22 (12.2%) String#split
102 (56.7%) 17 (9.4%) Object#collect_stats_from_users
11 (6.1%) 11 (6.1%) Regexp#match
71 (39.4%) 11 (6.1%) Array#map
6 (3.3%) 6 (3.3%) Date#iso8601
13 (7.2%) 6 (3.3%) Object#parse_session
6 (3.3%) 6 (3.3%) String#gsub!
5 (2.8%) 5 (2.8%) Array#sort
5 (2.8%) 5 (2.8%) Hash#merge
4 (2.2%) 4 (2.2%) MatchData#begin
4 (2.2%) 3 (1.7%) Enumerable#group_by
3 (1.7%) 3 (1.7%) String#upcase
170 (94.4%) 3 (1.7%) Array#each
2 (1.1%) 2 (1.1%) IO.write
sp-flame

- как решил её оптимизировать
```ruby
# def collect_stats_from_users(report, users_objects)
# users_objects.each do |user|
# user_key = "#{user.attributes['first_name']}" + ' ' + "#{user.attributes['last_name']}"
# report['usersStats'][user_key] ||= {}
# report['usersStats'][user_key] = report['usersStats'][user_key].merge(yield(user))
# end
# end
def collect_stats_from_users(report, users_objects)
users_objects.each do |user|
user_key = "#{user.attributes['first_name']} #{user.attributes['last_name']}"
report['usersStats'][user_key] ||= {}
report['usersStats'][user_key].update(yield(user))
end
end
```
- как изменилась метрика
```
"data5000.txt finish in 0.15"
"data10000.txt finish in 0.19"
"data15000.txt finish in 0.28"
"data20000.txt finish in 0.36"
Copy link
Collaborator

Choose a reason for hiding this comment

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

А само профилирование на каком объёме?

Хорошо подбирать объём данных так, чтобы программа успевала покрутиться пару секунд. Если она завершается слишком быстро (“не успевает поработать”) могут возникнуть какие-то перекосы (например, на полном объёме основная часть времени тратится в основном цикле, а если данных мало - то большая часть уходит на инициализацию и финализацию, например на чтение из файла и запись потом в файл)

И плюс когда время уже на миллисекунды - больше влияние погрешностей.

```
- как изменился отчёт профилировщика - исправленная проблема перестала быть главной точкой роста?
Да, появились новые точки роста

### Ваша находка №X
- какой отчёт показал главную точку роста
- как вы решили её оптимизировать
- как изменилась метрика
- как изменился отчёт профилировщика - исправленная проблема перестала быть главной точкой роста?
Потом я решил не косектировать данные шаги, а по этому сценарию проходиться по другим точкам роста.
Долго не мог выяснить как дальше оптимизировать внося минимальные правки в код.
И дошел то точки роста Date.parse, плюс к которому было еще преобразование в iso что на деле оказалось не нужным.
Удалив это преобразование - получил boost скорости и выполнение в рамках бюджета.

## Результаты
В результате проделанной оптимизации наконец удалось обработать файл с данными.
Удалось улучшить метрику системы с *того, что у вас было в начале, до того, что получилось в конце* и уложиться в заданный бюджет.
Удалось улучшить метрику системы с неизвестного времени обработки файла в ~30 s уложиться в заданный бюджет.

Столкнулся с тем, что папка проекта лежала у меня на сетевом диске и только потом заметил, что это сильно влияло на IO.
Copy link
Collaborator

Choose a reason for hiding this comment

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

вот кстати пример того как профилировщик показывает реальную проблему, а она совершенно не интуитивная

хотелось код переписать, а на самом деле надо диск локальный

И тесты плавали.
Я уже даже думал не уж то надо переписывать код, так пол времени занимала запись в итоговый файл json.

*Какими ещё результами можете поделиться*
Добавил rubyprof flamegraph не затронутый в лекции и установил speedscope локально, чтобы командой запускать:
`speedscope ruby_prof_reports/task-1_flamegraph_data_file_data20000.txt_disable_gc_true.json`

Добавил новый Firefox Profiler, используя гемы:
Copy link
Collaborator

Choose a reason for hiding this comment

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

👍 понравилось?

```ruby
gem 'vernier'
gem 'profile-viewer'
```
## Защита от регрессии производительности
Для защиты от потери достигнутого прогресса при дальнейших изменениях программы *о performance-тестах, которые вы написали*
Для защиты от потери достигнутого прогресса при дальнейших изменениях программы performance-тесты.
Тесты проверяют время выполнения обработки разных объемов данных.

Loading