Fix Gitaly Sidekiq timings in Prometheus

The RequestStoreMiddleware runs 'inside' the ServerMetrics middleware,
so by the time ServerMetrics is done with its `yield`, the RequestStore
doesn't exist any more.

This is exactly the reason why the InstrumentationLogger middleware
stores some values in the payload, so use that instead.

lib/gitlab/sidekiq_middleware/server_metrics.rb

@@ -46,7 +46,7 @@ module Gitlab
           @metrics[:sidekiq_jobs_cpu_seconds].observe(labels, job_thread_cputime)
           @metrics[:sidekiq_jobs_completion_seconds].observe(labels, monotonic_time)
           @metrics[:sidekiq_jobs_db_seconds].observe(labels, ActiveRecord::LogSubscriber.runtime / 1000)
-          @metrics[:sidekiq_jobs_gitaly_seconds].observe(labels, Gitlab::GitalyClient.query_time)
+          @metrics[:sidekiq_jobs_gitaly_seconds].observe(labels, get_gitaly_time(job))
         end
       end
 
@@ -69,6 +69,10 @@ module Gitlab
       def get_thread_cputime
         defined?(Process::CLOCK_THREAD_CPUTIME_ID) ? Process.clock_gettime(Process::CLOCK_THREAD_CPUTIME_ID) : 0
       end
+
+      def get_gitaly_time(job)
+        job.fetch(:gitaly_duration, 0) / 1000.0
+      end
     end
   end
 end

spec/lib/gitlab/sidekiq_middleware/server_metrics_spec.rb

@@ -67,7 +67,7 @@ describe Gitlab::SidekiqMiddleware::ServerMetrics do
             allow(Gitlab::Metrics::System).to receive(:monotonic_time).and_return(monotonic_time_before, monotonic_time_after)
             allow(Gitlab::InstrumentationHelper).to receive(:queue_duration_for_job).with(job).and_return(queue_duration_for_job)
             allow(ActiveRecord::LogSubscriber).to receive(:runtime).and_return(db_duration * 1000)
-            allow(Gitlab::GitalyClient).to receive(:query_time).and_return(gitaly_duration)
+            allow(subject).to receive(:get_gitaly_time).and_return(gitaly_duration)
 
             expect(running_jobs_metric).to receive(:increment).with(labels, 1)
             expect(running_jobs_metric).to receive(:increment).with(labels, -1)

spec/lib/gitlab/sidekiq_middleware_spec.rb

@@ -8,6 +8,8 @@ describe Gitlab::SidekiqMiddleware do
     include Sidekiq::Worker
 
     def perform(_arg)
+      Gitlab::SafeRequestStore['gitaly_call_actual'] = 1
+      Gitlab::GitalyClient.query_time = 5
     end
   end
 
@@ -99,6 +101,24 @@ describe Gitlab::SidekiqMiddleware do
       it "passes through server middlewares" do
         worker_class.perform_async(*job_args)
       end
+
+      context "server metrics" do
+        let(:gitaly_histogram) { double(:gitaly_histogram) }
+
+        before do
+          allow(Gitlab::Metrics).to receive(:histogram).and_call_original
+
+          allow(Gitlab::Metrics).to receive(:histogram)
+                                      .with(:sidekiq_jobs_gitaly_seconds, anything, anything, anything)
+                                      .and_return(gitaly_histogram)
+        end
+
+        it "records correct Gitaly duration" do
+          expect(gitaly_histogram).to receive(:observe).with(anything, 5.0)
+
+          worker_class.perform_async(*job_args)
+        end
+      end
     end
   end