diff options
author | Sean McGivern <sean@mcgivern.me.uk> | 2018-05-29 11:05:10 +0300 |
---|---|---|
committer | Sean McGivern <sean@mcgivern.me.uk> | 2018-05-29 11:05:10 +0300 |
commit | 43ec52ab36069faa060f227fb73d6efeff5b96a5 (patch) | |
tree | dbd608a06c153fb1b72a14a68bc0a61a556f1ccd | |
parent | a75d11211e356e856e563e390fb7470ed5cc3586 (diff) | |
parent | 16e04e006cf8996883ef0c5b7881eb3cbb7079ce (diff) |
Merge branch 'sh-tag-queue-duration-api-calls' into 'master'
Log queue duration for Grape API calls
Closes #46601
See merge request gitlab-org/gitlab-ce!19159
-rw-r--r-- | changelogs/unreleased/sh-tag-queue-duration-api-calls.yml | 5 | ||||
-rw-r--r-- | lib/api/api.rb | 3 | ||||
-rw-r--r-- | lib/gitlab/grape_logging/loggers/queue_duration_logger.rb | 26 | ||||
-rw-r--r-- | spec/lib/gitlab/grape_logging/loggers/queue_duration_logger_spec.rb | 35 |
4 files changed, 68 insertions, 1 deletions
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 |