Optimization

.gitignore

@@ -0,0 +1,2 @@
+data.txt
+result.json

bench_test.rb

@@ -0,0 +1,20 @@
+require 'minitest/benchmark'
+require 'minitest/autorun'
+require './task-1'
+
+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,162 @@
+# Case-study оптимизации
+
+## Актуальная проблема
+В нашем проекте возникла серьёзная проблема.
+
+Необходимо было обработать файл с данными, чуть больше ста мегабайт.
+
+У нас уже была программа на `ruby`, которая умела делать нужную обработку.
+
+Она успешно работала на файлах размером пару мегабайт, но для большого файла она работала слишком долго, и не было понятно, закончит ли она вообще работу за какое-то разумное время.
+
+Я решил исправить эту проблему, оптимизировав эту программу.
+
+## Формирование метрики
+Для того, чтобы понимать, дают ли мои изменения положительный эффект на быстродействие программы я придумал использовать такую метрику:
+
+Среднее время выполнения и кол-во аллоцируемой памяти каждых 1000 строк для периода от 10 до 15 тыс. строк и других периодов.
+
+## Гарантия корректности работы оптимизированной программы
+Программа поставлялась с тестом. Выполнение этого теста позволяет не допустить изменения логики программы при оптимизации.
+
+## Feedback-Loop
+Для того, чтобы иметь возможность быстро проверять гипотезы я выстроил эффективный `feedback-loop`, который позволил мне получать обратную связь по эффективности сделанных изменений за одну минуту.
+
+Вот как я построил `feedback_loop`:
+
+Внесение изменений в код - Прогон тестов - Проверка улучшения метрик - Коммит изменений
+
+## Вникаем в детали системы, чтобы найти 20% точек роста
+Для того, чтобы найти "точки роста" для оптимизации я воспользовался инструментами:
+
+* `GC.stat`
+* `MemoryProfiler`
+* `ps`
+* `ObjectSpace.count_objects`
+* `StackProf`
+* `RubyProf`
+
+Вот какие проблемы удалось найти и решить
+
+### Ваша находка №1
+MemoryProfiler
+
+Аллоцируется 400 Mb объектов класса Array и 16 Mb класса String.
+Более всего памяти для класса Array выделяется в строках 53, 54, 100, 102.
+Более всего памяти для класса String выделяется в строках 39,46, 52, 139, 142.
+Аллоцируются одинаковые строки `" ", "session", ",", "user"`
+
+### Ваша находка №2
+StackProf
+
+Object mode
+
+207 000 callees of `file_lines.each`
+90 000 callees of `split`
+
+Object#collect_stats_from_users
+250 000 callees of `users_objects.each`
+190 000 callees of `report['usersStats'][user_key] = report['usersStats'][user_key].merge(block.call(user))`
+
+Wall mode
+```
+ 5822   (93.1%)                    |    98  |   users.each do |user|
+                                   |    99  |     attributes = user
+ 11584  (185.2%) /  5792  (92.6%)  |   100  |     user_sessions = sessions.select { |session| session['user_id'] == user['id'] }
+ ```
+
+
+
+### Ваша находка №3
+RubyProf
+
+Allocations mode
+```
+ %self      total      self      wait     child     calls  name
+ 27.38  146929.000 146929.000    0.000    0.000     20001  String#split
+ 24.28  489625.000 130272.000    0.000 359353.000   10010  *Array#each
+ 14.20  93120.000  76192.000     0.000 16928.000    8464   <Class::Date>#parse
+ ```
+
+Wall mode
+```
+ %self      total      self      wait     child     calls  name
+ 91.03      7.694     7.694     0.000     0.000     1536   Array#select
+  2.52      8.392     0.213     0.000     8.179     10010  *Array#each
+```
+
+
+## Результаты
+В результате проделанной оптимизации наконец удалось обработать файл с данными.
+Удалось улучшить метрику системы
+
+### Step 1
+Was
+```
+10000 lines performed in 5.98 s. + 74MB
+11000 lines performed in 7.97 s. + 52MB
+12000 lines performed in 9.24 s. + 63MB
+13000 lines performed in 11.27 s. + -12MB
+14000 lines performed in 14.17 s. + 12MB
+15000 lines performed in 16.11 s. + 12MB
+Average period for each 1000 lines: 2.026s.
+Average memory allocation for each 1000 lines: 33.5MB
+```
+
+Became
+```
+10000 lines performed in 0.25 s. + 14MB
+11000 lines performed in 0.34 s. + 1MB
+12000 lines performed in 0.4 s. + 1MB
+13000 lines performed in 0.41 s. + 5MB
+14000 lines performed in 0.46 s. + 2MB
+15000 lines performed in 0.48 s. + 1MB
+Average period for each 1000 lines: 0.046s.
+Average memory allocation for each 1000 lines: 4.0MB
+```
+
+### Step 2
+Was
+```
+50000 lines performed in 1.26 s. + 68MB
+51000 lines performed in 1.45 s. + 6MB
+52000 lines performed in 1.52 s. + 1MB
+53000 lines performed in 1.58 s. + 0MB
+54000 lines performed in 1.85 s. + -2MB
+55000 lines performed in 1.58 s. + 64MB
+Average period for each 1000 lines: 0.06400000000000002s.
+Average memory allocation for each 1000 lines: 22.83MB
+```
+
+Became
+```
+50000 lines performed in 1.09 s. + 66MB
+51000 lines performed in 1.28 s. + 6MB
+52000 lines performed in 1.37 s. + 2MB
+53000 lines performed in 1.4 s. + 1MB
+54000 lines performed in 1.52 s. + 0MB
+55000 lines performed in 1.54 s. + 0MB
+Average period for each 1000 lines: 0.09s.
+Average memory allocation for each 1000 lines: 12.5MB
+```
+
+### Final
+
+```
+50000 lines performed in 0.79 s. + 53MB
+51000 lines performed in 0.95 s. + 11MB
+52000 lines performed in 0.92 s. + 11MB
+53000 lines performed in 0.97 s. + 1MB
+54000 lines performed in 1.05 s. + 2MB
+55000 lines performed in 0.98 s. + 23MB
+Average period for each 1000 lines: 0.03799999999999999s.
+Average memory allocation for each 1000 lines: 16.83MB
+```
+
+```
+3_000_000 lines performed in 77.23 s. + 2879MB
+```
+
+## Защита от регресса производительности
+Для защиты от потери достигнутого прогресса при дальнейших изменениях программы
+написан тест `bench_test.rb`.

