Merge branch 'update-merge-worker-metrics' into 'master'

Add simple logging to UpdateMergeRequestsWorker#perform

See merge request gitlab-org/gitlab-ce!15360

app/workers/update_merge_requests_worker.rb

@@ -2,6 +2,8 @@ class UpdateMergeRequestsWorker
   include Sidekiq::Worker
   include DedicatedSidekiqQueue
 
+  LOG_TIME_THRESHOLD = 90 # seconds
+
   def perform(project_id, user_id, oldrev, newrev, ref)
     project = Project.find_by(id: project_id)
     return unless project
@@ -9,6 +11,20 @@ class UpdateMergeRequestsWorker
     user = User.find_by(id: user_id)
     return unless user
 
-    MergeRequests::RefreshService.new(project, user).execute(oldrev, newrev, ref)
+    # TODO: remove this benchmarking when we have rich logging
+    time = Benchmark.measure do
+      MergeRequests::RefreshService.new(project, user).execute(oldrev, newrev, ref)
+    end
+
+    args_log = [
+      "elapsed=#{time.real}",
+      "project_id=#{project_id}",
+      "user_id=#{user_id}",
+      "oldrev=#{oldrev}",
+      "newrev=#{newrev}",
+      "ref=#{ref}"
+    ].join(',')
+
+    Rails.logger.info("UpdateMergeRequestsWorker#perform #{args_log}") if time.real > LOG_TIME_THRESHOLD
   end
 end

changelogs/unreleased/update-merge-worker-metrics.yml

+---
+title: Add performance logging to UpdateMergeRequestsWorker.
+merge_request: 15360
+author:
+type: performance

spec/workers/update_merge_requests_worker_spec.rb

@@ -23,5 +23,17 @@ describe UpdateMergeRequestsWorker do
 
       perform
     end
+
+    context 'when slow' do
+      before do
+        stub_const("UpdateMergeRequestsWorker::LOG_TIME_THRESHOLD", -1)
+      end
+
+      it 'logs debug info' do
+        expect(Rails.logger).to receive(:info).with(a_string_matching(/\AUpdateMergeRequestsWorker#perform.*project_id=#{project.id},user_id=#{user.id},oldrev=#{oldrev},newrev=#{newrev},ref=#{ref}/))
+
+        perform
+      end
+    end
   end
 end