Homewor 1

case-study.md

@@ -0,0 +1,173 @@
+# Case-study оптимизации
+
+## Актуальная проблема
+В нашем проекте возникла серьёзная проблема.
+
+Необходимо было обработать файл с данными, чуть больше ста мегабайт.
+
+У нас уже была программа на `ruby`, которая умела делать нужную обработку.
+
+Она успешно работала на файлах размером пару мегабайт, но для большого файла она работала слишком долго, и не было понятно, закончит ли она вообще работу за какое-то разумное время.
+
+Я решил исправить эту проблему, оптимизировав эту программу.
+
+## Формирование метрики
+Для того, чтобы понимать, дают ли мои изменения положительный эффект на быстродействие программы я придумал использовать такую метрику: Файл размером 128M(3250940 строк) должен обрабатываться за 30 секунд.
+
+## Гарантия корректности работы оптимизированной программы
+Программа поставлялась с тестом. Выполнение этого теста в фидбек-лупе позволяет не допустить изменения логики программы при оптимизации.
+
+## Feedback-Loop
+Для того, чтобы иметь возможность быстро проверять гипотезы я выстроил эффективный `feedback-loop`, который позволил мне получать обратную связь по эффективности сделанных изменений за определение слабых мест занимает в районе 1-3 минут, часть времени формирование отчета и использование разных профилировщиков. Дальше в районе 5 минут сравнение и анализ нескольких профилировщиков и определение слабого места.
+
+Вот как я построил `feedback_loop`: 
+- перенес существующий тест в более удобное место и рядом создал тест с performance промежуточными и итоговым
+- заранее разбил файлы и сложил в отдельную папку data, на 5_000, 10_000, 20_000, 30_000 и тд. Скриптом
+- отдельные написал скрипты для профилировщиков и сделал возможность указывать через ENV `FILE_SIZE=10000 ruby profilers/rubyprof_graph.rb`
+- первые 2 итерации пробовал разные отчеты, но по итогу пришел к использованию rubyprof_graph иногда с чередованием rbspy для более живого просмотра
+
+## Вникаем в детали системы, чтобы найти главные точки роста
+Для того, чтобы найти "точки роста" для оптимизации я воспользовался
+
+Предварительные замеры  benchmark виден рост скорости, в среднем в 2 раза величивая время.
+GB_OFF=1 FILE_SIZE=10000 ruby profilers/benchmark.rb
+  1.746674   0.125046   1.871720 (  1.873619)
+GB_OFF=1 FILE_SIZE=20000 ruby profilers/benchmark.rb
+  9.431936   0.591053  10.022989 ( 10.173283)
+GB_OFF=1 FILE_SIZE=30000 ruby profilers/benchmark.rb
+ 15.142661   1.062562  16.205223 ( 16.214299)
+
+дальше использовались rubyprof, stackprof
+
+Вот какие проблемы удалось найти и решить
+
+### Ваша находка №1
+- предваритаельно по всем отчетам видно что 85 процентов времени занимает select на 101 строчке, что является селектом сессий
+```
+99.80%	0.85%	7.80	0.07	0.00	7.73	10	Array#each	
+ 6.75	4.81	0.00	1.94	1536/1536	Array#select	101
+```
+- Заменить поиск по массиву, предварительной подготовкой хэша сессий по пользователю
+- сразу видны изменения по benchmark
+```
+GB_OFF=1 FILE_SIZE=10000 ruby profilers/benchmark.rb
+  0.287000   0.117284   0.404284 (  0.406841)
+
+GB_OFF=1 FILE_SIZE=20000 ruby profilers/benchmark.rb
+  0.736604   0.470229   1.206833 (  1.211173)
+
+GB_OFF=1 FILE_SIZE=30000 ruby profilers/benchmark.rb
+  1.345629   0.993643   2.339272 (  2.342273)
+```
+- проблема ушла, теперь на профилировщике видны новые точки роста
+
+### Ваша находка №2
+- используя rubyprof через отчеты graph 
+```
+53.92% 6.43	6.43	0.00	0.00	57895/57895	Array#+	54
+```
+отчет и rbspy
+```
+ 56.49 65.61 block in work - rails-optimization-task1/work.rb:56
+```
+определяем новую точку роста
+- видно что больше всего времени занимает складывание массивов
+- заменил операцию сложения на оператор `<<`
+- видно что операция сложения массиово стало меньше и по общим замерам произошло ускорение на 2 сек
+```
+0.06	0.06	0.00	0.00	4592/4592	Array#+
+```
+- по профилоровщику видны новые точки роста и что операции склеивания массивов занимает меньше времени
+
+  по отчетам так же видно что общее операции Array#+, пропали совсем теперь убеждаюсь что есть толкьо 0.43%	0.04	0.04	0.00	0.00	230749	Array#<<, который как видно работает куда лучше
+
+### Ваша находка №3
+- поднимаю кол-во используемых данных до 100_000, чтобы видеть более проблемные места
+- используя rubyprof через отчеты graph и общее время с таким набором `12.06217939099588`
+```
+98.51%	7.31%	12.90	0.96	0.00	11.94	11	Array#each	
+ 	 	7.16	3.09	0.00	4.07	100000/100000	Array#all?  90
+```
+определяем новую точку роста
+- видно что больше всего времени опреация сбора уникальних браузеров через all?
+- заменил постоянное сравнение all? на использование коллекции Set
+- общее время вполенение сократилось с 12.06217939099588 до 6.39049573399825 в профилировщике.
+- по отчетам так же видно что общее время на each уменьшилось и старая проблемная точка ушла
+
+### Ваша находка №4
+- используя rubyprof и последний отчет из прошлой находки
+```
+69.68%	0.00%	6.29	0.00	0.00	6.29	7	Object#collect_stats_from_users	39
+ 	 	6.29	1.27	0.00	5.02	7/11	Array#each	40
+
+5.88	1.16	0.00	4.72	7/11	Object#collect_stats_from_users	40
+  95.51%	20.16%	7.82	1.65	0.00	6.17	11	Array#each
+```
+определяем новую точку роста
+- определяю что несколько проблем в аггрегации отчета
+   1) отчет формируется не за один заход и данные каждый раз пересобираются
+   2) медоты сбора отчета состоят из большого кол-ва операций прохода по массивам
+- 1) собирает отчет за одни подход
+  2) убираем повторяющиеся дейсвия и оптимизируем запросы
+
+- общее время вполенение сократилось с 9 до 3.9 в профилировщике.
+- по отчетам так же видно уменьшенеие времени на сбор 
+коллекции почти в 5 раз
+
+```
+36.83%	0.00%	1.46	0.00	0.00	1.46	1	Object#collect_stats_from_users	39
+ 	 	1.46	0.36	0.00	1.10	1/5	Array#each
+
+```
+- попробовал запустить полную нагрузку, больше 2 минут выполнялось, не дождался
+
+
+### Ваша находка №6
+- поднимаю кол-во используемых данных до 1_000_000, чтобы видеть более проблемные места
+- используя rubyprof 
+```
+100.00%	0.05%	58.03	0.03	0.00	58.00	1	Object#work	46
+ 	32.57	6.56	0.00	26.01	3/5	Array#each	52
+ 	20.31	0.00	0.00	20.31	1/1	Object#collect_stats_from_users	108
+```
+определяем новую точку роста
+- видем 2 слабые точки это 
+1) первый цикл где происходит парс сессий и проход оп массивам
+```
+93.40%	22.66%	54.20	13.15	0.00	41.05	5	Array#each	
+ 	 	12.40	3.58	0.00	8.82	846230/846230	Object#parse_session	55
+ 	 	9.58	9.58	0.00	0.00	1000000/2000001	String#split	53
+ 	 	5.40	2.75	0.00	2.65	615080/615082	Array#map	109
+```
+2) так же сбор статистики collect_stats_from_users
+- что сделал
+1) избавился от повторяющихся split
+2) избежать повторные цциклы, подсчёетом всем каунтеров и сбором ифнормации в первом цикле
+3) занёс логику сбора отчета прямиков в work из collect_stats_from_users для удобства и оптимизации
+4) убрал лишние взаимодействия с пользователями, сделал чтобы они сразу создавали и записывались в виде объекта User
+5) заменил способ загрузки файла на построчный File.readlines(data_file_path, chomp: true), ускорило процесс секунда на 10
+
+- сделал замеры, но предварительно отключил все лишние програмы(по типу докера).
+```
+rails-optimization-task1/ (homewor_1✗) $ GB_OFF=1 FILE_SIZE=_large ruby profilers/benchmark.rb
+26.993516
+Run options: --seed 3252
+# Running:
+
+rails-optimization-task1/ (homewor_1✗) $ FILE_SIZE=_large ruby profilers/benchmark.rb 
+27.32220099999995
+```
+
+замеры уложились, в при прогоне теста тоже всё успешно
+
+
+## Результаты
+В результате проделанной оптимизации наконец удалось обработать файл с данными.
+Удалось улучшить метрику системы с урезаных данных в виде 10_000 строк за 5-10 сек, до полный файл за 30 секунд и уложиться в заданный бюджет.
+
+- надо активно следить за тем какие процессы запущены еще, они могут частично съедать ресурсы
+- так же если делать всё в докере, то видно нужные еще более жесткие настройки образа,  потмоу что я пытался играться версиями рубей через образы, он слишком много ресурсов отбирает и дополнительно ограничивает
+
+## Защита от регрессии производительности
+Для защиты от потери достигнутого прогресса при дальнейших изменениях программы пару performansce тестов, на мелкие данные и на полный файл + тест проверки логики
+

