igor-arkhipov/performance-improvement-2

assert-performance.rb

@@ -0,0 +1,40 @@
+require 'rspec-benchmark'
+require_relative 'task-2'
+
+RSpec.configure do |config|
+  config.include RSpec::Benchmark::Matchers
+end
+
+describe 'Performance' do
+  describe 'work' do
+    # 100 lines under 6.9 milliseconds
+    it 'should work under 6.9 milliseconds' do
+      expect { work('data100.txt') }.to perform_under(6.9).ms.warmup(2).times.sample(10).times
+    end
+
+    # 1000 lines under 8.9 milliseconds
+    it 'should work under 8.9 milliseconds' do
+      expect { work('data1000.txt') }.to perform_under(8.9).ms.warmup(2).times.sample(10).times
+    end
+
+    # 10000 lines under 33 milliseconds
+    it 'should work under 33 milliseconds' do
+      expect { work('data10000.txt') }.to perform_under(33).ms.warmup(2).times.sample(10).times
+    end
+
+    # 10000 lines memory allocation
+    it 'should allocate 129098 objects' do
+      expect { work('data10000.txt') }.to perform_allocation(129098).and_retain(129098)
+    end
+
+    let(:measurement_time_seconds) { 1 }
+    let(:warmup_time_seconds) { 0.2 }
+    it 'works faster than 170 ips' do
+      expect { work('data100.txt') }.to perform_at_least(170).within(measurement_time_seconds).warmup(warmup_time_seconds).ips
+    end
+
+    it 'performs linear' do
+      expect { |n, _i| work("data#{n}.txt") }.to perform_linear.in_range(1000, 8000).ratio(2)
+    end
+  end
+end

benchmark.rb

@@ -0,0 +1,16 @@
+require 'benchmark'
+require_relative 'task-2'
+
+puts 'Started'
+time = Benchmark.realtime do
+  # work('data10000.txt')
+  work('data_large.txt')
+end
+puts "Finished in #{time.round(2)}"
+
+# Iteration 0: measurement without any changes for 10000 first strings = 0.73 seconds
+# Iteration 1: measurement after streaming refactoring = 0.06 seconds
+# Iteration 2: measurement after dates refactoring = 0.04 seconds, MEMORY USAGE: 39 MB
+# Iteration 3: measurement after complete map refactoring = 0.03 seconds, MEMORY USAGE: 39 MB
+# Iteration 4: measurement after iterative report write = 0.03 seconds, MEMORY USAGE: 36 MB
+# Iteration 4: measurement after iterative report write = 7.69 seconds, MEMORY USAGE: 33 MB for data_large

case-study.md

