Merge branch 'bvl-duration-recording' into 'master'

Don't record duration for errors

See merge request gitlab-org/gitlab!63892

doc/administration/monitoring/prometheus/gitlab_metrics.md

@@ -58,7 +58,7 @@ The following metrics are available:
 | `gitlab_transaction_cache_duration_total`                        | Counter     | 10.2    | Counter for total time (seconds) spent in Rails cache calls (aggregate)                                               |                                                           |
 | `gitlab_transaction_cache_read_hit_count_total`                  | Counter     | 10.2    | Counter for cache hits for Rails cache calls                                                                          | `controller`, `action`                                    |
 | `gitlab_transaction_cache_read_miss_count_total`                 | Counter     | 10.2    | Counter for cache misses for Rails cache calls                                                                        | `controller`, `action`                                    |
-| `gitlab_transaction_duration_seconds`                            | Histogram   | 10.2    | Duration for all transactions (`gitlab_transaction_*` metrics)                                                        | `controller`, `action`                                    |
+| `gitlab_transaction_duration_seconds`                            | Histogram   | 10.2    | Duration for successful requests (`gitlab_transaction_*` metrics)                                                     | `controller`, `action`                                    |
 | `gitlab_transaction_event_build_found_total`                     | Counter     | 9.4     | Counter for build found for API /jobs/request                                                                         |                                                           |
 | `gitlab_transaction_event_build_invalid_total`                   | Counter     | 9.4     | Counter for build invalid due to concurrency conflict for API /jobs/request                                           |                                                           |
 | `gitlab_transaction_event_build_not_found_cached_total`          | Counter     | 9.4     | Counter for cached response of build not found for API /jobs/request                                                  |                                                           |
@@ -91,7 +91,7 @@ The following metrics are available:
 | `gitlab_transaction_view_duration_total`                         | Counter     | 9.4     | Duration for views                                                                                                    | `controller`, `action`, `view`                            |
 | `gitlab_view_rendering_duration_seconds`                         | Histogram   | 10.2    | Duration for views (histogram)                                                                                        | `controller`, `action`, `view`                            |
 | `http_requests_total`                                            | Counter     | 9.4     | Rack request count                                                                                                    | `method`, `status`                                        |
-| `http_request_duration_seconds`                                  | Histogram   | 9.4     | HTTP response time from rack middleware                                                                               | `method`                                                  |
+| `http_request_duration_seconds`                                  | Histogram   | 9.4     | HTTP response time from rack middleware for successful requests                                                       | `method`                                                  |
 | `gitlab_transaction_db_count_total`                              | Counter     | 13.1    | Counter for total number of SQL calls                                                                                 | `controller`, `action`                                    |
 | `gitlab_transaction_db_<role>_count_total`                       | Counter     | 13.10   | Counter for total number of SQL calls, grouped by database roles (primary/replica)                                    | `controller`, `action`                                    |
 | `gitlab_transaction_db_write_count_total`                        | Counter     | 13.1    | Counter for total number of write SQL calls                                                                           | `controller`, `action`                                    |

lib/gitlab/metrics.rb

@@ -16,6 +16,10 @@ module Gitlab
       @error
     end
 
+    def self.record_duration_for_status?(status)
+      status.to_i.between?(200, 499)
+    end
+
     # Tracks an event.
     #
     # See `Gitlab::Metrics::Transaction#add_event` for more details.

lib/gitlab/metrics/requests_rack_middleware.rb

@@ -66,16 +66,16 @@ module Gitlab
       def call(env)
         method = env['REQUEST_METHOD'].downcase
         method = 'INVALID' unless HTTP_METHODS.key?(method)
-        started = Time.now.to_f
+        started = Gitlab::Metrics::System.monotonic_time
         health_endpoint = health_endpoint?(env['PATH_INFO'])
         status = 'undefined'
 
         begin
           status, headers, body = @app.call(env)
 
-          elapsed = Time.now.to_f - started
+          elapsed = Gitlab::Metrics::System.monotonic_time - started
 
-          unless health_endpoint
+          if !health_endpoint && Gitlab::Metrics.record_duration_for_status?(status)
             RequestsRackMiddleware.http_request_duration_seconds.observe({ method: method }, elapsed)
           end
 

lib/gitlab/metrics/transaction.rb

@@ -13,8 +13,6 @@ module Gitlab
 
       THREAD_KEY = :_gitlab_metrics_transaction
 
-      SMALL_BUCKETS = [0.1, 0.25, 0.5, 1.0, 2.5, 5.0].freeze
-
       # The series to store events (e.g. Git pushes) in.
       EVENT_SERIES = 'events'
 
@@ -39,29 +37,10 @@ module Gitlab
 
       def initialize
         @methods = {}
-
-        @started_at = nil
-        @finished_at = nil
-      end
-
-      def duration
-        @finished_at ? (@finished_at - @started_at) : 0.0
       end
 
       def run
-        Thread.current[THREAD_KEY] = self
-
-        @started_at = System.monotonic_time
-
-        yield
-      ensure
-        @finished_at = System.monotonic_time
-
-        observe(:gitlab_transaction_duration_seconds, duration) do
-          buckets SMALL_BUCKETS
-        end
-
-        Thread.current[THREAD_KEY] = nil
+        raise NotImplementedError
       end
 
       # Tracks a business level event

lib/gitlab/metrics/web_transaction.rb

@@ -6,12 +6,29 @@ module Gitlab
       CONTROLLER_KEY = 'action_controller.instance'
       ENDPOINT_KEY = 'api.endpoint'
       ALLOWED_SUFFIXES = Set.new(%w[json js atom rss xml zip])
+      SMALL_BUCKETS = [0.1, 0.25, 0.5, 1.0, 2.5, 5.0].freeze
 
       def initialize(env)
         super()
         @env = env
       end
 
