Skip to content

case-study-template.md

Latest commit

 

History

History
217 lines (191 loc) · 12.5 KB

case-study-template.md

File metadata and controls

217 lines (191 loc) · 12.5 KB

Case-study оптимизации

Актуальная проблема

В нашем проекте возникла серьёзная проблема.

Необходимо было обработать файл с данными, чуть больше ста мегабайт.

У нас уже была программа на ruby, которая умела делать нужную обработку.

Она успешно работала на файлах размером пару мегабайт, но для большого файла она работала слишком долго, и не было понятно, закончит ли она вообще работу за какое-то разумное время.

Я решил исправить эту проблему, оптимизировав эту программу.

Формирование метрики

Для того, чтобы понимать, дают ли мои изменения положительный эффект на быстродействие программы я придумал использовать такую метрику: тут ваша метрика

Гарантия корректности работы оптимизированной программы

Программа поставлялась с тестом. Выполнение этого теста в фидбек-лупе позволяет не допустить изменения логики программы при оптимизации.

Feedback-Loop

Для того, чтобы иметь возможность быстро проверять гипотезы я выстроил эффективный feedback-loop, который позволил мне получать обратную связь по эффективности сделанных изменений за несколько секунд

Вот как я построил feedback_loop:

  1. запускал написанный bash скрипт который выполнял выгрузку профалеров
  2. в браузере смотрел точку роста
  3. правил код на основе точки роста
  4. запускал снова скрипт
  5. смотрел к чему привело, если откату, то возвращал обратно
  6. и тд

Вникаем в детали системы, чтобы найти главные точки роста

Для того, чтобы найти "точки роста" для оптимизации я воспользовался всеми профайлерами из лекции, чтобы получить опыт.

Вот какие проблемы удалось найти и решить и как начинал:

находка №1

  1. Написал тест задав бюджет: 30 секунд и линейной асимптотикой.
  2. При выполнении на маленьком data.txt получил логарифмическую асимптотику.
  3. Создал файлы с разным количеством строк и убедился, что уже на 40тыс строк все долго виснет.
  4. Чтобы понять затратные операции, решил посмотреть отчеты всех профилировщиков
  5. Из отчета в task-1_graph_data_file_data10000.txt_disable_gc_true.html увидел:
  • что 10 раз вызывается Array#each и в нем 1536/1536 Array#select что занимает 97.29% времени
  • сам Array#select потребляет 52.22% и в нем Hash#[] 26001408/26144384 26.01% и String#== 13000704/13861980 13.91% Таким образом главная точка раста - разобраться для начала с Array#select.
  1. Сравнил время выполнения benchmark/ips на разных объемах строк в файлах: 
      Comparison:
  data5000.txt:        1.6 i/s
  data10000.txt:       0.5 i/s - 3.06x  (± 0.19) slower
  data15000.txt:       0.3 i/s - 6.29x  (± 0.36) slower
  data20000.txt:       0.1 i/s - 11.31x  (± 0.61) slower
  with 95.0% confidence
    Видно, что обработка 10тыс. строк в ~3 раз медленнее чем 5 тыс. После 10 тыс. с увеличением на 5 тыс. в 2x раза увеличвается время выполнения.
  2. Запоминаю время обработки:
  • выставляю в тесте rspec текущее время выполнения 10 секунд на файл 5 тыс., чтобы не скатиться ниже
  • измеряю время в benchmark:
 1 - Before refactoring:
 "data5000.txt  finish in 1.07"
 "data10000.txt finish in 2.48"
 "data15000.txt finish in 5.48"
 "data20000.txt finish in 9.69"
  1. Начинаю рефактор Array#select, а именно user_sessions = sessions.select { |session| session['user_id'] = }
# Преобразовываю массив сессий в хэш-таблицу по 'user_id'
sessions_by_user_id = sessions.group_by { |session| session['user_id'] }

users.each do |user|
  attributes = user

  # user_sessions = sessions.select { |session| session['user_id'] = }
  # Ищу из созданного хеша
  user_sessions = sessions_by_user_id[user['id']] || []

  user_object = User.new(attributes:, sessions: user_sessions)
  users_objects += [user_object]
  progressbar.increment
end
  1. Снова измеряю время в benchmark, получаю утешительную картину, время уменьшилось в ~8 раз
2 - After refactoring:
user_sessions = sessions.select { |session| session['user_id'] = }
"data5000.txt finish in 0.17"
"data10000.txt finish in 0.29"
"data15000.txt finish in 0.55"
"data20000.txt finish in 0.77"
  1. Теперь самое время бы почить на лаврах, но надо проверить выполнится ли заданная метрика (30 s) на data_large.txt, но увы обработка будто виснет, значит ищем дальше точки раста в профайлерах.

находка №2

  • какой отчёт показал главную точку роста rubyprof - flat
  • как решил её оптимизировать
