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 {