Optimization

.gitignore

@@ -0,0 +1,4 @@
+*.txt
+result.json
+massif.out.*
+.DS_Store

bench_test.rb

@@ -0,0 +1,20 @@
+require 'minitest/benchmark'
+require 'minitest/autorun'
+require './task-2'
+
+class BenchTest < MiniTest::Benchmark
+  def self.bench_range
+    [1_000, 10_000, 100_000]
+  end
+
+  def bench_algorithm
+    assert_performance_linear 0.9999 do |n|
+      algorithm(n)
+    end
+  end
+
+  def algorithm(lines_num)
+    system "zcat data_large.txt.gz | head -n #{lines_num} > data.txt"
+    work
+  end
+end

case-study.md

@@ -0,0 +1,143 @@
+# Case-study оптимизации
+
+## Актуальная проблема
+В нашем проекте возникла серьёзная проблема.
+
+Необходимо было обработать файл с данными, чуть больше ста мегабайт.
+
+У нас уже была программа на `ruby`, которая умела делать нужную обработку.
+
+Она успешно работала на файлах размером пару мегабайт, но для большого файла она работала слишком долго, и не было понятно, закончит ли она вообще работу за какое-то разумное время.
+
+Я решил исправить эту проблему, оптимизировав эту программу.
+
+## Формирование метрики
+Для того, чтобы понимать, дают ли мои изменения положительный эффект на быстродействие программы я придумал использовать такую метрику: 
+
+*ips для файлов с разным количеством строк (кратно 2000).*
+
+```
+Calculating -------------------------------------
+Process with 2000 lines
+                          5.641  (± 0.0%) i/s -     29.000  in   5.143275s
+Process with 4000 lines
+                          1.532  (± 0.0%) i/s -      8.000  in   5.226870s
+Process with 8000 lines
+                          0.269  (± 0.0%) i/s -      2.000  in   7.430696s
+Process with 16000 lines
+                          0.063  (± 0.0%) i/s -      1.000  in  15.813776s
+
+Comparison:
+Process with 2000 lines:        5.6 i/s
+Process with 4000 lines:        1.5 i/s - 3.68x  slower
+Process with 8000 lines:        0.3 i/s - 20.94x  slower
+Process with 16000 lines:        0.1 i/s - 89.20x  slower
+```
+
+А также изучим график из Valigrind
+
+![Valgrind Before](/png/valgr_before.png)
+
+## Гарантия корректности работы оптимизированной программы
+Программа поставлялась с тестом. Выполнение этого теста позволяет не допустить изменения логики программы при оптимизации.
+
+## Feedback-Loop
+Для того, чтобы иметь возможность быстро проверять гипотезы я выстроил эффективный `feedback-loop`, который позволил мне получать обратную связь по эффективности сделанных изменений за *время, которое у вас получилось*
+
+Вот как я построил `feedback_loop`:
+
+Файл `feedback_loop.rb` замеряет ips для целевого количества строк, а также проверяет прохождения теста программы.
+
+UPD:
+Добавил вывод предыдущего прогона.
+```
+*** Previous result ***
+ Process 16000 lines      2.280  (± 0.0%) i/s -     12.000  in   5.266539s
+*** Result ***
+Warming up --------------------------------------
+ Process 16000 lines     1.000  i/100ms
+Calculating -------------------------------------
+ Process 16000 lines      2.769  (± 0.0%) i/s -     14.000  in   5.062075s
+ ```
+
+## Вникаем в детали системы, чтобы найти 20% точек роста
+Для того, чтобы найти "точки роста" для оптимизации я воспользовался профайлером *RubyProf*
+
+### Режим Flat
+
+```
+ %self      total      self      wait     child     calls  name
+ 93.93     18.388    18.388     0.000     0.000     2436   Array#select
+  1.94     19.500     0.380     0.000    19.120    16010  *Array#each
+  0.46      0.090     0.090     0.000     0.000    32001   String#split
+  0.46      0.260     0.089     0.000     0.171    26798   Array#map
+  0.35      0.142     0.069     0.000     0.073    13564   <Class::Date>#parse
+```
+
+### Режим Graph
+![Graph](/png/ruby_prof_graph.png)
+
+### Режим CallStack
+![CallStack](/png/call_stack.png)
+
+### Режим CallTree
+![CallTree](/png/call_tree.png)
+
+### Rbspy
+Ничего нового не сказал. Может я его неправильно приготовил.
+![Rbspy_Flame](/records/rbspy-flamegraph.svg)
+
+Вот какие проблемы удалось найти и решить
+
+### Первая итерация
+* Большую часть процессорного времени занимает `select` вложенный в `each`
+* Подозрение на вложенный цикл: `all?` в `each`
+
+### Вторая итерация
+* Метод `collect_stats_from_users` занимает 60% времени. [CallStack](http://htmlpreview.github.io/?https://github.com/stanislove/task-2/blob/optimization/rubyprof/call_stack_1553284084.html)
+
+### Третья итерация
+* Попробовать оптимизировать методы `parse_user` и `parse_session`. [Предпосылки](http://htmlpreview.github.io/?https://github.com/stanislove/task-2/blob/optimization/rubyprof/call_stack_1553285252.html)
+
+### Четрвёртая итерация
+* 20% занимает формирование JSON. Некоторый прирост ips дал гем Oj.
+
+### Пятая итерация
+* 18% парсинг даты - добавил кастомную регулярку.
+
+## Результаты
+В результате проделанной оптимизации наконец удалось обработать файл с данными.
+Удалось улучшить метрику системы
+
+```
+Warming up --------------------------------------
+Process with 2000 lines
+                         1.000  i/100ms
+Process with 4000 lines
+                         1.000  i/100ms
+Process with 8000 lines
+                         1.000  i/100ms
+Process with 16000 lines
+                         1.000  i/100ms
+Calculating -------------------------------------
+Process with 2000 lines
+                         60.201  (±10.0%) i/s -    290.000  in   5.007587s
+Process with 4000 lines
+                         28.857  (± 6.9%) i/s -    144.000  in   5.007349s
+Process with 8000 lines
+                         12.940  (± 7.7%) i/s -     65.000  in   5.039034s
+Process with 16000 lines
+                          6.747  (± 0.0%) i/s -     34.000  in   5.061690s
+
+Comparison:
+Process with 2000 lines:       60.2 i/s
+Process with 4000 lines:       28.9 i/s - 2.09x  slower
+Process with 8000 lines:       12.9 i/s - 4.65x  slower
+Process with 16000 lines:        6.7 i/s - 8.92x  slower
+```
+
+![Valgrind After](/png/valgr_after.png)
+
+## Защита от регресса производительности
+Для защиты от потери достигнутого прогресса при дальнейших изменениях программы
+написан тест `bench_test.rb`.

feedback_loop.rb

@@ -0,0 +1,41 @@
+require 'benchmark/ips'
+require './task-2'
+
+def mac_os?
+  RUBY_PLATFORM.match?(/darwin/)
+end
+
+def populate(lines_num)
+  if mac_os?
+    system "zcat < data_large.txt.gz | head -n #{lines_num} > data_#{lines_num}.txt"
+  else
+    system "zcat data_large.txt.gz | head -n #{lines_num} > data_#{lines_num}.txt"
+  end
+end
+
+target = 16_000
+
+populate(target)
+
+if File.exist?('ips.result')
+  puts "*** Previous result ***"
+  system("cat ips.result")
+end
+
+GC.disable
+
+puts "*** Result ***"
+result = Benchmark.ips do |bench|
+  bench.config(stats: :bootstrap, confidence: 99)
+  bench.report("Process #{target} lines") do
+    work("data_#{target}.txt")
+  end
+end
+
+_stdout = $stdout
+$stdout = StringIO.new
+result.entries.each(&:display)
+File.open('ips.result', 'w') { |file| file << $stdout.string }
+$stdout = _stdout
+
+require './task_test'

ips.result

@@ -0,0 +1 @@
+ Process 16000 lines      8.521  (± 2.1%) i/s -     43.000  in   5.060054s

metrics.rb

@@ -0,0 +1,31 @@
+require 'benchmark/ips'
+require './task-2'
+
+def mac_os?
+  RUBY_PLATFORM.match?(/darwin/)
+end
+
+def lines_nums
+  (1..4).map { |x| 1000 * 2**x }
+end
+
+def populate(lines_num)
+  if mac_os?
+    system "zcat < data_large.txt.gz | head -n #{lines_num} > data_#{lines_num}.txt"
+  else
+    system "zcat data_large.txt.gz | head -n #{lines_num} > data_#{lines_num}.txt"
+  end
+end
+
+lines_nums.each { |lines_num| populate(lines_num) }
+
+Benchmark.ips do |bench|
+  bench.config(stats: :bootstrap, confidence: 99)
+  bench.warmup = 0
+
+  lines_nums.each do |lines_num|
+    bench.report("Process with #{lines_num} lines") { work("data_#{lines_num}.txt") }
+  end
+
+  bench.compare!
+end

pid_work.rb

@@ -0,0 +1,5 @@
+require './task-2'
+
+GC.disable
+puts Process.pid
+work(ENV['DATA'] || 'test_16000.txt')

profilers/rubyprof.rb

@@ -0,0 +1,17 @@
+require 'ruby-prof'
+require_relative '../task-2'
+
+def profile(mode:)
+  puts "*** Measure mode #{mode} ***"
+
+  RubyProf.measure_mode = Object.const_get("RubyProf::#{mode.upcase}")
+
+  result = RubyProf.profile do
+    work('data_16000.txt')
+  end
+
+  printer = RubyProf::FlatPrinter.new(result)
+  printer.print(STDOUT)
+end
+
+profile(mode: ENV['RUBYPROF_MODE'])