Instrument Redis calls

Shopify · Sep 14, 2023 · 5c82bbb · 5c82bbb
1 parent 897c116
commit 5c82bbb
Show file tree

Hide file tree

Showing 3 changed files with 47 additions and 14 deletions.
diff --git a/ruby/lib/ci/queue.rb b/ruby/lib/ci/queue.rb
@@ -13,6 +13,8 @@
 require 'ci/queue/file'
 require 'ci/queue/grind'
 require 'ci/queue/bisect'
+require 'logger'
+require 'fileutils'
 
 module CI
   module Queue
@@ -28,6 +30,21 @@ def requeueable?(test_result)
       requeueable.nil? || requeueable.call(test_result)
     end
 
+    def logger
+      @logger ||= begin
+        FileUtils.mkdir_p("log")
+        Logger.new('log/ci-queue.log')
+      end
+    end
+
+    def with_instrumentation(msg)
+      start = Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_millisecond)
+      result = yield
+      duration = Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_millisecond) - start
+      CI::Queue.logger.info("#{msg} #{duration}ms")
+      result
+    end
+
     def shuffle(tests, random)
       if shuffler
         shuffler.call(tests, random)

diff --git a/ruby/lib/ci/queue/redis/base.rb b/ruby/lib/ci/queue/redis/base.rb
@@ -11,9 +11,23 @@ class Base
           ::SocketError, # https://github.com/redis/redis-rb/pull/631
         ].freeze
 
+        module RedisInstrumentation
+          def connect(redis_config)
+            CI::Queue.with_instrumentation("redis connect: ") { super }
+          end
+
+          def call(command, redis_config)
+            CI::Queue.with_instrumentation("redis call #{command}: ") { super }
+          end
+
+          def call_pipelined(commands, redis_config)
+            CI::Queue.with_instrumentation("redis pipeline #{commands}: ") { super }
+          end
+        end
+
         def initialize(redis_url, config)
           @redis_url = redis_url
-          @redis = ::Redis.new(url: redis_url)
+          @redis = ::Redis.new(url: redis_url, middlewares: [RedisInstrumentation])
           @config = config
         end
 

diff --git a/ruby/lib/ci/queue/redis/worker.rb b/ruby/lib/ci/queue/redis/worker.rb
@@ -199,21 +199,23 @@ def try_to_reserve_lost_test
         end
 
         def push(tests)
-          @total = tests.size
-
-          if @master = redis.setnx(key('master-status'), 'setup')
-            redis.multi do |transaction|
-              transaction.lpush(key('queue'), tests) unless tests.empty?
-              transaction.set(key('total'), @total)
-              transaction.set(key('master-status'), 'ready')
-
-              transaction.expire(key('queue'), config.redis_ttl)
-              transaction.expire(key('total'), config.redis_ttl)
-              transaction.expire(key('master-status'), config.redis_ttl)
+          CI::Queue.with_instrumentation("push tests: ") do
+            @total = tests.size
+
+            if @master = redis.setnx(key('master-status'), 'setup')
+              redis.multi do |transaction|
+                transaction.lpush(key('queue'), tests) unless tests.empty?
+                transaction.set(key('total'), @total)
+                transaction.set(key('master-status'), 'ready')
+
+                transaction.expire(key('queue'), config.redis_ttl)
+                transaction.expire(key('total'), config.redis_ttl)
+                transaction.expire(key('master-status'), config.redis_ttl)
+              end
             end
+            register
+            redis.expire(key('workers'), config.redis_ttl)
           end
-          register
-          redis.expire(key('workers'), config.redis_ttl)
         rescue *CONNECTION_ERRORS
           raise if @master
         end