profilers/benchmark.rb

@@ -0,0 +1,4 @@
+require_relative '../work'
+require 'benchmark'
+
+puts Benchmark.realtime { work("data/data#{ENV['FILE_SIZE']}.txt") }

profilers/rbspy_script.rb

@@ -0,0 +1,4 @@
+require_relative '../work'
+
+file_size = 100_000
+work("data/data#{file_size}.txt")

profilers/rubyprof_calltree.rb

@@ -0,0 +1,15 @@
+require_relative '../work'
+require 'ruby-prof'
+
+GC.disable if ENV['GB_OFF']
+profile = RubyProf::Profile.new(measure_mode: RubyProf::WALL_TIME)
+
+profile.start
+
+work("data/data#{ENV['FILE_SIZE']}.txt")
+
+result = profile.stop
+
+
+printer4 = RubyProf::CallTreePrinter.new(result)
+printer4.print(:path => "profilers", :profile => 'callgrind')

profilers/rubyprof_clstk.rb

@@ -0,0 +1,15 @@
+require_relative '../work'
+require 'ruby-prof'
+
+GC.disable if ENV['GB_OFF']
+profile = RubyProf::Profile.new(measure_mode: RubyProf::WALL_TIME)
+
+profile.start
+
+work("data/data#{ENV['FILE_SIZE']}.txt")
+
+result = profile.stop
+
+
+printer = RubyProf::CallStackPrinter.new(result)
+printer.print(File.open('profilers/callstack.html', 'w+'))

