rework the logging to be simpler and add a threshold

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
@@ -14,12 +16,16 @@ class UpdateMergeRequestsWorker
       MergeRequests::RefreshService.new(project, user).execute(oldrev, newrev, ref)
     end
 
-    log_args = ["elapsed=#{time.real}"]
+    args_log = [
-    method(__method__).parameters.map do |_, p|
+      "elapsed=#{time.real}",
-      pname = p.to_s
+      "project_id=#{project_id}",
-      log_args << [pname, binding.local_variable_get(pname)].join('=')
+      "user_id=#{user_id}",
-    end
+      "oldrev=#{oldrev}",
+      "newrev=#{newrev}",
+      "ref=#{ref}"
+    ].join(',')
 
-    Rails.logger.info("UpdateMergeRequestsWorker#perform #{log_args.join(',')}")
+    Rails.logger.info("UpdateMergeRequestsWorker#perform #{args_log}") if time.real > LOG_TIME_THRESHOLD
   end
+
 end

spec/workers/update_merge_requests_worker_spec.rb

@@ -24,10 +24,16 @@ describe UpdateMergeRequestsWorker do
       perform
     end
 
-    it 'logs performance' do
+    context 'when slow' 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}/))
+      before do
+        stub_const("UpdateMergeRequestsWorker::LOG_TIME_THRESHOLD", -1)
+      end
 
-      perform
+      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