@@ -0,0 +1,72 @@
+# Case-study оптимизации
+
+## Актуальная проблема
+В нашем проекте возникла серьёзная проблема.
+
+Необходимо было обработать файл с данными, чуть больше ста мегабайт.
+
+У нас уже была программа на `ruby`, которая умела делать нужную обработку.
+
+Она успешно работала на файлах размером пару мегабайт, но для большого файла она работала слишком долго, и не было понятно, закончит ли она вообще работу за какое-то разумное время.
+
+Я решил исправить эту проблему, оптимизировав эту программу.
+
+## Формирование метрики
+Для того, чтобы понимать, дают ли мои изменения положительный эффект на быстродействие программы я придумал использовать такую метрику: объем используемой памяти на протяжении исполнения программы.
+
+## Гарантия корректности работы оптимизированной программы
+Программа поставлялась с тестом. Выполнение этого теста в фидбек-лупе позволяет не допустить изменения логики программы при оптимизации.
+
+## Feedback-Loop
+Для того, чтобы иметь возможность быстро проверять гипотезы, я выстроил эффективный `feedback-loop`, который позволил мне получать обратную связь по эффективности сделанных изменений за меньшее 30 секунд время.
+
+Вот как я построил `feedback_loop`: предоставленные данные разбиваются на меньшие объемы (100, 1000 ... 10000 строк), и уже на основе них строятся тесты для фиксирования текущей производительности и используемой памяти в процессе работы как отправной точки. Для этого код самой программы незначительно модифицируется, чтобы поддерживать параметры запуска: имя файла с данными и режим работы Garbage Collector. Самая первая итерация представляла из себя написание тестов производительности (время выполнения программы, объем используемой памяти в процессе работы). В данном случае это можно отнести к шагу Profile & Test & Benchmark. Полученные при первом запуске значения бенчмарка мы можем записать в цели теста для исключения регрессий на последующих итерациях.
+С этого момента наш feedback loop создан, и мы можем переходить к профилированию и изменению кода, после чего запускать уже написанные тесты для сравнения результатов с отправным шагом (или шагом предыдущей итерации).
+
+## Вникаем в детали системы, чтобы найти главные точки роста
+Для того, чтобы найти "точки роста" для оптимизации я воспользовался инструментами memory-profiler, ruby-prof и stackprof после завершения первого этапа, в котором исходный код был изменен, чтобы файл с данными читался и обрабатывался построчно, а не загружался целиком в память перед обработкой. Я так же заморозил все строчные литералы.
+
+Вот какие проблемы удалось найти и решить
+
+### Ваша находка №1
+- какой отчёт показал главную точку роста
+  * memory_profiler с профилем на 10.000 строк указал на MEMORY USAGE: 103 MB, Total allocated: 18.92 MB (259923 objects), Total retained: 4.79 kB (9 objects). Строка, где создавалось больше всего объектов - это та, где происходит конвертация формата даты пользовательской сессии. Эта строка станет главной точкой роста
+- как вы решили её оптимизировать
+  * на этой ознакомительной итерации были удалены избыточные преобразования дат во время обработки полученной информации о сессиях для каждого пользователя
+- как изменилась метрика
+  * MEMORY USAGE: 76 MB, Total allocated: 11.63 MB (155267 objects), Total retained: 40.00 B (1 objects)
+- как изменился отчёт профилировщика
+  * на первое место в отчете профилировщика теперь попала строка `cols = line.split(',')`, за ней следует операция помещения прочитанных в строке данных сессии во временный объект.
+
+### Ваша находка №2
+- какой отчёт показал главную точку роста
+  * ruby-prof не смог предоставить отчеты по аллокации памяти на версии 2.7.7 без патчей и на версии 2.7.7 с патчами, поэтому я перешел на ruby-prof в режиме MEMORY с просмотром отчета в qcachegrind. Отчет показал следующую точку роста внутри функции сбора статистики по всем сессиям одного пользователя: `String::upcase` 27.61% и `Array::map` 18.07%. Использование памяти на данном этапе составило порядка 40 MB.
+- как вы решили её оптимизировать
+  * очевидно, что после незначительной модернизации блока кода, ответственного за перебор сессий пользователя, следует довести рефакторинг этого блока до конца, избавившись от ненужных `map` операций, занимающих память временными объектами, и постаравшись сбор статистики совершать в процессе итерации обхода сессий.
+- как изменилась метрика
+  * MEMORY USAGE: 67 MB, Total allocated: 10.93 MB (134691 objects), Total retained: 40.00 B (1 objects)
+- как изменился отчёт профилировщика
+  * `String::upcase` 12.72% и `Array::each` 5.87%. Использование памяти на данном этапе составило порядка 40 MB.
+
+### Ваша находка №3
+- какой отчёт показал главную точку роста
+  * после того, как предыдущие итерации оптимизации снизили сложность алгоритма до линейного, стало возможным запускать бенчмарк и профилировщики на полном наборе данных.
+  * бенчмарк показал MEMORY USAGE: 1245 MB, Finished in 10.06
+  * memory_profiler показал MEMORY USAGE: 7188 MB, Total allocated: 3.55 GB (43771136 objects), Total retained: 40.00 B (1 objects)
+  * stackprof на 10.000 строках показал, что уровень аллокаций для блока с обработкой данных по сессиям по-прежнему высок
+- как вы решили её оптимизировать
+  * т.к. мы уже оптимизировали число итераций и привели алгоритм к линейному, что позволяет совершать обход конечного большого файла с данными целиком, на данной итерации придется сразу записывать итоговые данные по каждому пользователю в конечный файл. Мы все еще создаем промежуточные переменные, куда складываем получаемые на итерациях результаты, а затем передаем эти переменные обратно в верхние циклы обхода строк данных. Число аллокаций говорит нам о том, что все эти переменные для каждой сессии и пользователя так и остаются лежать в памяти, хотя их можно было бы высвободить на каждой новой итерации. Идея здесь в том, чтобы как только мы переходим к следующему пользователю, очищать предыдущие накопленные аллокации для временных вычислений статистики по предыдущему пользователю. Одновременно с этим получится и не раздувать итоговый отчет, который до изменений включает итоговые данные по абсолютно всем пользователям из файла данных.
+- как изменилась метрика
+  * MEMORY USAGE: 33 MB, Finished in 7.69
+- как изменился отчёт профилировщика
+  * скриншот из valgrind_massif показал, что в пике во время обработки файла со всеми данными использование памяти не выходит за рамки 37,1 MB
+  * MEMORY USAGE: 7089 MB, Total allocated: 3.71 GB (42019996 objects), Total retained: 11.38 kB (6 objects)
+
+## Результаты
+В результате проделанной оптимизации наконец удалось обработать файл с данными.
+Удалось улучшить метрику системы со 103 MB при 10.000 строк из исходного файла до 37 MB при всем объеме строк из data_large и уложиться в заданный бюджет.
+
+Время выполнения обработки исходного файла с данными на полном объеме строк составило почти в 2 раза меньше времени, чем в первом задании с оптимизацией по вычислительной мощности.
+
+## Защита от регрессии производительности
+Для защиты от потери достигнутого прогресса при дальнейших изменениях программы я использовал аналогичные первому заданию тесты на производительность алгоритма при числе строк 100, 1000, 1000, а так же тест на линейность алгоритма