metrics.rb

@@ -0,0 +1,50 @@
+require 'benchmark'
+require './task-1'
+
+def allocated_memory
+  `ps -o rss= -p #{Process.pid}`.to_i / 1024
+end
+
+def mac_os?
+  RUBY_PLATFORM.match?(/darwin/)
+end
+
+from = 50_000
+to   = 55_000
+step = 1000
+
+times = []
+allocations = []
+
+(from..to).step(step) do |lines_num|
+
+  if mac_os?
+    system "zcat < data_large.txt.gz | head -n #{lines_num} > data.txt"
+  else
+    system "zcat data_large.txt.gz | head -n #{lines_num} > data.txt"
+  end
+
+  time = Benchmark.realtime do
+    memory = allocated_memory
+    work
+    allocations << allocated_memory - memory
+  end.round(2)
+
+  puts "#{lines_num} lines performed in #{time} s. + #{allocations.last}MB"
+
+  times << time.round(2)
+end
+
+deltas = []
+
+times.each_index do |i|
+  break if times[i.next].nil?
+
+  deltas << times[i.next] - times[i]
+end
+
+avg_delta = deltas.reduce(:+) / deltas.size
+mem_delta = (allocations.reduce(:+) / allocations.size.to_f).round(2)
+
+puts "Average period for each #{step} lines: #{avg_delta}s."
+puts "Average memory allocation for each #{step} lines: #{mem_delta}MB"

profilers/gc_stat.rb

@@ -0,0 +1,5 @@
+require_relative '../task-1'
+
+puts "old GC stat:\n #{GC.stat}"
+work
+puts "new GC stat:\n #{GC.stat}"

profilers/memory_profiler.rb

@@ -0,0 +1,8 @@
+require 'memory_profiler'
+require_relative '../task-1.rb'
+
+report = MemoryProfiler.report(trace: [String]) do
+  work
+end
+
+report.pretty_print(scale_bytes: true)

profilers/memory_usage.rb

@@ -0,0 +1,9 @@
+require_relative '../task-1.rb'
+
+def print_memory_usage
+  "%d MB" % (`ps -o rss= -p #{Process.pid}`.to_i / 1024)
+end
+
+puts "rss before: #{print_memory_usage}"
+work
+puts "rss after: #{print_memory_usage}"

profilers/object_space_objects.rb

@@ -0,0 +1,11 @@
+require_relative '../task-1'
+
+def print_object_space_delta(before, after)
+  puts "TOTAL:    #{after[:TOTAL] - before[:TOTAL]}"
+  puts "T_STRING: #{after[:T_STRING] - before[:T_STRING]}"
+  puts "T_ARRAY:  #{after[:T_ARRAY] - before[:T_ARRAY]}"
+end
+
+object_space_before = ObjectSpace.count_objects
+work
+print_object_space_delta(object_space_before, ObjectSpace.count_objects)

profilers/realtime.rb

@@ -0,0 +1,8 @@
+require 'benchmark'
+require_relative '../task-1'
+
+time = Benchmark.realtime do
+  work
+end
+
+puts "Finish in #{time.round(2)}"

profilers/rubyprof.rb

@@ -0,0 +1,18 @@
+require 'ruby-prof'
+require_relative '../task-1'
+
+def profile(mode:)
+  puts "*** Measure mode #{mode} ***"
+
+  RubyProf.measure_mode = Object.const_get("RubyProf::#{mode.upcase}")
+
+  result = RubyProf.profile do
+    work
+  end
+
+  printer = RubyProf::FlatPrinter.new(result)
+  printer.print(STDOUT)
+end
+
+profile(mode: :allocations)
+profile(mode: :wall_time)

profilers/stackprof.rb

@@ -0,0 +1,20 @@
+require 'stackprof'
+require_relative '../task-1'
+
+def profile(mode:)
+  dump_file = "/tmp/stackprof_#{mode}.dump"
+
+  StackProf.run(mode: mode, out: dump_file, raw: true) do
+    work
+  end
+
+  puts "*** Stackprof #{mode} mode ***"
+  system "stackprof #{dump_file} --text --limit 3"
+  puts '=== Object#work ==='
+  system %(stackprof #{dump_file} --method 'Object#work')
+  puts '=== Object#collect_stats_from_users ==='
+  system %(stackprof #{dump_file} --method 'Object#collect_stats_from_users')
+end
+
+profile(mode: :object)
+profile(mode: :wall)