С 4 часов до 1 минуты. Как найти одну строчку, которая ускорит сервис на Ruby

Как-то раз у нас перестал работать один сервис. Никто давно его не трогал, никто не помнил, кто его написал. Работает — и ладно. Генерировал CSV отчеты для бизнеса в Sidekiq воркере (асинхронно). Проблема стала очевидной то ли от того, что девопсы переехали на Kubernetes, то ли от того, что бизнес просто раньше никогда не генерировал таких больших отчетов. В этот раз сервис должен был «прожевать» 38_000 заявок, но зависал в ‘in_progress’. Возможно, спустя какое-то время процесс просто убивался кубером, возможно, юзеры сами, не дожидаясь результата, отменяли экспорт и запускали по новой.

Спойлером скажу, что проблема оказалась до смешного мелкой. Но мне показалось интересным поделиться, как я нашел решение.

Метрика

Поняв, что на малом объеме данных отчет генерируется без проблем, я решил замерить, с какой скоростью работает сервис. Для этого достаточно применить стандартный Ruby модуль Benchmark. Положим вот такой файлик в папку ‘profilers’:

performance_evaluation.rb

# frozen_string_literal: true  require 'benchmark'  class PerformanceEvaluation   def self.call(applications_ids, export_id)     puts "Start"      time = Benchmark.realtime do       ApplicationsManagement::Export.new(applications_ids, export_id).call     end      puts "Finish in #{time.round(2)}"   end end 

И затем дернем его из консоли:

require './profilers/performance_evaluation'  applications_ids = Application.where(id: (1..100)).pluck(:id) export_id = FactoryBot.create(:export).id PerformanceEvaluation.call(applications_ids, export_id) ... Finish in 40.13 => nil

Сотню заявок наш сервис обсчитывал около 40 секунд. А это значит, на наши 38_000 записей ему потребовалось бы больше 4 часов! Естественно, цифры выглядели просто неприемлемыми.

Профилирование

Чтобы понять, куда двигаться дальше, подключим гем ruby-prof. Он умеет не только профилировать и искать «узкие места», но и печатать отчеты в разных форматах. Для этой задачи я выбрал формат ‘callgrind’, и чтобы его читать нам понадобится утилита qcachegrind. Профайлер положим в ту же папку ‘profilers’:

time_profiler.rb

# frozen_string_literal: true  require 'ruby-prof'  class TimeProfiler   def run(applications_ids, export_id)     RubyProf.measure_mode = RubyProf::WALL_TIME      result = RubyProf.profile do       ApplicationsManagement::Export.new(applications_ids, export_id).call     end      printer = RubyProf::CallTreePrinter.new(result)     printer.print(path: 'profilers/ruby_prof_reports', profile: 'callgrind')   end end 

Как видно выше, отчеты этот профайлер будет складывать в папку ‘profilers/ruby_prof_reports/’. Запускаем его также из консоли:

require_relative 'profilers/time_profiler' applications_ids = Application.pluck(:id).last(100) export_id = FactoryBot.create(:export).id TimeProfiler.new.run(applications_ids, export_id)

Теперь в папке с отчетами появился новый файл callgrind.callgrind.out.10176. Если появилось несколько, нам нужен тот, у которого имя покороче. Открываем его из терминала с помощью утилиты qcachegrind:

qcachegrind profilers/ruby_prof_reports/callgrind.callgrind.out.10176

И видим такое окно:

(Если у вас вид отличается, можете кликнуть Settings -> Sidebars -> Flat Profile). Здесь Я отсортировал данные по колонке self — что значит, сколько времени процесс потратил на свое выполнение. (Колонка Incl. Показывает — сколько времени он потратил на выполнение себя самого и дочерних процессов). Если кликнем по иконке % в верхнем меню, то увидим, что IO::wait_readable занимает больше 90% выполнения.

Доки Ruby не очень многословны о модуле IO::WaitReadable:
‘exception to wait for reading. see IO.select.’
Но в целом, что тут еще говорить — ожидание input/output. Вопрос в том, что это ожидание вызывает?

Проверка гипотез

Первой моей гипотезой было — ожидание записи в CSV файл. Я решил ее проверить, и прогнать через профилировщик не весь сервис, а лишь этот его метод. Профилировщик в этот раз получился таким:

time_profiler.rb

