API-26059 Log durations of some sidekiq jobs (#12474)

* API-26059 Adds generic way to opt a job into benchmark logging

config/initializers/sidekiq.rb

@@ -7,6 +7,7 @@
 require 'sidekiq/semantic_logging'
 require 'sidekiq/set_request_id'
 require 'sidekiq/set_request_attributes'
+require 'sidekiq/middleware/benchmark_logging_middleware'
 require 'datadog/statsd' # gem 'dogstatsd-ruby'
 
 Rails.application.reloader.to_prepare do
@@ -31,6 +32,7 @@
       chain.add SidekiqStatsInstrumentation::ServerMiddleware
       chain.add Sidekiq::RetryMonitoring
       chain.add Sidekiq::ErrorTag
+      chain.add Sidekiq::Middleware::BenchmarkLoggingMiddleware
 
       if Settings.dogstatsd.enabled == true
         require 'sidekiq/middleware/server/statsd'

lib/sidekiq/benchmark_logging_worker.rb

@@ -0,0 +1,10 @@
+# frozen_string_literal: true
+
+require 'benchmark'
+
+module Sidekiq
+  module BenchmarkLoggingWorker
+    # This module serves to mark workers which should log benchmarking information.
+    # Actual logging takes place in Sidekiq::Middleware::BenchmarkLoggingMiddleware.
+  end
+end

lib/sidekiq/middleware/benchmark_logging_middleware.rb

@@ -0,0 +1,18 @@
+# frozen_string_literal: true
+
+require 'benchmark'
+
+module Sidekiq::Middleware
+  class BenchmarkLoggingMiddleware
+    # include Sidekiq::BenchmarkLoggingWorker in your sidekiq job to apply this middleware to it
+    def call(worker, _job, _queue, &block)
+      if worker.is_a?(Sidekiq::BenchmarkLoggingWorker)
+        m = Benchmark.measure(&block)
+        data = { real: m.real.round, system: m.stime.round, total: m.total.round, user: m.utime.round }
+        Rails.logger.info "Sidekiq job #{worker.class.name} benchmark: #{data.to_json}"
+      else
+        block.call
+      end
+    end
+  end
+end

modules/appeals_api/app/workers/appeals_api/flipper_status_alert.rb

@@ -1,11 +1,13 @@
 # frozen_string_literal: true
 
 require 'sidekiq'
+require 'sidekiq/benchmark_logging_worker'
 require 'flipper/utilities/bulk_feature_checker'
 
 module AppealsApi
   class FlipperStatusAlert
     include Sidekiq::Worker
+    include Sidekiq::BenchmarkLoggingWorker
 
     WARNING_EMOJI = ':warning:'
     DISABLED_FLAG_EMOJI = ':vertical_traffic_light:'

modules/va_forms/app/workers/va_forms/flipper_status_alert.rb

@@ -1,11 +1,13 @@
 # frozen_string_literal: true
 
 require 'sidekiq'
+require 'sidekiq/benchmark_logging_worker'
 require 'flipper/utilities/bulk_feature_checker'
 
 module VAForms
   class FlipperStatusAlert
     include Sidekiq::Worker
+    include Sidekiq::BenchmarkLoggingWorker
 
     WARNING_EMOJI = ':warning:'
     DISABLED_FLAG_EMOJI = ':vertical_traffic_light:'

modules/vba_documents/app/workers/vba_documents/flipper_status_alert.rb

@@ -1,11 +1,13 @@
 # frozen_string_literal: true
 
 require 'sidekiq'
+require 'sidekiq/benchmark_logging_worker'
 require 'flipper/utilities/bulk_feature_checker'
 
 module VBADocuments
   class FlipperStatusAlert
     include Sidekiq::Worker
+    include Sidekiq::BenchmarkLoggingWorker
 
     WARNING_EMOJI = ':warning:'
     DISABLED_FLAG_EMOJI = ':vertical_traffic_light:'

spec/lib/sidekiq/middleware/benchmark_logging_middleware_spec.rb

@@ -0,0 +1,46 @@
+# frozen_string_literal: true
+
+require 'rails_helper'
+require 'sidekiq/benchmark_logging_worker'
+require 'sidekiq/middleware/benchmark_logging_middleware'
+
+class NormalTestWorker
+  include Sidekiq::Worker
+
+  def perform; end
+end
+
+class BenchmarkLoggingTestWorker < NormalTestWorker
+  include Sidekiq::BenchmarkLoggingWorker
+end
+
+RSpec.describe Sidekiq::Middleware::BenchmarkLoggingMiddleware do
+  let(:worker) { NormalTestWorker.new }
+  let(:job) { {} }
+  let(:queue) { 'default' }
+  let(:middleware) { described_class.new }
+
+  describe '#call' do
+    context 'when the job does not include the benchmark logging module' do
+      it 'does not log benchmark data' do
+        expect(Rails.logger).not_to receive(:info)
+
+        middleware.call(worker, job, queue) {}
+      end
+    end
+
+    context 'when the job includes the benchmark logging module' do
+      let(:worker) { BenchmarkLoggingTestWorker.new }
+      let(:flag_name) { :sidekiq_benchmark_logging }
+
+      it 'logs benchmark data' do
+        expect(Rails.logger).to receive(:info) do |message|
+          expect(message)
+            .to eq('Sidekiq job BenchmarkLoggingTestWorker benchmark: {"real":0,"system":0,"total":0,"user":0}')
+        end
+
+        middleware.call(worker, job, queue) {}
+      end
+    end
+  end
+end