Merge branch '214279-es-instrumentation' into 'master'

Introduce instrumentation for all Elasticsearch HTTP requests

Closes #214279

See merge request gitlab-org/gitlab!32822

doc/administration/logs.md

@@ -77,6 +77,14 @@ User clone and fetch activity using HTTP transport appears in this log as `actio
 In addition, the log contains the originating IP address,
 (`remote_ip`),the user's ID (`user_id`), and username (`username`).
 
+Some endpoints such as `/search` may make requests to Elasticsearch if using
+[Advanced Global Search](../user/search/advanced_global_search.md). These will
+additionally log `elasticsearch_calls` and `elasticsearch_call_duration_s`,
+which correspond to:
+
+1. `elasticsearch_calls`: total number of calls to Elasticsearch
+1. `elasticsearch_duration_s`: total time taken by Elasticsearch calls
+
 NOTE: **Note:** Starting with GitLab 12.5, if an error occurs, an
 `exception` field is included with `class`, `message`, and
 `backtrace`. Previous versions included an `error` field instead of

ee/spec/lib/gitlab/instrumentation/elasticsearch_transport_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+# We don't want to interact with Elasticsearch in GitLab FOSS so we test
+# this in ee/ only. The code exists in FOSS and won't do anything.
+
+describe ::Gitlab::Instrumentation::ElasticsearchTransport, :elastic, :request_store do
+  describe '.increment_request_count' do
+    it 'increases the request count by 1' do
+      expect { described_class.increment_request_count }.to change(described_class, :get_request_count).by(1)
+    end
+  end
+
+  describe '.add_duration' do
+    it 'does not lose precision while adding' do
+      ::Gitlab::SafeRequestStore.clear!
+
+      precision = 1.0 / (10**::Gitlab::InstrumentationHelper::DURATION_PRECISION)
+      2.times { described_class.add_duration(0.4 * precision) }
+
+      # 2 * 0.4 should be 0.8 and get rounded to 1
+      expect(described_class.query_time).to eq(1 * precision)
+    end
+  end
+
+  describe '.add_call_details' do
+    before do
+      stub_ee_application_setting(elasticsearch_search: true, elasticsearch_indexing: true)
+      allow(::Gitlab::PerformanceBar).to receive(:enabled_for_request?).and_return(true)
+    end
+
+    it 'parses and tracks the call details' do
+      ensure_elasticsearch_index!
+
+      ::Gitlab::SafeRequestStore.clear!
+
+      create(:issue, title: "new issue")
+      ensure_elasticsearch_index!
+
+      request = ::Gitlab::Instrumentation::ElasticsearchTransport.detail_store.first
+      expect(request[:method]).to eq("POST")
+      expect(request[:path]).to eq("_bulk")
+    end
+  end
+end
+
+describe ::Gitlab::Instrumentation::ElasticsearchTransportInterceptor, :elastic, :request_store do
+  before do
+    allow(::Gitlab::PerformanceBar).to receive(:enabled_for_request?).and_return(true)
+  end
+
+  it 'tracks any requests via the Elasticsearch client' do
+    ensure_elasticsearch_index!
+
+    expect(::Gitlab::Instrumentation::ElasticsearchTransport.get_request_count).to be > 0
+    expect(::Gitlab::Instrumentation::ElasticsearchTransport.query_time).to be > 0
+    expect(::Gitlab::Instrumentation::ElasticsearchTransport.detail_store).not_to be_empty
+  end
+end

ee/spec/lib/gitlab/instrumentation_helper_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::InstrumentationHelper do
+  describe '.add_instrumentation_data', :request_store do
+    let(:payload) { {} }
+
+    subject { described_class.add_instrumentation_data(payload) }
+
+    # We don't want to interact with Elasticsearch in GitLab FOSS so we test
+    # this in ee/ only. The code exists in FOSS and won't do anything.
+    context 'when Elasticsearch calls are made', :elastic do
+      it 'adds Elasticsearch data' do
+        ensure_elasticsearch_index!
+
+        subject
+
+        expect(payload[:elasticsearch_calls]).to be > 0
+        expect(payload[:elasticsearch_duration_s]).to be > 0
+      end
+    end
+  end
+end

lib/gitlab/instrumentation/elasticsearch_transport.rb

+# frozen_string_literal: true
+
+require 'elasticsearch-transport'
+
+module Gitlab
+  module Instrumentation
+    module ElasticsearchTransportInterceptor
+      def perform_request(*args)
+        start = Time.now
+        super
+      ensure
+        if ::Gitlab::SafeRequestStore.active?
+          duration = (Time.now - start)
+
+          ::Gitlab::Instrumentation::ElasticsearchTransport.increment_request_count
+          ::Gitlab::Instrumentation::ElasticsearchTransport.add_duration(duration)
+          ::Gitlab::Instrumentation::ElasticsearchTransport.add_call_details(duration, args)
+        end
+      end
+    end
+
+    class ElasticsearchTransport
+      ELASTICSEARCH_REQUEST_COUNT = :elasticsearch_request_count
+      ELASTICSEARCH_CALL_DURATION = :elasticsearch_call_duration
+      ELASTICSEARCH_CALL_DETAILS = :elasticsearch_call_details
+
+      def self.get_request_count
+        ::Gitlab::SafeRequestStore[ELASTICSEARCH_REQUEST_COUNT] || 0
+      end
+
+      def self.increment_request_count
+        ::Gitlab::SafeRequestStore[ELASTICSEARCH_REQUEST_COUNT] ||= 0
+        ::Gitlab::SafeRequestStore[ELASTICSEARCH_REQUEST_COUNT] += 1
+      end
+
+      def self.detail_store
+        ::Gitlab::SafeRequestStore[ELASTICSEARCH_CALL_DETAILS] ||= []
+      end
+
+      def self.query_time
+        query_time = ::Gitlab::SafeRequestStore[ELASTICSEARCH_CALL_DURATION] || 0
+        query_time.round(::Gitlab::InstrumentationHelper::DURATION_PRECISION)
+      end
+
+      def self.add_duration(duration)
+        ::Gitlab::SafeRequestStore[ELASTICSEARCH_CALL_DURATION] ||= 0
+        ::Gitlab::SafeRequestStore[ELASTICSEARCH_CALL_DURATION] += duration
+      end
+
+      def self.add_call_details(duration, args)
+        return unless Gitlab::PerformanceBar.enabled_for_request?
+
+        detail_store << {
+          method: args[0],
+          path: args[1],
+          params: args[2],
+          body: args[3],
+          duration: duration,
+          backtrace: ::Gitlab::BacktraceCleaner.clean_backtrace(caller)
+        }
+      end
+    end
+  end
+end
+
+class ::Elasticsearch::Transport::Client
+  prepend ::Gitlab::Instrumentation::ElasticsearchTransportInterceptor
+end

lib/gitlab/instrumentation_helper.rb

@@ -4,7 +4,19 @@ module Gitlab
   module InstrumentationHelper
     extend self
 
-    KEYS = %i(gitaly_calls gitaly_duration_s rugged_calls rugged_duration_s redis_calls redis_duration_s redis_read_bytes redis_write_bytes).freeze
+    KEYS = %i(
+      gitaly_calls
+      gitaly_duration_s
+      rugged_calls
+      rugged_duration_s
+      redis_calls
+      redis_duration_s
+      redis_read_bytes
+      redis_write_bytes
+      elasticsearch_calls
+      elasticsearch_duration_s
+    ).freeze
+
     DURATION_PRECISION = 6 # microseconds
 
     def add_instrumentation_data(payload)
@@ -35,6 +47,15 @@ module Gitlab
         payload[:redis_read_bytes] = redis_read_bytes
         payload[:redis_write_bytes] = redis_write_bytes
       end
+
+      # Elasticsearch integration is only available in EE but instrumentation
+      # only depends on the Gem which is also available in FOSS.
+      elasticsearch_calls = Gitlab::Instrumentation::ElasticsearchTransport.get_request_count
+
+      if elasticsearch_calls > 0
+        payload[:elasticsearch_calls] = elasticsearch_calls
+        payload[:elasticsearch_duration_s] = Gitlab::Instrumentation::ElasticsearchTransport.query_time
+      end
     end
 
     # Returns the queuing duration for a Sidekiq job in seconds, as a float, if the