# frozen_string_literal: true  require 'ruby-prof'  class TimeProfiler   attr_reader :applications_ids, :file_path, :errors    def initialize(applications_ids)     @applications_ids = applications_ids     @file_path = Tempfile.new(['', '.csv']).to_path     @errors = []   end    def run     RubyProf.measure_mode = RubyProf::WALL_TIME     result = RubyProf.profile do       to_csv_export     end      printer = RubyProf::CallTreePrinter.new(result)     printer.print(path: 'profilers/ruby_prof_reports', profile: 'callgrind')   end    private    def to_csv_export     CSV.open(file_path, 'w') do |csv|       csv << export_headers # массив заголовков отчета почти на 90 элементов        # ActiveRecord::Relation с экспортируемыми заявками       export_collection.find_each do |instance|         begin           # В оригинальном сервисе здесь вызывается           # export_row(instance.decorate) -           # метод, который формировал каждую строку отчета.           # Заменим его на простую выборку атрибутов модели,           # чтобы минимизировать работу, и проверить,           # вызывается ли наш IO::WaitReadable самим процессом записи в CSV           # или вызовом тех самых методов модели для отрисовки отчета            csv << instance.attributes.values         rescue StandardError => e           errors << "#{instance.id}: #{e}"         end       end     end   end    def export_headers # rubocop:disable Metrics/MethodLength     [       'ID',       'Status',       ... # Еще почти 90 заголовков     ]   end    def export_collection     Application.where(id: applications_ids).includes(       ... # увесистый список связанных моделей, опустим для краткости     ).order(created_at: :desc)   end end

Новый отчет callgrind вообще не содержал вызова этого модуля.

Попробуем углубиться, и «прощупать» сам метод формирования строки export_row.

time_profiler.rb

# frozen_string_literal: true  require 'ruby-prof'  class TimeProfiler   def run     RubyProf.measure_mode = RubyProf::WALL_TIME     app = Application.last     result = RubyProf.profile do       export_row(app.decorate)     end     printer = RubyProf::CallTreePrinter.new(result)     printer.print(path: 'profilers/ruby_prof_reports', profile: 'callgrind')   end    private    # Data for writing for each application   def export_row(application) # rubocop:disable Metrics/MethodLength, Metrics/AbcSize, Metrics/PerceivedComplexity, Metrics/CyclomaticComplexity, Metrics/LineLength     [       application.id,       application.status,       ... # Еще около 90 строк      ]   end end

А вот и наш модуль. И опять занимает гигантские 80% времени даже при всего одной записи.

Дальше можно по принципу бинарного поиска закомментировать половину вызываемых методов, и проверить, вызывается ли «долгий» модуль или нет. Если нет — проблема в закомментированных строках. Делим их пополам опять и т.д… Довольно быстро я нашел строку, которая вызывала этот модуль:

... application.photo_urls.present? ? 'Yes' : 'No', ...

Смотрим в модель Application, что же это за метод такой?

models/application.rb

# frozen_string_literal: true  class Application   ...   def photo_urls     return if Rails.env.test?      s3 = Aws::S3::Resource.new     bucket = s3.bucket('bucket-name')     return [] if guid.nil?      bucket.objects(prefix: "documents/#{guid}")           .reject { |x| x.key.include?('/preview/') }           .map { |o| o.presigned_url(:get) }   end end

Иными словами, чтобы написать в отчете ‘yes’ или ‘no’ мы лезли в AWS, и смотрели, есть ли у нас в определенной папочке какие-нибудь фотографии. Заголовок этого столбца в отчете гласил KYC. То есть менеджеры ожидали видеть, прошел ли заявитель процедуру KYC (know-your-customer, кто работает в Fintech, наверняка знает) или еще нет. Я начал спрашивать бизнес, может, выберем другой способ этот признак определить? Например, можно сохранять этот флаг в бд при загрузке фотографий. Выяснилось, что им вообще этот столбец в отчете не нужен.

Я выпилил эту строчку и снова обратился к нашей метрике. PerformanceEvaluation показал всего лишь 3 секунды на обработке той же сотни заявок. На больших объемах разница была еще разительней. Отчет, который до этого не могли сгенерировать за 4+ часа, теперь пишется чуть дольше, чем за одну минуту. Виной всему одна строчка, которая вообще-то никому не была нужна.

P.S./Bonus

На самом деле, найти эту проблему можно было и быстрей. Без разбивания сервиса на части и прогона их через профилировщик. Опытные фанаты Qcachegrind наверное заметили, что я не углублялся в его интерфейс, и в целом я далеко не спец по нему. Наверняка его можно использовать и с бОльшим КПД. Например, если кликнуть по любому процессу, а в правой нижней части окна выбрать режим «Call Graph», можно увидеть дерево вызовов — какой модуль каким модулем был вызван.

Дважды кликаем по любому родителю, и дерево «растет» дальше:

Думаю, модуль Net/HTTPResponse мог на правильную догадку подтолкнуть быстрей, и статья закончилась бы раньше. Но мне хотелось показать пример воркфлоу, который легко можно применить на любых проектах. Если кто-то хорошо знает Qcachegrind (да и ruby-prof) или другие полезные инструменты, поделитесь в комментах, как вы их используете и какие полезные фичи можете порекомендовать?