+      def run
+        Thread.current[THREAD_KEY] = self
+
+        started_at = System.monotonic_time
+
+        status, _, _ = retval = yield
+
+        finished_at = System.monotonic_time
+        duration = finished_at - started_at
+        record_duration_if_needed(status, duration)
+
+        retval
+      ensure
+        Thread.current[THREAD_KEY] = nil
+      end
+
       def labels
         return @labels if @labels
 
@@ -27,6 +44,14 @@ module Gitlab
 
       private
 
+      def record_duration_if_needed(status, duration)
+        return unless Gitlab::Metrics.record_duration_for_status?(status)
+
+        observe(:gitlab_transaction_duration_seconds, duration) do
+          buckets SMALL_BUCKETS
+        end
+      end
+
       def labels_from_controller
         controller = @env[CONTROLLER_KEY]
 

spec/lib/gitlab/metrics/requests_rack_middleware_spec.rb

@@ -79,6 +79,17 @@ RSpec.describe Gitlab::Metrics::RequestsRackMiddleware, :aggregate_failures do
       end
     end
 
+    context '@app.call returns an error code' do
+      let(:status) { '500' }
+
+      it 'tracks count but not duration' do
+        expect(described_class).to receive_message_chain(:http_requests_total, :increment).with(method: 'get', status: '500', feature_category: 'unknown')
+        expect(described_class).not_to receive(:http_request_duration_seconds)
+
+        subject.call(env)
+      end
+    end
+
     context '@app.call throws exception' do
       let(:http_request_duration_seconds) { double('http_request_duration_seconds') }
       let(:http_requests_total) { double('http_requests_total') }

spec/lib/gitlab/metrics/transaction_spec.rb

@@ -12,32 +12,6 @@ RSpec.describe Gitlab::Metrics::Transaction do
     }
   end
 
-  describe '#duration' do
-    it 'returns the duration of a transaction in seconds' do
-      transaction.run { }
-
-      expect(transaction.duration).to be > 0
-    end
-  end
-
-  describe '#run' do
-    it 'yields the supplied block' do
-      expect { |b| transaction.run(&b) }.to yield_control
-    end
-
-    it 'stores the transaction in the current thread' do
-      transaction.run do
-        expect(described_class.current).to eq(transaction)
-      end
-    end
-
-    it 'removes the transaction from the current thread upon completion' do
-      transaction.run { }
-
-      expect(described_class.current).to be_nil
-    end
-  end
-
   describe '#method_call_for' do
     it 'returns a MethodCall' do
       method = transaction.method_call_for('Foo#bar', :Foo, '#bar')
@@ -46,6 +20,10 @@ RSpec.describe Gitlab::Metrics::Transaction do
     end
   end
 
+  describe '#run' do
+    specify { expect { transaction.run }.to raise_error(NotImplementedError) }
+  end
+
   describe '#add_event' do
     let(:prometheus_metric) { instance_double(Prometheus::Client::Counter, increment: nil, base_labels: {}) }
 

spec/lib/gitlab/metrics/web_transaction_spec.rb

@@ -38,16 +38,6 @@ RSpec.describe Gitlab::Metrics::WebTransaction do
     end
   end
 
-  describe '#duration' do
-    include_context 'transaction observe metrics'
-
-    it 'returns the duration of a transaction in seconds' do
-      transaction.run { sleep(0.5) }
-
-      expect(transaction.duration).to be >= 0.5
-    end
-  end
-
   describe '#run' do
     include_context 'transaction observe metrics'
 
@@ -58,6 +48,9 @@ RSpec.describe Gitlab::Metrics::WebTransaction do
     it 'stores the transaction in the current thread' do
       transaction.run do
         expect(Thread.current[described_class::THREAD_KEY]).to eq(transaction)
+        expect(described_class.current).to eq(transaction)
+
+        ['200', {}, '']
       end
     end
 
@@ -65,6 +58,33 @@ RSpec.describe Gitlab::Metrics::WebTransaction do
       transaction.run { }
 
       expect(Thread.current[described_class::THREAD_KEY]).to be_nil
+      expect(described_class.current).to be_nil
+    end
+
+    it 'records the duration of the transaction if the request was successful' do
+      expect(transaction).to receive(:observe).with(:gitlab_transaction_duration_seconds, instance_of(Float))
+
+      transaction.run { ['200', {}, ''] }
+    end
+
+    it 'does not record the duration of the transaction if the request failed' do
+      expect(transaction).not_to receive(:observe).with(:gitlab_transaction_duration_seconds, instance_of(Float))
+
+      transaction.run { ['500', {}, ''] }
+    end
+
+    it 'does not record the duration of the transaction if it raised' do
+      expect(transaction).not_to receive(:observe).with(:gitlab_transaction_duration_seconds, instance_of(Float))
+
+      expect do
+        transaction.run { raise 'broken' }
+      end.to raise_error('broken')
+    end
+
+    it 'returns the rack response' do
+      response = ['500', {}, '']
+
+      expect(transaction.run { response }).to eq(response)
     end
   end
 

spec/lib/gitlab/metrics_spec.rb

@@ -92,6 +92,26 @@ RSpec.describe Gitlab::Metrics do
     end
   end
 
+  describe '.record_status_for_duration?' do
+    using RSpec::Parameterized::TableSyntax
+
+    where(:status, :should_record) do
+      100  | false
+      200  | true
+      401  | true
+      nil  | false
+      500  | false
+      503   | false
+      '100' | false
+      '201' | true
+      'nothing' | false
+    end
+
+    with_them do
+      specify { expect(described_class.record_duration_for_status?(status)).to be(should_record) }
+    end
+  end
+
   describe '.add_event' do
     context 'without a transaction' do
       it 'does nothing' do