diff options
author | GitLab Bot <gitlab-bot@gitlab.com> | 2019-10-28 18:05:58 +0300 |
---|---|---|
committer | GitLab Bot <gitlab-bot@gitlab.com> | 2019-10-28 18:05:58 +0300 |
commit | a77db6bc47d8cdd9edae2ec22f640821d0794404 (patch) | |
tree | 15861a5f1ec29e07c2012102e463402bb7dc8c2d /lib | |
parent | 6cf6996f183bdff46e73431c07bfb723066a8222 (diff) |
Add latest changes from gitlab-org/gitlab@master
Diffstat (limited to 'lib')
-rw-r--r-- | lib/gitlab/instrumentation_helper.rb | 44 | ||||
-rw-r--r-- | lib/gitlab/sidekiq_logging/structured_logger.rb | 11 | ||||
-rw-r--r-- | lib/gitlab/sidekiq_middleware/metrics.rb | 16 |
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 |