diff --git a/app/assets/javascripts/performance_bar/components/performance_bar_app.vue b/app/assets/javascripts/performance_bar/components/performance_bar_app.vue
index c827fd234a1255ecff566603c9b4942369318c38..04e9d13fa563ca5352136aaf108c23ccbf34240e 100644
--- a/app/assets/javascripts/performance_bar/components/performance_bar_app.vue
+++ b/app/assets/javascripts/performance_bar/components/performance_bar_app.vue
@@ -63,6 +63,11 @@ export default {
header: s__('PerformanceBar|Elasticsearch calls'),
keys: ['request', 'body'],
},
+ {
+ metric: 'external-http',
+ header: s__('PerformanceBar|External Http calls'),
+ keys: ['label', 'code', 'proxy', 'error'],
+ },
{
metric: 'total',
header: s__('PerformanceBar|Frontend resources'),
diff --git a/changelogs/unreleased/302-improve-visibility-of-time-spent-with-external-io.yml b/changelogs/unreleased/302-improve-visibility-of-time-spent-with-external-io.yml
new file mode 100644
index 0000000000000000000000000000000000000000..dfe39e01723e34d1a6d8b819483c14925f62dcf2
--- /dev/null
+++ b/changelogs/unreleased/302-improve-visibility-of-time-spent-with-external-io.yml
@@ -0,0 +1,5 @@
+---
+title: Improve visibility of time spent with external HTTP calls
+merge_request: 50696
+author:
+type: added
diff --git a/config/initializers/peek.rb b/config/initializers/peek.rb
index fa74d8620f4812dd46d1dbb8485eed3af73a1f57..7027ba69e13bebf12986de90d564f87ba9aae8d3 100644
--- a/config/initializers/peek.rb
+++ b/config/initializers/peek.rb
@@ -11,6 +11,7 @@
Peek.into Peek::Views::RedisDetailed
Peek.into Peek::Views::Elasticsearch
Peek.into Peek::Views::Rugged
+Peek.into Peek::Views::ExternalHttp
Peek.into Peek::Views::BulletDetailed if defined?(Bullet)
Peek.into Peek::Views::Tracing if Labkit::Tracing.tracing_url_enabled?
diff --git a/config/initializers/tracing.rb b/config/initializers/tracing.rb
index 3058bdeb84e405bcca7b784bd623f0ebff105466..3f066953c235348cc2265a77417ccbd4cc797e5d 100644
--- a/config/initializers/tracing.rb
+++ b/config/initializers/tracing.rb
@@ -8,6 +8,7 @@
# Instrument Redis
Labkit::Tracing::Redis.instrument
+ Labkit::Tracing::ExternalHttp.instrument
# Instrument Rails
Labkit::Tracing::Rails::ActiveRecordSubscriber.instrument
diff --git a/config/initializers/zz_metrics.rb b/config/initializers/zz_metrics.rb
index 430e4d60d611d1616eaaf7832611671b443d55f0..d1150704416e819310b3c433df734a3e85ec1c01 100644
--- a/config/initializers/zz_metrics.rb
+++ b/config/initializers/zz_metrics.rb
@@ -202,4 +202,8 @@ def connect(*args)
class ::Redis::Client
prepend TrackNewRedisConnections
end
+
+ Labkit::NetHttpPublisher.labkit_prepend!
+ Labkit::ExconPublisher.labkit_prepend!
+ Labkit::HTTPClientPublisher.labkit_prepend!
end
diff --git a/doc/administration/monitoring/performance/img/performance_bar_external_http_calls.png b/doc/administration/monitoring/performance/img/performance_bar_external_http_calls.png
new file mode 100644
index 0000000000000000000000000000000000000000..45f2b0956e9857d3d989458534797c7359b167c3
Binary files /dev/null and b/doc/administration/monitoring/performance/img/performance_bar_external_http_calls.png differ
diff --git a/doc/administration/monitoring/performance/performance_bar.md b/doc/administration/monitoring/performance/performance_bar.md
index 107c1e9e14f51e725f548e4591e38a621753b76b..8c1bc801b22bec3d438118c618fcc03582c65ac7 100644
--- a/doc/administration/monitoring/performance/performance_bar.md
+++ b/doc/administration/monitoring/performance/performance_bar.md
@@ -31,6 +31,10 @@ From left to right, it displays:
- **Elasticsearch calls**: the time taken (in milliseconds) and the total number of
Elasticsearch calls. Click to display a modal window with more details.
+- **External HTTP calls**: the time taken (in milliseconds) and the total
+ number of external calls to other systems. Click to display a modal window
+ with more details
+ 
- **Load timings** of the page: if your browser supports load timings (Chromium
and Chrome) several values in milliseconds, separated by slashes.
Click to display a modal window with more details. The values, from left to right:
diff --git a/doc/administration/monitoring/prometheus/gitlab_metrics.md b/doc/administration/monitoring/prometheus/gitlab_metrics.md
index 08c929419f70d1645f6ea3bdc90395b3c66567ed..105c0a408ce96aceb9bc4620151c311507912983 100644
--- a/doc/administration/monitoring/prometheus/gitlab_metrics.md
+++ b/doc/administration/monitoring/prometheus/gitlab_metrics.md
@@ -114,6 +114,9 @@ The following metrics are available:
| `action_cable_pool_tasks_total` | Gauge | 13.4 | Total number of tasks executed in ActionCable thread pool | `server_mode` |
| `gitlab_issuable_fast_count_by_state_total` | Counter | 13.5 | Total number of row count operations on issue/merge request list pages | |
| `gitlab_issuable_fast_count_by_state_failures_total` | Counter | 13.5 | Number of soft-failed row count operations on issue/merge request list pages | |
+| `gitlab_external_http_total` | Counter | 13.8 | Total number of HTTP calls to external systems | `controller`, `action` |
+| `gitlab_external_http_duration_seconds` | Counter | 13.8 | Duration in seconds spent on each HTTP call to external systems | |
+| `gitlab_external_http_exception_total` | Counter | 13.8 | Total number of exceptions raised when making external HTTP calls | |
## Metrics controlled by a feature flag
diff --git a/lib/gitlab/instrumentation_helper.rb b/lib/gitlab/instrumentation_helper.rb
index 6b0f01757b786c7d2322571f2b330984a14fe317..b7dd9b0dc7321317c7c33a2fc1780c2892571d86 100644
--- a/lib/gitlab/instrumentation_helper.rb
+++ b/lib/gitlab/instrumentation_helper.rb
@@ -14,7 +14,8 @@ def keys
:elasticsearch_calls,
:elasticsearch_duration_s,
*::Gitlab::Instrumentation::Redis.known_payload_keys,
- *::Gitlab::Metrics::Subscribers::ActiveRecord::DB_COUNTERS]
+ *::Gitlab::Metrics::Subscribers::ActiveRecord::DB_COUNTERS,
+ *::Gitlab::Metrics::Subscribers::ExternalHttp::KNOWN_PAYLOAD_KEYS]
end
def add_instrumentation_data(payload)
@@ -24,6 +25,7 @@ def add_instrumentation_data(payload)
instrument_elasticsearch(payload)
instrument_throttle(payload)
instrument_active_record(payload)
+ instrument_external_http(payload)
end
def instrument_gitaly(payload)
@@ -59,6 +61,14 @@ def instrument_elasticsearch(payload)
payload[:elasticsearch_duration_s] = Gitlab::Instrumentation::ElasticsearchTransport.query_time
end
+ def instrument_external_http(payload)
+ external_http_count = Gitlab::Metrics::Subscribers::ExternalHttp.request_count
+
+ return if external_http_count == 0
+
+ payload.merge! Gitlab::Metrics::Subscribers::ExternalHttp.payload
+ end
+
def instrument_throttle(payload)
safelist = Gitlab::Instrumentation::Throttle.safelist
payload[:throttle_safelist] = safelist if safelist.present?
diff --git a/lib/gitlab/metrics/subscribers/external_http.rb b/lib/gitlab/metrics/subscribers/external_http.rb
new file mode 100644
index 0000000000000000000000000000000000000000..94c5d965200050bae18713b1bf22a05492b95ec1
--- /dev/null
+++ b/lib/gitlab/metrics/subscribers/external_http.rb
@@ -0,0 +1,99 @@
+# frozen_string_literal: true
+
+module Gitlab
+ module Metrics
+ module Subscribers
+ # Class for tracking the total time spent in external HTTP
+ # See more at https://gitlab.com/gitlab-org/labkit-ruby/-/blob/v0.14.0/lib/gitlab-labkit.rb#L18
+ class ExternalHttp < ActiveSupport::Subscriber
+ attach_to :external_http
+
+ DEFAULT_STATUS_CODE = 'undefined'
+
+ DETAIL_STORE = :external_http_detail_store
+ COUNTER = :external_http_count
+ DURATION = :external_http_duration_s
+
+ KNOWN_PAYLOAD_KEYS = [COUNTER, DURATION].freeze
+
+ def self.detail_store
+ ::Gitlab::SafeRequestStore[DETAIL_STORE] ||= []
+ end
+
+ def self.duration
+ Gitlab::SafeRequestStore[DURATION].to_f
+ end
+
+ def self.request_count
+ Gitlab::SafeRequestStore[COUNTER].to_i
+ end
+
+ def self.payload
+ {
+ COUNTER => request_count,
+ DURATION => duration
+ }
+ end
+
+ def request(event)
+ payload = event.payload
+ add_to_detail_store(payload)
+ add_to_request_store(payload)
+ expose_metrics(payload)
+ end
+
+ private
+
+ def current_transaction
+ ::Gitlab::Metrics::Transaction.current
+ end
+
+ def add_to_detail_store(payload)
+ return unless Gitlab::PerformanceBar.enabled_for_request?
+
+ self.class.detail_store << {
+ duration: payload[:duration],
+ scheme: payload[:scheme],
+ method: payload[:method],
+ host: payload[:host],
+ port: payload[:port],
+ path: payload[:path],
+ query: payload[:query],
+ code: payload[:code],
+ exception_object: payload[:exception_object],
+ backtrace: Gitlab::BacktraceCleaner.clean_backtrace(caller)
+ }
+ end
+
+ def add_to_request_store(payload)
+ return unless Gitlab::SafeRequestStore.active?
+
+ Gitlab::SafeRequestStore[COUNTER] = Gitlab::SafeRequestStore[COUNTER].to_i + 1
+ Gitlab::SafeRequestStore[DURATION] = Gitlab::SafeRequestStore[DURATION].to_f + payload[:duration].to_f
+ end
+
+ def expose_metrics(payload)
+ return unless current_transaction
+
+ labels = { method: payload[:method], code: payload[:code] || DEFAULT_STATUS_CODE }
+
+ current_transaction.increment(:gitlab_external_http_total, 1, labels) do
+ docstring 'External HTTP calls'
+ label_keys labels.keys
+ end
+
+ current_transaction.observe(:gitlab_external_http_duration_seconds, payload[:duration]) do
+ docstring 'External HTTP time'
+ buckets [0.001, 0.01, 0.1, 1.0, 2.0, 5.0]
+ end
+
+ if payload[:exception_object].present?
+ current_transaction.increment(:gitlab_external_http_exception_total, 1) do
+ docstring 'External HTTP exceptions'
+ end
+ end
+ end
+ end
+ end
+ end
+end
diff --git a/lib/peek/views/external_http.rb b/lib/peek/views/external_http.rb
new file mode 100644
index 0000000000000000000000000000000000000000..7a42fceebc1f98acc07a345d916a3387f4d63707
--- /dev/null
+++ b/lib/peek/views/external_http.rb
@@ -0,0 +1,87 @@
+# frozen_string_literal: true
+
+module Peek
+ module Views
+ class ExternalHttp < DetailedView
+ DEFAULT_THRESHOLDS = {
+ calls: 10,
+ duration: 1000,
+ individual_call: 100
+ }.freeze
+
+ THRESHOLDS = {
+ production: {
+ calls: 10,
+ duration: 1000,
+ individual_call: 100
+ }
+ }.freeze
+
+ def key
+ 'external-http'
+ end
+
+ def results
+ super.merge(calls: calls)
+ end
+
+ def self.thresholds
+ @thresholds ||= THRESHOLDS.fetch(Rails.env.to_sym, DEFAULT_THRESHOLDS)
+ end
+
+ def format_call_details(call)
+ uri = URI("")
+ uri.scheme = call[:scheme]
+ uri.host = call[:host]
+ uri.port = call[:port]
+ uri.path = call[:path]
+ uri.query = call[:query]
+
+ super.merge(
+ label: "#{call[:method]} #{uri}",
+ code: code(call),
+ proxy: proxy(call),
+ error: error(call)
+ )
+ end
+
+ private
+
+ def duration
+ ::Gitlab::Metrics::Subscribers::ExternalHttp.duration * 1000
+ end
+
+ def calls
+ ::Gitlab::Metrics::Subscribers::ExternalHttp.request_count
+ end
+
+ def call_details
+ ::Gitlab::Metrics::Subscribers::ExternalHttp.detail_store
+ end
+
+ def proxy(call)
+ if call[:proxy_host].present?
+ "Proxied via #{call[:proxy_host]}:#{call[:proxy_port]}"
+ else
+ nil
+ end
+ end
+
+ def code(call)
+ if call[:code].present?
+ "Response status: #{call[:code]}"
+ else
+ nil
+ end
+ end
+
+ def error(call)
+ if call[:exception_object].present?
+ "Exception: #{call[:exception_object]}"
+ else
+ nil
+ end
+ end
+ end
+ end
+end
diff --git a/locale/gitlab.pot b/locale/gitlab.pot
index 87184ea37aa0c98daebfaa784839a5f0415b090c..26ba2e4ae9663eac43a5585e9b95311c20b92951 100644
--- a/locale/gitlab.pot
+++ b/locale/gitlab.pot
@@ -20676,6 +20676,9 @@ msgstr ""
msgid "PerformanceBar|Elasticsearch calls"
msgstr ""
+msgid "PerformanceBar|External Http calls"
+msgstr ""
+
msgid "PerformanceBar|Frontend resources"
msgstr ""
diff --git a/spec/lib/gitlab/instrumentation_helper_spec.rb b/spec/lib/gitlab/instrumentation_helper_spec.rb
index c00b0fdf04375fc573945f10dd4a46921c478b03..084ad9bb443662075d58d435e0b6d6bb531318e7 100644
--- a/spec/lib/gitlab/instrumentation_helper_spec.rb
+++ b/spec/lib/gitlab/instrumentation_helper_spec.rb
@@ -37,7 +37,9 @@
:redis_shared_state_write_bytes,
:db_count,
:db_write_count,
- :db_cached_count
+ :db_cached_count,
+ :external_http_count,
+ :external_http_duration_s
]
expect(described_class.keys).to eq(expected_keys)
diff --git a/spec/lib/gitlab/metrics/subscribers/external_http_spec.rb b/spec/lib/gitlab/metrics/subscribers/external_http_spec.rb
new file mode 100644
index 0000000000000000000000000000000000000000..5bcaf8fbc47b4bae856005f6e06c571d2ff20dbc
--- /dev/null
+++ b/spec/lib/gitlab/metrics/subscribers/external_http_spec.rb
@@ -0,0 +1,172 @@
+# frozen_string_literal: true
+
+require 'spec_helper'
+
+RSpec.describe Gitlab::Metrics::Subscribers::ExternalHttp, :request_store do
+ let(:transaction) { Gitlab::Metrics::Transaction.new }
+ let(:subscriber) { described_class.new }
+
+ let(:event_1) do
+ double(:event, payload: {
+ method: 'POST', code: "200", duration: 0.321,
+ scheme: 'https', host: 'gitlab.com', port: 80, path: '/api/v4/projects',
+ query: 'current=true'
+ })
+ end
+
+ let(:event_2) do
+ double(:event, payload: {
+ method: 'GET', code: "301", duration: 0.12,
+ scheme: 'http', host: 'gitlab.com', port: 80, path: '/api/v4/projects/2',
+ query: 'current=true'
+ })
+ end
+
+ let(:event_3) do
+ double(:event, payload: {
+ method: 'POST', duration: 5.3,
+ scheme: 'http', host: 'gitlab.com', port: 80, path: '/api/v4/projects/2/issues',
+ query: 'current=true',
+ exception_object: Net::ReadTimeout.new
+ })
+ end
+
+ describe '.detail_store' do
+ context 'when external HTTP detail store is empty' do
+ before do
+ Gitlab::SafeRequestStore[:peek_enabled] = true
+ end
+
+ it 'returns an empty array' do
+ expect(described_class.detail_store).to eql([])
+ end
+ end
+
+ context 'when the performance bar is not enabled' do
+ it 'returns an empty array' do
+ expect(described_class.detail_store).to eql([])
+ end
+ end
+
+ context 'when external HTTP detail store has some values' do
+ before do
+ Gitlab::SafeRequestStore[:peek_enabled] = true
+ Gitlab::SafeRequestStore[:external_http_detail_store] = [{
+ method: 'POST', code: "200", duration: 0.321
+ }]
+ end
+
+ it 'returns the external http detailed store' do
+ expect(described_class.detail_store).to eql([{ method: 'POST', code: "200", duration: 0.321 }])
+ end
+ end
+ end
+
+ describe '.payload' do
+ context 'when SafeRequestStore does not have any item from external HTTP' do
+ it 'returns an empty array' do
+ expect(described_class.payload).to eql(external_http_count: 0, external_http_duration_s: 0.0)
+ end
+ end
+
+ context 'when external HTTP recorded some values' do
+ before do
+ Gitlab::SafeRequestStore[:external_http_count] = 7
+ Gitlab::SafeRequestStore[:external_http_duration_s] = 1.2
+ end
+
+ it 'returns the external http detailed store' do
+ expect(described_class.payload).to eql(external_http_count: 7, external_http_duration_s: 1.2)
+ end
+ end
+ end
+
+ describe '#request' do
+ before do
+ Gitlab::SafeRequestStore[:peek_enabled] = true
+ allow(subscriber).to receive(:current_transaction).and_return(transaction)
+ end
+
+ it 'tracks external HTTP request count' do
+ expect(transaction).to receive(:increment)
+ .with(:gitlab_external_http_total, 1, { code: "200", method: "POST" })
+ expect(transaction).to receive(:increment)
+ .with(:gitlab_external_http_total, 1, { code: "301", method: "GET" })
+
+ subscriber.request(event_1)
+ subscriber.request(event_2)
+ end
+
+ it 'tracks external HTTP duration' do
+ expect(transaction).to receive(:observe)
+ .with(:gitlab_external_http_duration_seconds, 0.321)
+ expect(transaction).to receive(:observe)
+ .with(:gitlab_external_http_duration_seconds, 0.12)
+ expect(transaction).to receive(:observe)
+ .with(:gitlab_external_http_duration_seconds, 5.3)
+
+ subscriber.request(event_1)
+ subscriber.request(event_2)
+ subscriber.request(event_3)
+ end
+
+ it 'tracks external HTTP exceptions' do
+ expect(transaction).to receive(:increment)
+ .with(:gitlab_external_http_total, 1, { code: 'undefined', method: "POST" })
+ expect(transaction).to receive(:increment)
+ .with(:gitlab_external_http_exception_total, 1)
+
+ subscriber.request(event_3)
+ end
+
+ it 'stores per-request counters' do
+ subscriber.request(event_1)
+ subscriber.request(event_2)
+ subscriber.request(event_3)
+
+ expect(Gitlab::SafeRequestStore[:external_http_count]).to eq(3)
+ expect(Gitlab::SafeRequestStore[:external_http_duration_s]).to eq(5.741) # 0.321 + 0.12 + 5.3
+ end
+
+ it 'stores a portion of events into the detail store' do
+ subscriber.request(event_1)
+ subscriber.request(event_2)
+ subscriber.request(event_3)
+
+ expect(Gitlab::SafeRequestStore[:external_http_detail_store].length).to eq(3)
+ expect(Gitlab::SafeRequestStore[:external_http_detail_store][0]).to include(
+ method: 'POST', code: "200", duration: 0.321,
+ scheme: 'https', host: 'gitlab.com', port: 80, path: '/api/v4/projects',
+ query: 'current=true', exception_object: nil,
+ backtrace: be_a(Array)
+ )
+ expect(Gitlab::SafeRequestStore[:external_http_detail_store][1]).to include(
+ method: 'GET', code: "301", duration: 0.12,
+ scheme: 'http', host: 'gitlab.com', port: 80, path: '/api/v4/projects/2',
+ query: 'current=true', exception_object: nil,
+ backtrace: be_a(Array)
+ )
+ expect(Gitlab::SafeRequestStore[:external_http_detail_store][2]).to include(
+ method: 'POST', duration: 5.3,
+ scheme: 'http', host: 'gitlab.com', port: 80, path: '/api/v4/projects/2/issues',
+ query: 'current=true',
+ exception_object: be_a(Net::ReadTimeout),
+ backtrace: be_a(Array)
+ )
+ end
+
+ context 'when the performance bar is not enabled' do
+ before do
+ Gitlab::SafeRequestStore.delete(:peek_enabled)
+ end
+
+ it 'does not capture detail store' do
+ subscriber.request(event_1)
+ subscriber.request(event_2)
+ subscriber.request(event_3)
+
+ expect(Gitlab::SafeRequestStore[:external_http_detail_store]).to be(nil)
+ end
+ end
+ end
+end
diff --git a/spec/lib/peek/views/external_http_spec.rb b/spec/lib/peek/views/external_http_spec.rb
new file mode 100644
index 0000000000000000000000000000000000000000..b90bb74c313b4126d46c06a7de27dd19f30125e9
--- /dev/null
+++ b/spec/lib/peek/views/external_http_spec.rb
@@ -0,0 +1,87 @@
+# frozen_string_literal: true
+
+require 'spec_helper'
+
+RSpec.describe Peek::Views::ExternalHttp, :request_store do
+ subject { described_class.new }
+
+ let(:subscriber) { Gitlab::Metrics::Subscribers::ExternalHttp.new }
+
+ before do
+ allow(Gitlab::PerformanceBar).to receive(:enabled_for_request?).and_return(true)
+ end
+
+ let(:event_1) do
+ double(:event, payload: {
+ method: 'POST', code: "200", duration: 0.03,
+ scheme: 'https', host: 'gitlab.com', port: 80, path: '/api/v4/projects',
+ query: 'current=true'
+ })
+ end
+
+ let(:event_2) do
+ double(:event, payload: {
+ method: 'POST', duration: 1.3,
+ scheme: 'http', host: 'gitlab.com', port: 80, path: '/api/v4/projects/2/issues',
+ query: 'current=true',
+ exception_object: Net::ReadTimeout.new
+ })
+ end
+
+ let(:event_3) do
+ double(:event, payload: {
+ method: 'GET', code: "301", duration: 0.005,
+ scheme: 'http', host: 'gitlab.com', port: 80, path: '/api/v4/projects/2',
+ query: 'current=true',
+ proxy_host: 'proxy.gitlab.com', proxy_port: 8080
+ })
+ end
+
+ it 'returns no results' do
+ expect(subject.results).to eq(
+ calls: 0, details: [], duration: "0ms", warnings: []
+ )
+ end
+
+ it 'returns aggregated results' do
+ subscriber.request(event_1)
+ subscriber.request(event_2)
+ subscriber.request(event_3)
+
+ results = subject.results
+ expect(results[:calls]).to eq(3)
+ expect(results[:duration]).to eq("1335.00ms")
+ expect(results[:details].count).to eq(3)
+
+ expected = [
+ {
+ duration: 30.0,
+ label: "POST https://gitlab.com:80/api/v4/projects?current=true",
+ code: "Response status: 200",
+ proxy: nil,
+ error: nil,
+ warnings: []
+ },
+ {
+ duration: 1300,
+ label: "POST http://gitlab.com:80/api/v4/projects/2/issues?current=true",
+ code: nil,
+ proxy: nil,
+ error: "Exception: Net::ReadTimeout",
+ warnings: ["1300.0 over 100"]
+ },
+ {
+ duration: 5.0,
+ label: "GET http://gitlab.com:80/api/v4/projects/2?current=true",
+ code: "Response status: 301",
+ proxy: nil,
+ error: nil,
+ warnings: []
+ }
+ ]
+
+ expect(
+ results[:details].map { |data| data.slice(:duration, :label, :code, :proxy, :error, :warnings) }
+ ).to match_array(expected)
+ end
+end