Fix Sidekiq scheduling_latency_ssh-fix-sidekiq-scheduling-latency

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

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
       {