Add latest changes from gitlab-org/gitlab@master

3 files changed, 56 insertions, 15 deletions

diff --git a/lib/gitlab/instrumentation_helper.rb b/lib/gitlab/instrumentation_helper.rb
index e6a5facb2a5..edaa9c645b4 100644
--- a/lib/gitlab/instrumentation_helper.rb
+++ b/lib/gitlab/instrumentation_helper.rb
@@ -21,5 +21,49 @@ module Gitlab
         payload[:rugged_duration_ms] = Gitlab::RuggedInstrumentation.query_time_ms
       end
     end
+
+    # Returns the queuing duration for a Sidekiq job in seconds, as a float, if the
+    # `enqueued_at` field or `created_at` field is available.
+    #
+    # * If the job doesn't contain sufficient information, returns nil
+    # * If the job has a start time in the future, returns 0
+    # * If the job contains an invalid start time value, returns nil
+    # @param [Hash] job a Sidekiq job, represented as a hash
+    def self.queue_duration_for_job(job)
+      # Old gitlab-shell messages don't provide enqueued_at/created_at attributes
+      enqueued_at = job['enqueued_at'] || job['created_at']
+      return unless enqueued_at
+
+      enqueued_at_time = convert_to_time(enqueued_at)
+      return unless enqueued_at_time
+
+      # Its possible that if theres clock-skew between two nodes
+      # this value may be less than zero. In that event, we record the value
+      # as zero.
+      [elapsed_by_absolute_time(enqueued_at_time), 0].max
+    end
+
+    # Calculates the time in seconds, as a float, from
+    # the provided start time until now
+    #
+    # @param [Time] start
+    def self.elapsed_by_absolute_time(start)
+      (Time.now - start).to_f.round(6)
+    end
+    private_class_method :elapsed_by_absolute_time
+
+    # Convert a representation of a time into a `Time` value
+    #
+    # @param time_value String, Float time representation, or nil
+    def self.convert_to_time(time_value)
+      return time_value if time_value.is_a?(Time)
+      return Time.iso8601(time_value) if time_value.is_a?(String)
+      return Time.at(time_value) if time_value.is_a?(Numeric) && time_value > 0
+    rescue ArgumentError
+      # Swallow invalid dates. Better to loose some observability
+      # than bring all background processing down because of a date
+      # formatting bug in a client
+    end
+    private_class_method :convert_to_time
   end
 end
diff --git a/lib/gitlab/sidekiq_logging/structured_logger.rb b/lib/gitlab/sidekiq_logging/structured_logger.rb
index 853fb2777c3..ca9e3b8428c 100644
--- a/lib/gitlab/sidekiq_logging/structured_logger.rb
+++ b/lib/gitlab/sidekiq_logging/structured_logger.rb
@@ -36,11 +36,8 @@ module Gitlab
         payload['message'] = "#{base_message(payload)}: start"
         payload['job_status'] = 'start'
 
-        # 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_by_absolute_time(Time.iso8601(enqueued_at))
-        end
+        scheduling_latency_s = ::Gitlab::InstrumentationHelper.queue_duration_for_job(payload)
+        payload['scheduling_latency_s'] = scheduling_latency_s if scheduling_latency_s
 
         payload
       end
@@ -98,10 +95,6 @@ module Gitlab
         end
       end
 
-      def elapsed_by_absolute_time(start)
-        (Time.now.utc - start).to_f.round(6)
-      end
-
       def elapsed(t0)
         t1 = get_time
         {
diff --git a/lib/gitlab/sidekiq_middleware/metrics.rb b/lib/gitlab/sidekiq_middleware/metrics.rb
index d45045ca414..bd819843bd4 100644
--- a/lib/gitlab/sidekiq_middleware/metrics.rb
+++ b/lib/gitlab/sidekiq_middleware/metrics.rb
@@ -15,6 +15,9 @@ module Gitlab
 
       def call(_worker, job, queue)
         labels = create_labels(queue)
+        queue_duration = ::Gitlab::InstrumentationHelper.queue_duration_for_job(job)
+
+        @metrics[:sidekiq_jobs_queue_duration_seconds].observe(labels, queue_duration) if queue_duration
         @metrics[:sidekiq_running_jobs].increment(labels, 1)
 
         if job['retry_count'].present?
@@ -49,12 +52,13 @@ module Gitlab
 
       def init_metrics
         {
-          sidekiq_jobs_cpu_seconds:        ::Gitlab::Metrics.histogram(:sidekiq_jobs_cpu_seconds, 'Seconds of cpu time to run sidekiq job', {}, SIDEKIQ_LATENCY_BUCKETS),
-          sidekiq_jobs_completion_seconds: ::Gitlab::Metrics.histogram(:sidekiq_jobs_completion_seconds, 'Seconds to complete sidekiq job', {}, SIDEKIQ_LATENCY_BUCKETS),
-          sidekiq_jobs_failed_total:       ::Gitlab::Metrics.counter(:sidekiq_jobs_failed_total, 'Sidekiq jobs failed'),
-          sidekiq_jobs_retried_total:      ::Gitlab::Metrics.counter(:sidekiq_jobs_retried_total, 'Sidekiq jobs retried'),
-          sidekiq_running_jobs:            ::Gitlab::Metrics.gauge(:sidekiq_running_jobs, 'Number of Sidekiq jobs running', {}, :all),
-          sidekiq_concurrency:             ::Gitlab::Metrics.gauge(:sidekiq_concurrency, 'Maximum number of Sidekiq jobs', {}, :all)
+          sidekiq_jobs_cpu_seconds:            ::Gitlab::Metrics.histogram(:sidekiq_jobs_cpu_seconds, 'Seconds of cpu time to run Sidekiq job', {}, SIDEKIQ_LATENCY_BUCKETS),
+          sidekiq_jobs_completion_seconds:     ::Gitlab::Metrics.histogram(:sidekiq_jobs_completion_seconds, 'Seconds to complete Sidekiq job', {}, SIDEKIQ_LATENCY_BUCKETS),
+          sidekiq_jobs_queue_duration_seconds: ::Gitlab::Metrics.histogram(:sidekiq_jobs_queue_duration_seconds, 'Duration in seconds that a Sidekiq job was queued before being executed', {}, SIDEKIQ_LATENCY_BUCKETS),
+          sidekiq_jobs_failed_total:           ::Gitlab::Metrics.counter(:sidekiq_jobs_failed_total, 'Sidekiq jobs failed'),
+          sidekiq_jobs_retried_total:          ::Gitlab::Metrics.counter(:sidekiq_jobs_retried_total, 'Sidekiq jobs retried'),
+          sidekiq_running_jobs:                ::Gitlab::Metrics.gauge(:sidekiq_running_jobs, 'Number of Sidekiq jobs running', {}, :all),
+          sidekiq_concurrency:                 ::Gitlab::Metrics.gauge(:sidekiq_concurrency, 'Maximum number of Sidekiq jobs', {}, :all)
         }
       end