diff --git a/changelogs/unreleased/sh-tag-queue-duration-api-calls.yml b/changelogs/unreleased/sh-tag-queue-duration-api-calls.yml new file mode 100644 index 00000000000..686cceaab62 --- /dev/null +++ b/changelogs/unreleased/sh-tag-queue-duration-api-calls.yml @@ -0,0 +1,5 @@ +--- +title: Log Workhorse queue duration for Grape API calls +merge_request: +author: +type: other diff --git a/lib/api/api.rb b/lib/api/api.rb index de20b2b8e67..206fabe5c43 100644 --- a/lib/api/api.rb +++ b/lib/api/api.rb @@ -15,7 +15,8 @@ module API include: [ GrapeLogging::Loggers::FilterParameters.new, GrapeLogging::Loggers::ClientEnv.new, - Gitlab::GrapeLogging::Loggers::UserLogger.new + Gitlab::GrapeLogging::Loggers::UserLogger.new, + Gitlab::GrapeLogging::Loggers::QueueDurationLogger.new ] allow_access_with_scope :api diff --git a/lib/gitlab/grape_logging/loggers/queue_duration_logger.rb b/lib/gitlab/grape_logging/loggers/queue_duration_logger.rb new file mode 100644 index 00000000000..0adac79f25a --- /dev/null +++ b/lib/gitlab/grape_logging/loggers/queue_duration_logger.rb @@ -0,0 +1,26 @@ +# This grape_logging module (https://github.com/aserafin/grape_logging) makes it +# possible to log how much time an API request was queued by Workhorse. +module Gitlab + module GrapeLogging + module Loggers + class QueueDurationLogger < ::GrapeLogging::Loggers::Base + attr_accessor :start_time + + def before + @start_time = Time.now + end + + def parameters(request, _) + proxy_start = request.env['HTTP_GITLAB_WORKHORSE_PROXY_START'].presence + + return {} unless proxy_start && start_time + + # Time in milliseconds since gitlab-workhorse started the request + duration = (start_time.to_f * 1_000 - proxy_start.to_f / 1_000_000).round(2) + + { 'queue_duration': duration } + end + end + end + end +end diff --git a/spec/lib/gitlab/grape_logging/loggers/queue_duration_logger_spec.rb b/spec/lib/gitlab/grape_logging/loggers/queue_duration_logger_spec.rb new file mode 100644 index 00000000000..f47b9dd3498 --- /dev/null +++ b/spec/lib/gitlab/grape_logging/loggers/queue_duration_logger_spec.rb @@ -0,0 +1,35 @@ +require 'spec_helper' + +describe Gitlab::GrapeLogging::Loggers::QueueDurationLogger do + subject { described_class.new } + + describe ".parameters" do + let(:start_time) { Time.new(2018, 01, 01) } + + describe 'when no proxy time is available' do + let(:mock_request) { OpenStruct.new(env: {}) } + + it 'returns an empty hash' do + expect(subject.parameters(mock_request, nil)).to eq({}) + end + end + + describe 'when a proxy time is available' do + let(:mock_request) do + OpenStruct.new( + env: { + 'HTTP_GITLAB_WORKHORSE_PROXY_START' => (start_time - 1.hour).to_i * (10**9) + } + ) + end + + it 'returns the correct duration in ms' do + Timecop.freeze(start_time) do + subject.before + + expect(subject.parameters(mock_request, nil)).to eq( { 'queue_duration': 1.hour.to_f * 1000 }) + end + end + end + end +end