profilers/rubyprof_flat.rb

@@ -0,0 +1,15 @@
+require_relative '../work'
+require 'ruby-prof'
+
+GC.disable if ENV['GB_OFF']
+profile = RubyProf::Profile.new(measure_mode: RubyProf::WALL_TIME)
+
+profile.start
+
+work("data/data#{ENV['FILE_SIZE']}.txt")
+
+result = profile.stop
+
+
+printer = RubyProf::FlatPrinter.new(result)
+printer.print(File.open("profilers/flat.txt", "w+"))

profilers/rubyprof_graph.rb

@@ -0,0 +1,15 @@
+require_relative '../work'
+require 'ruby-prof'
+
+GC.disable if ENV['GB_OFF']
+profile = RubyProf::Profile.new(measure_mode: RubyProf::WALL_TIME)
+
+profile.start
+
+work("data/data#{ENV['FILE_SIZE']}.txt")
+
+result = profile.stop
+
+
+printer = RubyProf::GraphHtmlPrinter.new(result)
+printer.print(File.open("profilers/graph.html", "w+"))

profilers/stackprof_cli.rb

@@ -0,0 +1,8 @@
+require_relative '../work'
+require 'stackprof'
+
+GC.disable if ENV['GB_OFF']
+
+StackProf.run(mode: :wall, out: 'profilers/stackprof.dump', interval: 1000) do
+  work("data/data#{ENV['FILE_SIZE']}.txt")
+end