data100.txt

@@ -0,0 +1,100 @@
+user,0,Hazel,Margarete,19
+session,0,0,Internet Explorer 50,81,2018-02-01
+session,0,1,Safari 27,88,2017-10-28
+session,0,2,Firefox 13,92,2016-11-02
+session,0,3,Internet Explorer 40,37,2017-05-31
+session,0,4,Internet Explorer 16,37,2017-11-21
+session,0,5,Safari 19,22,2017-11-30
+session,0,6,Chrome 31,74,2016-08-22
+session,0,7,Firefox 46,76,2019-02-04
+user,1,Wilfredo,Louetta,40
+session,1,0,Firefox 38,68,2018-04-24
+session,1,1,Internet Explorer 41,27,2016-09-06
+session,1,2,Internet Explorer 1,74,2017-01-05
+session,1,3,Firefox 47,28,2017-06-09
+session,1,4,Internet Explorer 22,98,2016-11-03
+user,2,Cecil,Rosalba,44
+session,2,0,Safari 26,96,2018-08-20
+session,2,1,Internet Explorer 10,3,2019-01-03
+session,2,2,Internet Explorer 47,52,2016-07-31
+session,2,3,Safari 34,37,2017-09-14
+session,2,4,Internet Explorer 17,22,2016-07-10
+session,2,5,Firefox 26,76,2017-02-06
+session,2,6,Chrome 14,88,2017-02-19
+session,2,7,Safari 31,113,2018-04-12
+session,2,8,Chrome 20,72,2016-09-04
+session,2,9,Safari 13,14,2017-07-26
+user,3,Kieth,Noble,20
+session,3,0,Safari 23,1,2018-02-19
+session,3,1,Internet Explorer 24,92,2018-05-15
+session,3,2,Chrome 6,91,2017-01-06
+session,3,3,Internet Explorer 47,7,2016-09-01
+session,3,4,Firefox 4,20,2017-03-22
+session,3,5,Internet Explorer 23,17,2016-12-02
+session,3,6,Internet Explorer 5,91,2017-12-29
+session,3,7,Internet Explorer 23,2,2017-03-17
+user,4,Corie,Erika,32
+session,4,0,Chrome 11,49,2019-02-05
+session,4,1,Safari 44,18,2017-09-01
+session,4,2,Firefox 32,88,2017-06-01
+session,4,3,Chrome 28,82,2018-03-18
+session,4,4,Firefox 38,36,2018-06-11
+session,4,5,Safari 14,11,2017-04-06
+session,4,6,Safari 27,116,2017-05-30
+session,4,7,Safari 24,36,2018-06-12
+session,4,8,Firefox 3,28,2018-01-05
+user,5,Lou,Lean,39
+session,5,0,Internet Explorer 42,74,2017-08-20
+session,5,1,Internet Explorer 1,80,2018-11-22
+session,5,2,Chrome 18,105,2018-01-17
+user,6,Deedra,Minta,44
+session,6,0,Firefox 32,27,2017-07-07
+session,6,1,Firefox 45,48,2017-07-22
+session,6,2,Safari 33,55,2018-07-09
+session,6,3,Safari 1,14,2016-11-08
+session,6,4,Firefox 39,18,2017-02-06
+session,6,5,Safari 12,52,2016-07-18
+session,6,6,Firefox 18,84,2016-08-16
+session,6,7,Chrome 2,114,2016-10-18
+user,7,Loria,Vernetta,68
+session,7,0,Safari 14,51,2019-01-25
+session,7,1,Internet Explorer 29,88,2016-10-12
+session,7,2,Firefox 32,55,2016-11-15
+session,7,3,Safari 4,20,2016-11-19
+session,7,4,Chrome 42,95,2018-02-10
+session,7,5,Safari 36,88,2018-03-30
+session,7,6,Safari 7,74,2017-05-27
+session,7,7,Safari 18,67,2017-02-22
+session,7,8,Chrome 24,26,2018-11-01
+user,8,Abdul,Venessa,55
+session,8,0,Internet Explorer 1,60,2018-12-02
+session,8,1,Chrome 3,63,2016-10-02
+session,8,2,Safari 41,99,2017-01-12
+session,8,3,Firefox 13,69,2017-04-17
+session,8,4,Safari 31,115,2018-04-08
+session,8,5,Chrome 30,77,2019-01-28
+session,8,6,Safari 43,56,2017-05-07
+user,9,Brooks,Janae,6
+session,9,0,Internet Explorer 36,11,2018-08-11
+user,10,Rey,Coy,95
+session,10,0,Internet Explorer 27,115,2017-08-05
+session,10,1,Internet Explorer 21,119,2018-11-15
+session,10,2,Internet Explorer 2,0,2016-06-10
+session,10,3,Safari 13,44,2018-04-07
+session,10,4,Firefox 37,26,2018-05-04
+user,11,Cyrus,Danyel,41
+session,11,0,Firefox 34,118,2016-10-14
+session,11,1,Internet Explorer 34,45,2017-10-10
+session,11,2,Internet Explorer 38,70,2017-07-10
+user,12,Valentin,Emilio,21
+session,12,0,Chrome 13,28,2018-04-23
+session,12,1,Firefox 35,17,2018-11-29
+session,12,2,Firefox 19,68,2018-05-03
+session,12,3,Internet Explorer 14,2,2016-09-18
+session,12,4,Firefox 15,97,2018-04-15
+session,12,5,Safari 26,40,2016-06-13
+user,13,Mitchell,Hobert,78
+session,13,0,Internet Explorer 32,89,2019-02-07
+session,13,1,Firefox 17,0,2017-11-05
+session,13,2,Chrome 17,117,2018-12-12
+session,13,3,Firefox 28,3,2016-12-01