Implement External HTTP metrics subscriber

In labkit-ruby, there are publishers for popular HTTP clients used by
Gitlab. Those publishers publish events via ActiveRecord::Notification.
Those events should be captured, accumulated by request, then displayed
in Rails logs, Sidekiq logs, and Performance Bar.

https://gitlab.com/gitlab-com/gl-infra/scalability/-/issues/302

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'),

changelogs/unreleased/302-improve-visibility-of-time-spent-with-external-io.yml

+---
+title: Improve visibility of time spent with external HTTP calls
+merge_request: 50696
+author:
+type: added

config/initializers/peek.rb

@@ -11,6 +11,7 @@ Peek.into Peek::Views::Gitaly
 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?

config/initializers/tracing.rb

@@ -8,6 +8,7 @@ if Labkit::Tracing.enabled?
 
   # Instrument Redis
   Labkit::Tracing::Redis.instrument
+  Labkit::Tracing::ExternalHttp.instrument
 
   # Instrument Rails
   Labkit::Tracing::Rails::ActiveRecordSubscriber.instrument

config/initializers/zz_metrics.rb

@@ -202,4 +202,8 @@ if Gitlab::Metrics.enabled? && !Rails.env.test? && !(Rails.env.development? && d
   class ::Redis::Client
     prepend TrackNewRedisConnections
   end
+
+  Labkit::NetHttpPublisher.labkit_prepend!
+  Labkit::ExconPublisher.labkit_prepend!
+  Labkit::HTTPClientPublisher.labkit_prepend!
 end

doc/administration/monitoring/performance/performance_bar.md

@@ -31,6 +31,10 @@ From left to right, it displays:
   ![Redis profiling using the Performance Bar](img/performance_bar_redis_calls.png)
 - **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
+  ![External call details in the Performance Bar](img/performance_bar_external_http_calls.png)
 - **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:

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
 

lib/gitlab/instrumentation_helper.rb

@@ -14,7 +14,8 @@ module Gitlab
                  :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 @@ module Gitlab
       instrument_elasticsearch(payload)
       instrument_throttle(payload)
       instrument_active_record(payload)
+      instrument_external_http(payload)
     end
 
     def instrument_gitaly(payload)
@@ -59,6 +61,14 @@ module Gitlab
       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?

lib/gitlab/metrics/subscribers/external_http.rb

+# 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

lib/peek/views/external_http.rb

+# 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

locale/gitlab.pot

@@ -20652,6 +20652,9 @@ msgstr ""
 msgid "PerformanceBar|Elasticsearch calls"
 msgstr ""
 
+msgid "PerformanceBar|External Http calls"
+msgstr ""
+
 msgid "PerformanceBar|Frontend resources"
 msgstr ""
 

spec/lib/gitlab/instrumentation_helper_spec.rb

@@ -37,7 +37,9 @@ RSpec.describe Gitlab::InstrumentationHelper do
         :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)

spec/lib/gitlab/metrics/subscribers/external_http_spec.rb

+# 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

spec/lib/peek/views/external_http_spec.rb

+# 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