Instrumentation: fix rounding errors on short durations

Rounding causes a loss of information. We should only round numbers
when we have to. This commit fixes instrumentation code that was
unnecessarily rounding intermediate results.

lib/gitlab/git/rugged_impl/use_rugged.rb

@@ -25,7 +25,7 @@ module Gitlab
 
             if Gitlab::RuggedInstrumentation.active?
               Gitlab::RuggedInstrumentation.increment_query_count
-              Gitlab::RuggedInstrumentation.query_time += duration
+              Gitlab::RuggedInstrumentation.add_query_time(duration)
 
               Gitlab::RuggedInstrumentation.add_call_details(
                 feature: method_name,

lib/gitlab/gitaly_client.rb

@@ -201,7 +201,8 @@ module Gitlab
       request_hash = request.is_a?(Google::Protobuf::MessageExts) ? request.to_h : {}
 
       # Keep track, separately, for the performance bar
-      self.query_time += duration
+      self.add_query_time(duration)
+
       if Gitlab::PerformanceBar.enabled_for_request?
         add_call_details(feature: "#{service}##{rpc}", duration: duration, request: request_hash, rpc: rpc,
                          backtrace: Gitlab::BacktraceCleaner.clean_backtrace(caller))
@@ -209,12 +210,15 @@ module Gitlab
     end
 
     def self.query_time
-      query_time = SafeRequestStore[:gitaly_query_time] ||= 0
+      query_time = Gitlab::SafeRequestStore[:gitaly_query_time] || 0
       query_time.round(Gitlab::InstrumentationHelper::DURATION_PRECISION)
     end
 
-    def self.query_time=(duration)
-      SafeRequestStore[:gitaly_query_time] = duration
+    def self.add_query_time(duration)
+      return unless Gitlab::SafeRequestStore.active?
+
+      Gitlab::SafeRequestStore[:gitaly_query_time] ||= 0
+      Gitlab::SafeRequestStore[:gitaly_query_time] += duration
     end
 
     def self.current_transaction_labels

lib/gitlab/instrumentation/redis.rb

@@ -43,8 +43,8 @@ module Gitlab
       end
 
       def self.add_duration(duration)
-        total_time = query_time + duration
-        ::RequestStore[REDIS_CALL_DURATION] = total_time
+        ::RequestStore[REDIS_CALL_DURATION] ||= 0
+        ::RequestStore[REDIS_CALL_DURATION] += duration
       end
 
       def self.add_call_details(duration, args)

lib/gitlab/rugged_instrumentation.rb

@@ -3,12 +3,13 @@
 module Gitlab
   module RuggedInstrumentation
     def self.query_time
-      query_time = SafeRequestStore[:rugged_query_time] ||= 0
+      query_time = SafeRequestStore[:rugged_query_time] || 0
       query_time.round(Gitlab::InstrumentationHelper::DURATION_PRECISION)
     end
 
-    def self.query_time=(duration)
-      SafeRequestStore[:rugged_query_time] = duration
+    def self.add_query_time(duration)
+      SafeRequestStore[:rugged_query_time] ||= 0
+      SafeRequestStore[:rugged_query_time] += duration
     end
 
     def self.query_time_ms

lib/peek/views/gitaly.rb

@@ -40,12 +40,6 @@ module Peek
 
         super.merge(request: pretty_request || {})
       end
-
-      def setup_subscribers
-        subscribe 'start_processing.action_controller' do
-          ::Gitlab::GitalyClient.query_time = 0
-        end
-      end
     end
   end
 end

spec/lib/gitlab/gitaly_client_spec.rb

@@ -21,10 +21,10 @@ describe Gitlab::GitalyClient do
 
   describe '.query_time', :request_store do
     it 'increments query times' do
-      subject.query_time += 0.451
-      subject.query_time += 0.322
+      subject.add_query_time(0.4510004)
+      subject.add_query_time(0.3220004)
 
-      expect(subject.query_time).to eq(0.773)
+      expect(subject.query_time).to eq(0.773001)
     end
   end
 

spec/lib/gitlab/instrumentation/redis_spec.rb

+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::Instrumentation::Redis do
+  describe '.add_duration', :request_store do
+    it 'does not lose precision while adding' do
+      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
+end

spec/lib/gitlab/rugged_instrumentation_spec.rb

@@ -7,10 +7,10 @@ describe Gitlab::RuggedInstrumentation, :request_store do
 
   describe '.query_time' do
     it 'increments query times' do
-      subject.query_time += 0.451
-      subject.query_time += 0.322
+      subject.add_query_time(0.4510004)
+      subject.add_query_time(0.3220004)
 
-      expect(subject.query_time).to be_within(0.001).of(0.773)
+      expect(subject.query_time).to eq(0.773001)
       expect(subject.query_time_ms).to eq(773.0)
     end
   end

spec/lib/gitlab/sidekiq_middleware_spec.rb

@@ -12,7 +12,7 @@ describe Gitlab::SidekiqMiddleware do
 
       def perform(_arg)
         Gitlab::SafeRequestStore['gitaly_call_actual'] = 1
-        Gitlab::GitalyClient.query_time = 5
+        Gitlab::SafeRequestStore[:gitaly_query_time] = 5
       end
     end
   end

spec/lib/peek/views/rugged_spec.rb

@@ -16,7 +16,7 @@ describe Peek::Views::Rugged, :request_store do
   end
 
   it 'returns aggregated results' do
-    ::Gitlab::RuggedInstrumentation.query_time += 1.234
+    ::Gitlab::RuggedInstrumentation.add_query_time(1.234)
     ::Gitlab::RuggedInstrumentation.increment_query_count
     ::Gitlab::RuggedInstrumentation.increment_query_count