Log poor Redis RTT, fixes #4824

Changes.md

@@ -5,6 +5,7 @@
 HEAD
 ---------
 
+- Store Redis RTT and log if poor [#4824]
 - Add process/thread stats to Busy page [#4806]
 - Refactor Web UI session usage. [#4804]
   Numerous people have hit "Forbidden" errors and struggled with Sidekiq's

lib/sidekiq/api.rb

@@ -791,12 +791,12 @@ def each
         # you'll be happier this way
         conn.pipelined do
           procs.each do |key|
-            conn.hmget(key, "info", "busy", "beat", "quiet", "rss")
+            conn.hmget(key, "info", "busy", "beat", "quiet", "rss", "rtt_us")
           end
         end
       }
 
-      result.each do |info, busy, at_s, quiet, rss|
+      result.each do |info, busy, at_s, quiet, rss, rtt|
         # If a process is stopped between when we query Redis for `procs` and
         # when we query for `result`, we will have an item in `result` that is
         # composed of `nil` values.
@@ -806,7 +806,8 @@ def each
         yield Process.new(hash.merge("busy" => busy.to_i,
                                      "beat" => at_s.to_f,
                                      "quiet" => quiet,
-                                     "rss" => rss.to_i))
+                                     "rss" => rss.to_i,
+                                     "rtt_us" => rtt.to_i))
       end
     end
 

lib/sidekiq/launcher.rb

@@ -153,6 +153,8 @@ def ❤
           end
         end
 
+        rtt = check_rtt
+
         fails = procd = 0
         kb = memory_usage(::Process.pid)
 
@@ -163,6 +165,7 @@ def ❤
             conn.hmset(key, "info", to_json,
               "busy", curstate.size,
               "beat", Time.now.to_f,
+              "rtt_us", rtt,
               "quiet", @done,
               "rss", kb)
             conn.expire(key, 60)
@@ -185,6 +188,29 @@ def ❤
       end
     end
 
+    RTT_WARNING_LEVEL = 50_000
+
+    def check_rtt
+      a = b = 0
+      Sidekiq.redis do |x|
+        a = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC, :microsecond)
+        x.ping
+        b = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC, :microsecond)
+      end
+      rtt = b - a
+      # Ideal RTT for Redis is < 1000µs
+      # Workable is < 10,000µs
+      # Log a warning if it's a disaster.
+      if rtt > RTT_WARNING_LEVEL
+        Sidekiq.logger.warn <<-EOM
+          Your Redis network connection is performing extremely poorly.
+          Current RTT is #{rtt} µs, ideally this should be < 1000.
+          Ensure Redis is running in the same AZ or datacenter as Sidekiq.
+        EOM
+      end
+      rtt
+    end
+
     MEMORY_GRABBER = case RUBY_PLATFORM
     when /linux/
       ->(pid) {

test/test_launcher.rb

@@ -49,9 +49,11 @@ def new_manager(opts)
         it 'stores process info in redis' do
           subject.heartbeat
 
-          workers = Sidekiq.redis { |c| c.hmget(subject.identity, 'busy') }
+          workers, rtt = Sidekiq.redis { |c| c.hmget(subject.identity, 'busy', 'rtt_us') }
 
-          assert_equal ["1"], workers
+          assert_equal "1", workers
+          refute_nil rtt
+          assert_in_delta 1000, rtt.to_i, 1000
 
           expires = Sidekiq.redis { |c| c.pttl(subject.identity) }