From 7ccbb562b161881cffea77b228c2c3d062fcc864 Mon Sep 17 00:00:00 2001 From: Stan Hu Date: Thu, 8 Aug 2019 20:51:40 -0700 Subject: [PATCH] Fix Sidekiq scheduling_latency_s This number was reporting a negative number because `current_time` was a monotonic counter, not an absolute time. Closes https://gitlab.com/gitlab-org/gitlab-ce/issues/65748 --- lib/gitlab/sidekiq_logging/structured_logger.rb | 6 +++++- spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb | 4 ++-- 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/lib/gitlab/sidekiq_logging/structured_logger.rb b/lib/gitlab/sidekiq_logging/structured_logger.rb index d556d5ef129..3ebc71dcc8b 100644 --- a/lib/gitlab/sidekiq_logging/structured_logger.rb +++ b/lib/gitlab/sidekiq_logging/structured_logger.rb @@ -35,7 +35,7 @@ module Gitlab # Old gitlab-shell messages don't provide enqueued_at/created_at attributes enqueued_at = payload['enqueued_at'] || payload['created_at'] if enqueued_at - payload['scheduling_latency_s'] = elapsed(Time.iso8601(enqueued_at).to_f) + payload['scheduling_latency_s'] = elapsed_by_absolute_time(Time.iso8601(enqueued_at)) end payload @@ -84,6 +84,10 @@ module Gitlab end end + def elapsed_by_absolute_time(start) + (Time.now.utc - start).to_f.round(3) + end + def elapsed(start) (current_time - start).round(3) end diff --git a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb index 98286eb432d..bf26335ef7f 100644 --- a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb +++ b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb @@ -3,8 +3,8 @@ require 'spec_helper' describe Gitlab::SidekiqLogging::StructuredLogger do describe '#call' do let(:timestamp) { Time.iso8601('2018-01-01T12:00:00Z') } - let(:created_at) { timestamp } - let(:scheduling_latency_s) { 0.0 } + let(:created_at) { timestamp - 1.second } + let(:scheduling_latency_s) { 1.0 } let(:job) do {