diff --git a/case-study.md b/case-study.md new file mode 100644 index 0000000..e18b0e2 --- /dev/null +++ b/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 #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) + + +## Защита от регресса производительности +Для защиты от потери достигнутого прогресса при дальнейших изменениях программы написан тест diff --git a/feedback-loop.rb b/feedback-loop.rb new file mode 100644 index 0000000..3a4e9e3 --- /dev/null +++ b/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 diff --git a/img/call_stack.png b/img/call_stack.png new file mode 100644 index 0000000..1dd6c7f Binary files /dev/null and b/img/call_stack.png differ diff --git a/img/call_stack_1.png b/img/call_stack_1.png new file mode 100644 index 0000000..943117f Binary files /dev/null and b/img/call_stack_1.png differ diff --git a/img/call_stack_2.png b/img/call_stack_2.png new file mode 100644 index 0000000..6f84efe Binary files /dev/null and b/img/call_stack_2.png differ diff --git a/img/flamegraph.png b/img/flamegraph.png new file mode 100644 index 0000000..595392a Binary files /dev/null and b/img/flamegraph.png differ diff --git a/img/memory_after.png b/img/memory_after.png new file mode 100644 index 0000000..9552c4c Binary files /dev/null and b/img/memory_after.png differ diff --git a/img/memory_before.png b/img/memory_before.png new file mode 100644 index 0000000..9ed27a1 Binary files /dev/null and b/img/memory_before.png differ diff --git a/reference.json b/reference.json new file mode 100644 index 0000000..ad48563 --- /dev/null +++ b/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"]}}} diff --git a/task-2.rb b/task-2.rb index 778672d..43e1b35 100644 --- a/task-2.rb +++ b/task-2.rb @@ -1,58 +1,77 @@ -# Deoptimized version of homework task +# frozen_string_literal: true -require 'json' require 'pry' require 'date' -require 'minitest/autorun' +require 'oj' +require 'ruby-progressbar' + +IE = /INTERNET EXPLORER/.freeze +CHROME = /CHROME/.freeze +USER = 'user'.freeze +SESSION = 'session'.freeze +COMMA = ','.freeze class User - attr_reader :attributes, :sessions + attr_reader :sessions, :browsers, :time, :key def initialize(attributes:, sessions:) - @attributes = attributes + @key = "#{attributes[:first_name]} #{attributes[:last_name]}" @sessions = sessions + @browsers = sessions.map { |s| s[:browser] }.sort! { |x, y| x <=> y } + @time = sessions.map { |s| s[:time] } end -end -def parse_user(user) - fields = user.split(',') - parsed_result = { - 'id' => fields[1], - 'first_name' => fields[2], - 'last_name' => fields[3], - 'age' => fields[4], - } + def stats + { + sessionsCount: sessions.length, + totalTime: "#{time.sum} min.", + longestSession: "#{time.max} min.", + browsers: browsers.join(', '), + usedIE: browsers.any? { |b| b.match?(IE) }, + alwaysUsedChrome: browsers.uniq.all? { |b| b.match?(CHROME) }, + dates: sessions.map { |s| s[:date] }.sort! { |x, y| y <=> x } + } + end end -def parse_session(session) - fields = session.split(',') - parsed_result = { - 'user_id' => fields[1], - 'session_id' => fields[2], - 'browser' => fields[3], - 'time' => fields[4], - 'date' => fields[5], +def parse_user(users, fields) + users[fields[1].to_i] = { + first_name: fields[2], + last_name: fields[3], + age: fields[4] } + users end -def collect_stats_from_users(report, users_objects, &block) - users_objects.each do |user| - user_key = "#{user.attributes['first_name']}" + ' ' + "#{user.attributes['last_name']}" - report['usersStats'][user_key] ||= {} - report['usersStats'][user_key] = report['usersStats'][user_key].merge(block.call(user)) - end +def parse_session(sessions, fields) + id = fields[1].to_i + sessions[id] ||= [] + sessions[id] << { + session_id: fields[2], + browser: fields[3].upcase!, + time: fields[4].to_i, + date: fields[5] + } + sessions end -def work - file_lines = File.read('data.txt').split("\n") +def work(file_name) + file_lines = File.read(file_name).split("\n") - users = [] - sessions = [] + progressbar = ProgressBar.create(total: file_lines.length, format: '%a, %J, %E %B') + users = {} + sessions = {} file_lines.each do |line| - cols = line.split(',') - users = users + [parse_user(line)] if cols[0] == 'user' - sessions = sessions + [parse_session(line)] if cols[0] == 'session' + progressbar.increment + cols = line.split(COMMA) + + case cols[0] + when USER + parse_user(users, cols) + when SESSION + parse_session(sessions, cols) + end end # Отчёт в json @@ -70,107 +89,26 @@ def work # - Всегда использовал только Хром? + # - даты сессий в порядке убывания через запятую + - report = {} - - report[:totalUsers] = users.count + all_sessions = sessions.values.flatten # Подсчёт количества уникальных браузеров - uniqueBrowsers = [] - sessions.each do |session| - browser = session['browser'] - uniqueBrowsers += [browser] if uniqueBrowsers.all? { |b| b != browser } - end - - report['uniqueBrowsersCount'] = uniqueBrowsers.count - - report['totalSessions'] = sessions.count - - report['allBrowsers'] = - sessions - .map { |s| s['browser'] } - .map { |b| b.upcase } - .sort - .uniq - .join(',') - - # Статистика по пользователям - users_objects = [] - - users.each do |user| - attributes = user - user_sessions = sessions.select { |session| session['user_id'] == user['id'] } - user_object = User.new(attributes: attributes, sessions: user_sessions) - users_objects = users_objects + [user_object] - end + unique_browsers = all_sessions.map { |s| s[:browser] }.uniq! + report = {} + report['totalUsers'] = users.keys.length + report['uniqueBrowsersCount'] = unique_browsers.length + report['totalSessions'] = all_sessions.length + report['allBrowsers'] = unique_browsers.sort! { |x, y| x <=> y }.join(COMMA) report['usersStats'] = {} - # Собираем количество сессий по пользователям - collect_stats_from_users(report, users_objects) do |user| - { 'sessionsCount' => user.sessions.count } - end - - # Собираем количество времени по пользователям - collect_stats_from_users(report, users_objects) do |user| - { 'totalTime' => user.sessions.map {|s| s['time']}.map {|t| t.to_i}.sum.to_s + ' min.' } - end - - # Выбираем самую длинную сессию пользователя - collect_stats_from_users(report, users_objects) do |user| - { 'longestSession' => user.sessions.map {|s| s['time']}.map {|t| t.to_i}.max.to_s + ' min.' } - end - - # Браузеры пользователя через запятую - collect_stats_from_users(report, users_objects) do |user| - { 'browsers' => user.sessions.map {|s| s['browser']}.map {|b| b.upcase}.sort.join(', ') } - end - - # Хоть раз использовал IE? - collect_stats_from_users(report, users_objects) do |user| - { 'usedIE' => user.sessions.map{|s| s['browser']}.any? { |b| b.upcase =~ /INTERNET EXPLORER/ } } - end - - # Всегда использовал только Chrome? - collect_stats_from_users(report, users_objects) do |user| - { 'alwaysUsedChrome' => user.sessions.map{|s| s['browser']}.all? { |b| b.upcase =~ /CHROME/ } } - end - - # Даты сессий через запятую в обратном порядке в формате iso8601 - collect_stats_from_users(report, users_objects) do |user| - { 'dates' => user.sessions.map{|s| s['date']}.map {|d| Date.parse(d)}.sort.reverse.map { |d| d.iso8601 } } - end - - File.write('result.json', "#{report.to_json}\n") -end - -class TestMe < Minitest::Test - def setup - File.write('result.json', '') - File.write('data.txt', -'user,0,Leida,Cira,0 -session,0,0,Safari 29,87,2016-10-23 -session,0,1,Firefox 12,118,2017-02-27 -session,0,2,Internet Explorer 28,31,2017-03-28 -session,0,3,Internet Explorer 28,109,2016-09-15 -session,0,4,Safari 39,104,2017-09-27 -session,0,5,Internet Explorer 35,6,2016-09-01 -user,1,Palmer,Katrina,65 -session,1,0,Safari 17,12,2016-10-21 -session,1,1,Firefox 32,3,2016-12-20 -session,1,2,Chrome 6,59,2016-11-11 -session,1,3,Internet Explorer 10,28,2017-04-29 -session,1,4,Chrome 13,116,2016-12-28 -user,2,Gregory,Santos,86 -session,2,0,Chrome 35,6,2018-09-21 -session,2,1,Safari 49,85,2017-05-22 -session,2,2,Firefox 47,17,2018-02-02 -session,2,3,Chrome 20,84,2016-11-25 -') + users.each do |user_id, attrs| + user = User.new(attributes: attrs, sessions: sessions[user_id]) + report['usersStats'][user.key] ||= {} + report['usersStats'][user.key] = user.stats end - def test_result - work - expected_result = '{"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" - assert_equal expected_result, File.read('result.json') + File.open('result.json', 'w') do |file| + file.write(Oj.dump(report, mode: :compat)) + file.write("\n") end end