file_lines.each do |line|
  cols = line.split(',')
  case cols[0]
  when 'user'
    users << parse_user(line)
  when 'session'
    sessions << parse_session(line)
  end
end
  • как изменилась метрика
"data5000.txt finish in 0.15"
"data10000.txt finish in 0.2"
"data15000.txt finish in 0.3"
"data20000.txt finish in 0.38"
  • как изменился отчёт профилировщика - исправленная проблема перестала быть главной точкой роста? Да, появилась новая точка роста

Ваша находка №3

  • какой отчёт показал главную точку роста rp-flat %self total self wait child calls name location 33.98 0.240 0.240 0.000 0.000 1 Class::IO#write
    11.74 0.388 0.083 0.000 0.305 17 *Array#each
    7.94 0.056 0.056 0.000 0.000 1 Class::IO#read
    7.26 0.150 0.051 0.000 0.099 33508 Array#map
    5.48 0.039 0.039 0.000 0.000 307946 Hash#[] rp-graph 0.26 0.05 0.00 0.21 7/17 Object#collect_stats_from_users 39 75.45% 15.82% 0.38 0.08 0.00 0.30 17 *Array#each rp-callstack 49.18% (100.00%) Array#each [7 calls, 17 total] 26.14% (53.15%) Array#map [33506 calls, 33508 total] 13.41% (51.29%) Class::Date#parse [16954 calls, 16954 total] 2.15% (16.01%) Regexp#match [33908 calls, 33908 total] 2.05% (15.32%) String#gsub! [16954 calls, 16954 total] 1.28% (9.57%) MatchData#begin [16954 calls, 16954 total] sp-cli Mode: wall(1000) Samples: 180 (3.23% miss rate) GC: 0 (0.00%)

    TOTAL (pct) SAMPLES (pct) FRAME 180 (100.0%) 26 (14.4%) Object#work 45 (25.0%) 23 (12.8%) Date.parse 23 (12.8%) 23 (12.8%) Array#include? 22 (12.2%) 22 (12.2%) String#split 102 (56.7%) 17 (9.4%) Object#collect_stats_from_users 11 (6.1%) 11 (6.1%) Regexp#match 71 (39.4%) 11 (6.1%) Array#map 6 (3.3%) 6 (3.3%) Date#iso8601 13 (7.2%) 6 (3.3%) Object#parse_session 6 (3.3%) 6 (3.3%) String#gsub! 5 (2.8%) 5 (2.8%) Array#sort 5 (2.8%) 5 (2.8%) Hash#merge 4 (2.2%) 4 (2.2%) MatchData#begin 4 (2.2%) 3 (1.7%) Enumerable#group_by 3 (1.7%) 3 (1.7%) String#upcase 170 (94.4%) 3 (1.7%) Array#each 2 (1.1%) 2 (1.1%) IO.write sp-flame

  • как решил её оптимизировать

# def collect_stats_from_users(report, users_objects)
#   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(yield(user))
#   end
# end
def collect_stats_from_users(report, users_objects)
  users_objects.each do |user|
    user_key = "#{user.attributes['first_name']} #{user.attributes['last_name']}"
    report['usersStats'][user_key] ||= {}
    report['usersStats'][user_key].update(yield(user))
  end
end
  • как изменилась метрика
"data5000.txt finish in 0.15"
"data10000.txt finish in 0.19"
"data15000.txt finish in 0.28"
"data20000.txt finish in 0.36"
  • как изменился отчёт профилировщика - исправленная проблема перестала быть главной точкой роста? Да, появились новые точки роста

Потом я решил не косектировать данные шаги, а по этому сценарию проходиться по другим точкам роста. Долго не мог выяснить как дальше оптимизировать внося минимальные правки в код. И дошел то точки роста Date.parse, плюс к которому было еще преобразование в iso что на деле оказалось не нужным. Удалив это преобразование - получил boost скорости и выполнение в рамках бюджета.

Результаты

В результате проделанной оптимизации наконец удалось обработать файл с данными. Удалось улучшить метрику системы с неизвестного времени обработки файла в ~30 s уложиться в заданный бюджет.

Столкнулся с тем, что папка проекта лежала у меня на сетевом диске и только потом заметил, что это сильно влияло на IO. И тесты плавали. Я уже даже думал не уж то надо переписывать код, так пол времени занимала запись в итоговый файл json.

Добавил rubyprof flamegraph не затронутый в лекции и установил speedscope локально, чтобы командой запускать: speedscope ruby_prof_reports/task-1_flamegraph_data_file_data20000.txt_disable_gc_true.json

Добавил новый Firefox Profiler, используя гемы:

gem 'vernier'
gem 'profile-viewer'

Защита от регрессии производительности

Для защиты от потери достигнутого прогресса при дальнейших изменениях программы performance-тесты. Тесты проверяют время выполнения обработки разных объемов данных.