[potashin] optimization

.gitignore

@@ -0,0 +1,10 @@
+result.json
+data*.txt
+
+/tmp/*
+!/tmp/.keep
+!/tmp/ruby_prof/.keep
+!/tmp/stackprof/.keep
+
+# Ignore MacOS system files
+.DS_Store

README.md

@@ -94,17 +94,17 @@ head -n N data_large.txt > dataN.txt # create smaller file from larger (take N f
 ## Checklist
 Советую использовать все рассмотренные в лекции инструменты хотя бы по разу - попрактикуйтесь с ними, научитесь с ними работать.
 
-- [ ] Прикинуть зависимость времени работы програмы от размера обрабатываемого файла
-- [ ] Построить и проанализировать отчёт `ruby-prof` в режиме `Flat`;
-- [ ] Построить и проанализировать отчёт `ruby-prof` в режиме `Graph`;
-- [ ] Построить и проанализировать отчёт `ruby-prof` в режиме `CallStack`;
-- [ ] Построить и проанализировать отчёт `ruby-prof` в режиме `CallTree` c визуализацией в `QCachegrind`;
-- [ ] Построить дамп `stackprof` и проанализировать его с помощью `CLI`
-- [ ] Построить дамп `stackprof` в `json` и проанализировать его с помощью `speedscope.app`
-- [ ] Профилировать работающий процесс `rbspy`;
-- [ ] Добавить в программу `ProgressBar`;
-- [ ] Постараться довести асимптотику до линейной и проверить это тестом;
-- [ ] Написать простой тест на время работы: когда вы придёте к оптимизированному решению, замерьте, сколько оно будет работать на тестовом объёме данных; и напишите тест на то, что это время не превышается (чтобы не было ложных срабатываний, задайте время с небольшим запасом);
+- [x] Прикинуть зависимость времени работы програмы от размера обрабатываемого файла
+- [x] Построить и проанализировать отчёт `ruby-prof` в режиме `Flat`;
+- [x] Построить и проанализировать отчёт `ruby-prof` в режиме `Graph`;
+- [x] Построить и проанализировать отчёт `ruby-prof` в режиме `CallStack`;
+- [x] Построить и проанализировать отчёт `ruby-prof` в режиме `CallTree` c визуализацией в `QCachegrind`;
+- [x] Построить дамп `stackprof` и проанализировать его с помощью `CLI`
+- [x] Построить дамп `stackprof` в `json` и проанализировать его с помощью `speedscope.app`
+- [x] Профилировать работающий процесс `rbspy`;
+- [x] Добавить в программу `ProgressBar`;
+- [x] Постараться довести асимптотику до линейной и проверить это тестом;
+- [x] Написать простой тест на время работы: когда вы придёте к оптимизированному решению, замерьте, сколько оно будет работать на тестовом объёме данных; и напишите тест на то, что это время не превышается (чтобы не было ложных срабатываний, задайте время с небольшим запасом);
 
 ### Главное
 Нужно потренироваться методично работать по схеме с фидбек-лупом:

case-study.md

@@ -0,0 +1,103 @@
+# Case-study оптимизации
+
+## Актуальная проблема
+В нашем проекте возникла серьёзная проблема.
+
+Необходимо было обработать файл с данными, чуть больше ста мегабайт.
+
+У нас уже была программа на `ruby`, которая умела делать нужную обработку.
+
+Она успешно работала на файлах размером пару мегабайт, но для большого файла она работала слишком долго, и не было понятно, закончит ли она вообще работу за какое-то разумное время.
+
+Я решил исправить эту проблему, оптимизировав эту программу.
+
+## Формирование метрики
+Для того, чтобы понимать, дают ли мои изменения положительный эффект на быстродействие программы я придумал использовать такую метрику: время выполнения программы для части данных (сначала 50к, потом 100к, потом 1кк).
+
+Сначала сделал гипотезу о том, что асимптотика времени работы программы квадратичная: отношение количества записей к времени выполнения в секундах: 100000/115 750000/61 50000/26, 25000/6). Подтвердил эту гипотезу с помощью теста rspec-benchmark. 
+
+## Гарантия корректности работы оптимизированной программы
+Программа поставлялась с тестом. Выполнение этого теста в фидбек-лупе позволяет не допустить изменения логики программы при оптимизации.
+
+## Feedback-Loop
+Для того, чтобы иметь возможность быстро проверять гипотезы я выстроил эффективный `feedback-loop`, который позволил мне получать обратную связь по эффективности сделанных изменений за *время, которое у вас получилось*
+
+Вот как я построил `feedback_loop`: профилирование - изменение кода - тестирование – бенчмаркинг – откат при отсутствии разницы от оптимизации/сохранение результатов
+
+## Вникаем в детали системы, чтобы найти главные точки роста
+Для того, чтобы найти "точки роста" для оптимизации я воспользовался rbspy, stackprof, ruby-prof
+
+Вот какие проблемы удалось найти и решить
+
+### Находка №1
+- rbspy показал `83.55    83.55  block (2 levels) in work - task-1.rb:101`: вызов `sessions.filter {}` на каждой итерации по `users.each`;
+- перед `users.each` сгруппировал `sessions_by_user = sessions.group_by { |session| session['user_id'] }`, в `each` использовал как `sessions_by_user[user['id']] || []`
+- время выполнения программы для 100к входных данных сократилось с 115с до 4с
+- исправленная проблема перестала быть главной точкой роста, rbspy показал, что теперь это `98.49   100.00  block in work - task-1.rb:56`
+
+### Находка №2
+- stackprof cli показал `7126  (99.4%)          11   (0.2%)     Array#each`, он вызывается несколько раз, наибольшее `6504  (   91.3%)  Object#work]`. Поскольку rbspy указывал на `task-1.rb:56`, что является `end` `each` блока, пробую вынести этот`each` в отдельный метод `parse_file`и подтвердить гипотезу, которая и подтверждается: `5765  (99.8%)        5525  (95.7%)     Object#parse_file`. Теперь нужно разобраться, какая именно операция в этом блоке `each` требует оптимизации, `stackprof stackprof.dump --method Object#parse_file` показывает, что это заполнение массива сессий: `5261   (93.2%) /  5133  (90.9%)  |    52  |     sessions = sessions + [parse_session(line)] if cols[0] == 'session'`.
+- вместо `sessions = sessions + [parse_session(line)] if cols[0] == 'session'` использую `sessions << parse_session(line) if cols[0] == 'session'`. аналогично для `users`
+- время выполнения программы для 500к входных данных сократилось с 100с до 13с
+- исправленная проблема перестала быть главной точкой роста, stackprof cli показал, что теперь это `558 (100.0%)         202  (36.2%)     Object#work`
+
+### Находка №3
+- `ruby-prof` в режиме `Graph` показывает, что точкой роста является `25.55%	25.55%	8.23	8.23	0.00	0.00	154066	Array#+` в `8.23	8.23	0.00	0.00	154066/154066	Array#each`. под это описания подходит 108 строка.
+- вместо `users_objects = users_objects + [user_object]` используем `users_objects << [user_object]`
+- время выполнения программы для 500к входных данных сократилось с 12с до с 6c
+- исправленная проблема перестала быть главной точкой роста, ruby prof показал, что теперь это `66.16%	26.52%	13.47	5.40	0.00	8.07	500000	Array#all?`
+
+### Находка №3
+- `ruby-prof` в режиме `Graph` показывает, что точкой роста является `25.55%	25.55%	8.23	8.23	0.00	0.00	154066	Array#+` в `8.23	8.23	0.00	0.00	154066/154066	Array#each`. под это описания подходит 108 строка.
+- вместо `users_objects = users_objects + [user_object]` используем `users_objects << user_object`
+- время выполнения программы для 500к входных данных сократилось с 12с до с 6c
+- исправленная проблема перестала быть главной точкой роста, ruby prof показал, что теперь это `66.16%	26.52%	13.47	5.40	0.00	8.07	500000	Array#all?`
+
+### Находка №4
+- `ruby-prof` в режиме `Graph` показывает, что точкой роста является `8.03	5.25	0.00	2.78	42580848/42580848	BasicObject#!=	85` в `66.16%	26.52%	13.47	5.40	0.00	8.07	500000	Array#all?`.
+- вместо `if uniqueBrowsers.all? { |b| b != browser }` используем `unless uniqueBrowsers.include?(browser)`
+- время выполнения программы для 500к входных данных сократилось с 6с до с 5c
+- исправленная проблема перестала быть главной точкой роста, ruby prof показал, что теперь это `66.16%	26.52%	13.47	5.40	0.00	8.07	500000	Array#all?`
+
+### Находка №5
+- `ruby-prof` в режиме `Graph` показывает, что точкой роста является `2.65	0.81	0.00	1.84	846263/846265	Array#map	120` в `94.64%	22.99%	7.22	1.75	0.00	5.47	11	Array#each`. Больше всего вызовов из `Object#collect_stats_from_users`
+- объединяем все блоки вызова `collect_stats_from_users` в один
+- время выполнения программы для 1кк входных данных сократилось с 12с до с 10c
+- исправленная проблема перестала быть главной точкой роста, ruby prof показал, что теперь это `27.07%	16.32%	3.99	2.41	0.00	1.58	846230	<Class::Date>#parse`
+
+### Находка №5
+- `ruby-prof` в режиме `Graph` показывает, что точкой роста является `27.07%	16.32%	3.99	2.41	0.00	1.58	846230	<Class::Date>#parse`, это строка `user.sessions.map{|s| s['date']}.map {|d| Date.parse(d)}.sort.reverse.map { |d| d.iso8601 }`
+- поскольку строки уже находятся в формате iso8601, это позволяет использовать строки для сортировки не преобразуя их в даты: убираем парсинг дат, с последующим преобразованием в iso8601.
+- время выполнения программы для 1кк входных данных сократилось с 10с до с 7.5c
+- исправленная проблема перестала быть главной точкой роста.
+
+### Находка №6
+- `ruby-prof` в режиме `CallStack` показывает, что точкой роста является `7.20% (15.82%) Array#include? [846230 calls, 846230 total]`
+- вместо формирования уникальных браузеров через each, сделаем `uniqueBrowsers = sessions.map { |session| session['browser'] }.uniq`.
+- время выполнения программы для 1кк входных данных сократилось с 7.5 до с 6.9c
+- исправленная проблема перестала быть главной точкой роста.
+
+### Находка №7
+- `ruby-prof` в режиме `CallGrind` показывает, что точкой роста является `Object::collect_stats_from_users`-> `Array::map`->`String::upcase`
+- поскольку используется только `upcase` версия браузера, при парсинге сессия сразу записываем `upcase` версию. Поскольку не так много видов браузеров относительно общего количества сессий, используем мемоизацию.
+- время выполнения программы для 1кк входных данных сократилось с 6.9 до с 6.4c
+- исправленная проблема перестала быть главной точкой роста.
+
+### Находка №8
+- `ruby-prof` в режиме `CallGrind` показывает, что точкой роста является `Array::each`->`Array::each`->`Object::parse_session`->`String::split`
+- делаем `split` только единожды для каждой строчки, в `parse_user`, `parse_session` передаем уже массив, а не строку
+- время выполнения программы для 1кк входных данных сократилось с 6.4 до с 5.4c
+- исправленная проблема перестала быть главной точкой роста.
+
+### Находка №9
+- `ruby-prof` в режиме `CallGrind` показывает, что точкой роста является `Object::collect_stats_from_users`->`Array::each`->`Array::map`->`String::to_i`
+- поскольку используется только целочисленное значение `time`, делаем преобразование `to_i` один раз в `parse_session`, а не дважды в `collect_stats_from_users`.
+- время выполнения программы для 1кк входных данных сократилось с 5.4 до с 5c
+- исправленная проблема перестала быть главной точкой роста.
+
+## Результаты
+В результате проделанной оптимизации наконец удалось обработать файл с данными.
+Удалось улучшить метрику системы на 100к с 115с до 0.5с секунд и уложиться в заданный бюджет. Для полного файла время выполнение стало 24с.
+
+## Защита от регрессии производительности
+Для защиты от потери достигнутого прогресса при дальнейших изменениях программы добавил два теста: прогон на 1кк данных до 5 секунд, проверка на линейную асимптотику на основе данных от 1000 до 100000 записей.

rbspy/record.sh

@@ -0,0 +1,2 @@
+#!/bin/sh
+ruby work.rb  | ps aux | grep work.rb | grep -v grep | awk '{print $2}' | xargs sudo rbspy record --pid

ruby_prof/call_grind.rb

@@ -0,0 +1,12 @@
+require_relative '../task-1'
+
+require 'ruby-prof'
+
+RubyProf.measure_mode = RubyProf::WALL_TIME
+
+result = RubyProf.profile do
+  GC.disable
+  work
+end
+printer = RubyProf::CallTreePrinter.new(result)
+printer.print(path: 'tmp/ruby_prof', profile: 'callgrind')

ruby_prof/call_stack.rb

@@ -0,0 +1,12 @@
+require_relative '../task-1'
+
+require 'ruby-prof'
+
+RubyProf.measure_mode = RubyProf::WALL_TIME
+
+result = RubyProf.profile do
+  GC.disable
+  work
+end
+printer = RubyProf::CallStackPrinter.new(result)
+printer.print(File.open("tmp/ruby_prof/callstack_#{Time.now.to_i}.html", 'w+'))

ruby_prof/flat.rb

@@ -0,0 +1,12 @@
+require_relative '../task-1'
+
+require 'ruby-prof'
+
+RubyProf.measure_mode = RubyProf::WALL_TIME
+
+result = RubyProf.profile do
+  GC.disable
+  work
+end
+printer = RubyProf::FlatPrinter.new(result)
+printer.print(File.open("tmp/ruby_prof/flat_#{Time.now.to_i}.html", 'w+'))

ruby_prof/graph.rb

@@ -0,0 +1,12 @@
+require_relative '../task-1'
+
+require 'ruby-prof'
+
+RubyProf.measure_mode = RubyProf::WALL_TIME
+
+result = RubyProf.profile do
+  GC.disable
+  work
+end
+printer = RubyProf::GraphHtmlPrinter.new(result)
+printer.print(File.open("tmp/ruby_prof/graph_#{Time.now.to_i}.html", 'w+'))

spec/task-1_spec.rb

@@ -0,0 +1,27 @@
+require 'rspec'
+require 'rspec-benchmark'
+require_relative '../task-1'
+
+RSpec.describe 'work' do
+  include RSpec::Benchmark::Matchers
+
+  it 'should be linear' do
+    expect { |number, _|
+      `head -n #{number * 1000} data_large.txt > data.txt`
+
+      work
+    }.to perform_linear.in_range(1, 100)
+  end
+
+  it 'should perform under 5 seconds' do
+    `head -n 1000000 data_large.txt > data.txt`
+
+    expect { work }.to perform_under(5).sec
+  end
+
+  # it 'should perform under 30 seconds' do
+  #   `cp data_large.txt data.txt`
+
+  #   expect { work }.to perform_under(30).sec
+  # end
+end

stackprof/cli.rb

@@ -0,0 +1,8 @@
+require_relative '../task-1'
+
+require 'stackprof'
+
+StackProf.run(mode: :wall, out: "tmp/stackprof/cli_#{Time.now.to_i}.dump", interval: 1000) do
+  GC.disable
+  work
+end

stackprof/speedscope.rb

@@ -0,0 +1,10 @@
+require_relative '../task-1'
+
+require 'stackprof'
+
+profile = StackProf.run(mode: :wall, raw: true) do
+  GC.disable
+  work
+end
+
+File.write("tmp/stackprof/speedscope_#{Time.now.to_i}.json", JSON.generate(profile))