Task 2. CPU optimization

case-study.md

@@ -0,0 +1,150 @@
+# Case-study оптимизации
+
+## Актуальная проблема
+В нашем проекте возникла серьёзная проблема.
+
+Необходимо было обработать файл с данными, чуть больше ста мегабайт.
+
+У нас уже была программа на `ruby`, которая умела делать нужную обработку.
+
+Она успешно работала на файлах размером пару мегабайт, но для большого файла она работала слишком долго, и не было понятно, закончит ли она вообще работу за какое-то разумное время.
+
+Я решил исправить эту проблему, оптимизировав эту программу.
+
+## Формирование метрики
+Для того, чтобы понимать, дают ли мои изменения положительный эффект на быстродействие программы я придумал использовать такую метрику: *Количество итераций в секунду (ips) работы программы на тестовых данных (размером 1Mb)*
+
+## Гарантия корректности работы оптимизированной программы
+Программа поставлялась с тестом. Выполнение этого теста позволяет не допустить изменения логики программы при оптимизации.
+
+## Feedback-Loop
+Для того, чтобы иметь возможность быстро проверять гипотезы я выстроил эффективный `feedback-loop`, который позволил мне получать обратную связь по эффективности сделанных изменений примерно за *5 сек.*
+
+Вот как я построил `feedback_loop`:
+
+Выделил в отдельный файл 1М данных из исходного файла.
+
+Написал отдельный скрипт `feedback-loop.rb`, который проверяет:
+- прохождение теста
+- выполняет замер метрики
+
+Используя его я могу быстро протестировать гипотезы и понимать их влияние на целевую метрику. При этом выполнение теста защищаем меня от случайной регресии функциональности системы на каждом шаге.
+
+## Фиксируем исходное состоние системы
+Исходная программа имеет **~3.268 ips**, время работы составило **~5,2 сек.**
+
+## Вникаем в детали системы, чтобы найти 20% точек роста
+### RbSpy
+По flamegraph видно, что больше всего процессорного времени занимает си функции и сбор статистики пользователя
+![massif visualizer](img/flamegraph.png)
+
+### Valgrind Massif ###
+Зафиксируем размер потребляемой памяти работы программы на тестовых данных.
+Пиковое значение составило 91МБ
+![massif visualizer](img/memory_before.png)
+
+### Ruby-prof ###
+Сформировал отчет `ruby-prof` с измерением `WALL_TIME` в режиме `Flat`. Видно, что больше всего процессорного времени забирает метод массива `each`.
+```
+ %self      total      self      wait     child     calls  name
+ 14.50      0.964     0.242     0.000     0.723        2   Array#each
+  8.38      0.415     0.140     0.000     0.275        1   JSON::Ext::Generator::GeneratorMethods::Hash#to_json
+  7.44      0.124     0.124     0.000     0.000    12235   Array#map
+  6.87      0.165     0.114     0.000     0.051     8157   Array#sort!
+  6.86      0.354     0.114     0.000     0.239    12235   Array#map!
+  6.72      0.189     0.112     0.000     0.077    22613   <Class::Date>#iso8601
+  6.09      0.101     0.101     0.000     0.000    67477   String#encode
+  5.49      0.160     0.091     0.000     0.068    22613   JSON::Ext::Generator::GeneratorMethods::Object#to_json
+```
+При этом значительную часть времени занимают дочерние методы **0.723** от общего **0.964**. В режиме `CallStack` можно наблюдать неоптимальную ветвь.
+![CallStack](img/call_stack.png)
+
+Вот какие проблемы удалось найти и решить
+
+## 1. iso8601
+Метод iso8601 по капотом которого находится регулярка забирает значительный процент ресурса процессора. Вынес его в отдельный метод и переписал
+
+```ruby
+def convert_date(date)
+  Date.new(*date.split('-').map!(&:to_i)).iso8601
+end
+```
+```ruby
+ dates: sessions.map { |s| s[:date] }.map! { |d| convert_date(d) }.sort! { |x, y| y <=> x }
+```
+в результате ips существенно увеличилось до **6,75** время выполения программы составило **~5 сек**
+
+В целом считаю преобразование в iso8601 лишней операцией, т.к. дата в исходных данных, уже в формате iso8601.
+Если убрать это лишнее преобразование получим прирост до **8,5 ips** за то же время работы программы в 5 сек.
+
+## 2. to_json
+Следующий в топе метод `to_json` занимал **23%** процессорного времени, преобразование отчета в json при записи файла.
+Оценил [сравнение производительности гемов](http://www.ohler.com/dev/oj_misc/performance_compat.html).
+Заменил гем `json` на `oj`
+
+```ruby
+file.write(Oj.dump(report, mode: :compat))
+```
+Получил прирост производительности **9,5 ips**
+```
+Calculating -------------------------------------
+Process 1 MB of data      9.537  (±10.5%) i/s -     47.000  in   5.044435s
+```
+
+![CallStack](img/call_stack_1.png)
+
+## 3. User#stats
+Примерно 30% занимает сбор статистики пользователя, из которого большая часть составляет операции с массивом `map`, `all?`, `join`, `uniq`, `any?`
+
+### 3.1. sort!
+Больше всего времени занимает операция `sort!`
+Заменил на
+```ruby
+sort! { |x, y| x <=> y }
+```
+Получил незначительный прирост производительности **9,8 ips**
+Также была попытка использовать `SortedSet` но это только ухудшило метрику, пришлось откатываться
+![CallStack](img/call_stack_2.png)
+
+### 3.2. Regexp
+Зафризил константы браузеров
+```ruby
+IE = /INTERNET EXPLORER/.freeze
+CHROME = /CHROME/.freeze
+```
+и заменил `=~`
+```ruby
+usedIE: browsers.any? { |b| b =~ IE },
+alwaysUsedChrome: browsers.uniq.all? { |b| b =~ CHROME },
+```
+на метод `match?`
+```ruby
+usedIE: browsers.any? { |b| b.match?(IE) },
+alwaysUsedChrome: browsers.uniq.all? { |b| b.match?(CHROME) },
+```
+Получил еще незначительный прирост производительности **10,1 ips**
+
+### 3.3. count >> length
+Согласно [ruby-fast](https://github.com/JuanitoFatas/fast-ruby) заменил у всех массивов метод `count` на `lenght`, это тоже дало незначительный прирост **10,4 ips**
+
+В целом после мелких и прирост составил **~1 ips**
+
+## 4. with_object
+Порядка 20% занимаем работа enumarator-a `with_object`.
+Переделал на `each`,
+получил прирост производительности **10,8 ips** за те же **~5 сек**
+
+## Результаты
+В результате проделанной оптимизации удалось существенно ускорить обработку файла.
+Удалось улучшить метрику системы с **~3.268 ips до 10,8 ips**
+
+Время выполнения программы с тестовыми данными составило **5 сек**.
+
+Время работы программы с реальными данными составило **13,67 сек**
+
+Также немного удалось снизить потреблением памяти до **84,6 МБ**
+![massif visualizer](img/memory_after.png)
+
+
+## Защита от регресса производительности
+Для защиты от потери достигнутого прогресса при дальнейших изменениях программы написан тест

feedback-loop.rb

@@ -0,0 +1,21 @@
+require 'benchmark/ips'
+require './task-2.rb'
+
+def reevaluate_metric
+  Benchmark.ips do |bench|
+    bench.report('Process 1 MB of data') do
+      work('data/data_1mb.txt')
+    end
+  end
+end
+
+def test_correctness
+  File.write('result.json', '')
+  work('fixtures/data_fixture.txt')
+  expected_result = File.read('fixtures/expected_result_fixture.json')
+  passed = expected_result == File.read('result.json')
+  passed ? puts('PASSED') : puts('!!! TEST FAILED !!!')
+end
+
+reevaluate_metric
+test_correctness

reference.json

@@ -0,0 +1 @@
+{"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"]}}}