spec/report_spec.rb

@@ -0,0 +1,47 @@
+require 'rspec'
+require 'rspec-benchmark'
+require_relative '../work'
+require 'byebug'
+require 'benchmark'
+
+
+RSpec.configure do |config|
+  config.include RSpec::Benchmark::Matchers
+end
+
+RSpec.describe do
+  let(:data_file_path)  { 'data.txt' }
+  let(:result_file_path)  { 'result.json' }
+
+  describe '#to_json logic test' do
+    subject { File.read(result_file_path) }
+
+    let(:expected_result)  do
+      '{"totalUsers":3,"uniqueBrowsersCount":14,"totalSessions":15,"allBrowsers":"CHROME 13,CHROME 20,CHROME 35,CHROME 6,FIREFOX 12,FIREFOX 32,FIREFOX 47,INTERNET EXPLORER 10,INTERNET EXPLORER 28,INTERNET EXPLORER 35,SAFARI 17,SAFARI 29,SAFARI 39,SAFARI 49","usersStats":{"Leida Cira":{"sessionsCount":6,"totalTime":"455 min.","longestSession":"118 min.","browsers":"FIREFOX 12, INTERNET EXPLORER 28, INTERNET EXPLORER 28, INTERNET EXPLORER 35, SAFARI 29, SAFARI 39","usedIE":true,"alwaysUsedChrome":false,"dates":["2017-09-27","2017-03-28","2017-02-27","2016-10-23","2016-09-15","2016-09-01"]},"Palmer Katrina":{"sessionsCount":5,"totalTime":"218 min.","longestSession":"116 min.","browsers":"CHROME 13, CHROME 6, FIREFOX 32, INTERNET EXPLORER 10, SAFARI 17","usedIE":true,"alwaysUsedChrome":false,"dates":["2017-04-29","2016-12-28","2016-12-20","2016-11-11","2016-10-21"]},"Gregory Santos":{"sessionsCount":4,"totalTime":"192 min.","longestSession":"85 min.","browsers":"CHROME 20, CHROME 35, FIREFOX 47, SAFARI 49","usedIE":false,"alwaysUsedChrome":false,"dates":["2018-09-21","2018-02-02","2017-05-22","2016-11-25"]}}}' + "\n"
+    end
+
+    it {
+      work(data_file_path, result_file_path)
+      is_expected.to eq(expected_result) 
+    }
+  end
+
+  describe '#performance' do
+    let(:file_size) { 1_000_000 }
+    let(:data_file_path)  { "data/data#{file_size}.txt" }
+    let(:result_file_path)  { 'result.json' }
+
+    it 'performs success' do
+      expect { work(data_file_path, result_file_path) }.to perform_under(10).sec
+    end
+  end
+
+  describe '#performance max' do
+    let(:data_file_path)  { "data_large.txt" }
+    let(:result_file_path)  { 'result.json' }
+
+    it 'performs success' do
+      expect { work(data_file_path, result_file_path) }.to perform_under(30).sec
+    end
+  end
+end