From bae6385bda13f1db0083ef834aedcc89424e0130 Mon Sep 17 00:00:00 2001 From: "micael.bergeron" Date: Mon, 13 Nov 2017 14:56:08 -0500 Subject: add simple logging to UpdateMergeRequestsWorker#perform this is to try to debug #35914 --- app/workers/update_merge_requests_worker.rb | 13 ++++++++++++- spec/workers/update_merge_requests_worker_spec.rb | 6 ++++++ 2 files changed, 18 insertions(+), 1 deletion(-) diff --git a/app/workers/update_merge_requests_worker.rb b/app/workers/update_merge_requests_worker.rb index 89ae17cef37..d8d818aee8e 100644 --- a/app/workers/update_merge_requests_worker.rb +++ b/app/workers/update_merge_requests_worker.rb @@ -9,6 +9,17 @@ 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 + + log_args = ["elapsed=#{time.real}"] + method(__method__).parameters.map do |_, p| + pname = p.to_s + log_args << [pname, binding.local_variable_get(pname)].join('=') + end + + Rails.logger.info("UpdateMergeRequestsWorker#perform #{log_args.join(',')}") end end diff --git a/spec/workers/update_merge_requests_worker_spec.rb b/spec/workers/update_merge_requests_worker_spec.rb index 558ff9109ec..5c711399cd5 100644 --- a/spec/workers/update_merge_requests_worker_spec.rb +++ b/spec/workers/update_merge_requests_worker_spec.rb @@ -23,5 +23,11 @@ describe UpdateMergeRequestsWorker do perform end + + it 'logs performance' 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 -- cgit v1.2.1 From a579bc59b04834eed656e2d8bcf672026d2829ce Mon Sep 17 00:00:00 2001 From: GitLab Development Date: Mon, 13 Nov 2017 20:10:55 +0000 Subject: [ci-skip] add changelog --- changelogs/unreleased/update-merge-worker-metrics.yml | 5 +++++ 1 file changed, 5 insertions(+) create mode 100644 changelogs/unreleased/update-merge-worker-metrics.yml diff --git a/changelogs/unreleased/update-merge-worker-metrics.yml b/changelogs/unreleased/update-merge-worker-metrics.yml new file mode 100644 index 00000000000..c733675926a --- /dev/null +++ b/changelogs/unreleased/update-merge-worker-metrics.yml @@ -0,0 +1,5 @@ +--- +title: Add performance logging to UpdateMergeRequestsWorker. +merge_request: 15360 +author: +type: performance -- cgit v1.2.1 From 0b4a7d656b224c145072946f06539fcff40cc8ca Mon Sep 17 00:00:00 2001 From: "micael.bergeron" Date: Tue, 14 Nov 2017 09:22:15 -0500 Subject: rework the logging to be simpler and add a threshold --- app/workers/update_merge_requests_worker.rb | 18 ++++++++++++------ spec/workers/update_merge_requests_worker_spec.rb | 12 +++++++++--- 2 files changed, 21 insertions(+), 9 deletions(-) diff --git a/app/workers/update_merge_requests_worker.rb b/app/workers/update_merge_requests_worker.rb index d8d818aee8e..ab831858676 100644 --- a/app/workers/update_merge_requests_worker.rb +++ b/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}"] - method(__method__).parameters.map do |_, p| - pname = p.to_s - log_args << [pname, binding.local_variable_get(pname)].join('=') - 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 #{log_args.join(',')}") + Rails.logger.info("UpdateMergeRequestsWorker#perform #{args_log}") if time.real > LOG_TIME_THRESHOLD end + end diff --git a/spec/workers/update_merge_requests_worker_spec.rb b/spec/workers/update_merge_requests_worker_spec.rb index 5c711399cd5..0fa19ac84bb 100644 --- a/spec/workers/update_merge_requests_worker_spec.rb +++ b/spec/workers/update_merge_requests_worker_spec.rb @@ -24,10 +24,16 @@ describe UpdateMergeRequestsWorker do perform end - it 'logs performance' 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}/)) + context 'when slow' do + 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 -- cgit v1.2.1 From 45c373caf570cee7ef3b51d0709c01cc3df3a818 Mon Sep 17 00:00:00 2001 From: Micael Bergeron Date: Tue, 14 Nov 2017 18:12:52 +0000 Subject: [ci-skip] linting --- app/workers/update_merge_requests_worker.rb | 1 - 1 file changed, 1 deletion(-) diff --git a/app/workers/update_merge_requests_worker.rb b/app/workers/update_merge_requests_worker.rb index ab831858676..afc47fc63d6 100644 --- a/app/workers/update_merge_requests_worker.rb +++ b/app/workers/update_merge_requests_worker.rb @@ -27,5 +27,4 @@ class UpdateMergeRequestsWorker Rails.logger.info("UpdateMergeRequestsWorker#perform #{args_log}") if time.real > LOG_TIME_THRESHOLD end - end -- cgit v1.2.1