Lock performance (#595)

* Adds test-prof, stackprof and ruby-prof

* Correct typo

* Reduce concurrent ruby waiting times

* Yield the actual token received

* Update appraisals

* Bump bundler version

* Better debugging on failure

This should allow easier debugging of when things go wrong

.github/workflows/lint.yml

@@ -14,7 +14,7 @@ jobs:
       - uses: ruby/setup-ruby@v1
         with:
           ruby-version: 2.7
-          bundler: 2.2.15
+          bundler: 2.2.16
           bundler-cache: true
       - run: bin/bundle --jobs=$(nproc) --retry=$(nproc)
       - run: bin/rubocop -P
@@ -29,7 +29,7 @@ jobs:
       - uses: ruby/setup-ruby@v1
         with:
           ruby-version: 2.7
-          bundler: 2.2.15
+          bundler: 2.2.16
           bundler-cache: true
       - run: bin/bundle --jobs=$(nproc) --retry=$(nproc)
       - run: bin/reek .

.github/workflows/rspec.yml

@@ -18,7 +18,7 @@ jobs:
       - uses: ruby/setup-ruby@v1
         with:
           ruby-version: 2.7
-          bundler: 2.2.15
+          bundler: 2.2.16
           bundler-cache: true
 
       - name: Install Code Climate reporter
@@ -56,7 +56,7 @@ jobs:
       - uses: ruby/setup-ruby@v1
         with:
           ruby-version: ${{ matrix.ruby }}
-          bundler: 2.2.15
+          bundler: 2.2.16
           bundler-cache: true
       - run: bin/appraisal install --jobs=$(nproc) --retry=$(nproc)
       - run: bin/appraisal rspec --require spec_helper --tag ~perf

.reek.yml

@@ -25,6 +25,7 @@ detectors:
     enabled: true
     exclude:
       - SidekiqUniqueJobs::DeleteOrphan
+      - SidekiqUniqueJobs::Logging
       - SidekiqUniqueJobs::Redis
   DuplicateMethodCall:
     exclude:
@@ -133,6 +134,7 @@ detectors:
       - SidekiqUniqueJobs::Locksmith#lock_async
       - SidekiqUniqueJobs::Locksmith#lock_sync
       - SidekiqUniqueJobs::LockTTL#calculate
+      - SidekiqUniqueJobs::Logging#build_message
       - SidekiqUniqueJobs::Logging::Middleware#logging_context
       - SidekiqUniqueJobs::Middleware#call
       - SidekiqUniqueJobs::Server#self.configure

Gemfile

@@ -32,8 +32,10 @@ platforms :mri do
   gem "reek", ">= 5.3"
   gem "rspec-benchmark"
   gem "rubocop-mhenrixon"
-  gem "ruby-prof", require: false
+  gem "ruby-prof", ">= 0.17.0", require: false
   gem "simplecov-sublime", ">= 0.21.2", require: false
+  gem "stackprof", ">= 0.2.9", require: false
+  gem "test-prof"
   gem "travis"
 end
 

gemfiles/sidekiq_5.0.gemfile

@@ -30,8 +30,10 @@ platforms :mri do
   gem "reek", ">= 5.3"
   gem "rspec-benchmark"
   gem "rubocop-mhenrixon"
-  gem "ruby-prof", require: false
+  gem "ruby-prof", ">= 0.17.0", require: false
   gem "simplecov-sublime", ">= 0.21.2", require: false
+  gem "stackprof", ">= 0.2.9", require: false
+  gem "test-prof"
   gem "travis"
 end
 

gemfiles/sidekiq_5.1.gemfile

@@ -30,8 +30,10 @@ platforms :mri do
   gem "reek", ">= 5.3"
   gem "rspec-benchmark"
   gem "rubocop-mhenrixon"
-  gem "ruby-prof", require: false
+  gem "ruby-prof", ">= 0.17.0", require: false
   gem "simplecov-sublime", ">= 0.21.2", require: false
+  gem "stackprof", ">= 0.2.9", require: false
+  gem "test-prof"
   gem "travis"
 end
 

gemfiles/sidekiq_5.2.gemfile

@@ -30,8 +30,10 @@ platforms :mri do
   gem "reek", ">= 5.3"
   gem "rspec-benchmark"
   gem "rubocop-mhenrixon"
-  gem "ruby-prof", require: false
+  gem "ruby-prof", ">= 0.17.0", require: false
   gem "simplecov-sublime", ">= 0.21.2", require: false
+  gem "stackprof", ">= 0.2.9", require: false
+  gem "test-prof"
   gem "travis"
 end
 

gemfiles/sidekiq_6.0.gemfile

@@ -30,8 +30,10 @@ platforms :mri do
   gem "reek", ">= 5.3"
   gem "rspec-benchmark"
   gem "rubocop-mhenrixon"
-  gem "ruby-prof", require: false
+  gem "ruby-prof", ">= 0.17.0", require: false
   gem "simplecov-sublime", ">= 0.21.2", require: false
+  gem "stackprof", ">= 0.2.9", require: false
+  gem "test-prof"
   gem "travis"
 end
 

gemfiles/sidekiq_6.1.gemfile

@@ -30,8 +30,10 @@ platforms :mri do
   gem "reek", ">= 5.3"
   gem "rspec-benchmark"
   gem "rubocop-mhenrixon"
-  gem "ruby-prof", require: false
+  gem "ruby-prof", ">= 0.17.0", require: false
   gem "simplecov-sublime", ">= 0.21.2", require: false
+  gem "stackprof", ">= 0.2.9", require: false
+  gem "test-prof"
   gem "travis"
 end
 

gemfiles/sidekiq_develop.gemfile

@@ -30,8 +30,10 @@ platforms :mri do
   gem "reek", ">= 5.3"
   gem "rspec-benchmark"
   gem "rubocop-mhenrixon"
-  gem "ruby-prof", require: false
+  gem "ruby-prof", ">= 0.17.0", require: false
   gem "simplecov-sublime", ">= 0.21.2", require: false
+  gem "stackprof", ">= 0.2.9", require: false
+  gem "test-prof"
   gem "travis"
 end
 

lib/sidekiq_unique_jobs/lock/base_lock.rb

@@ -124,7 +124,7 @@ def replace?
       attr_reader :attempt
 
       def unlock_with_callback
-        return log_warn("might need to be unlocked manually") unless unlock
+        return log_warn("Might need to be unlocked manually", item) unless unlock
 
         callback_safely
         item[JID]
@@ -134,7 +134,7 @@ def callback_safely
         callback&.call
         item[JID]
       rescue StandardError
-        log_warn("unlocked successfully but the #after_unlock callback failed!")
+        log_warn("Unlocked successfully but the #after_unlock callback failed!", item)
         raise
       end
 

lib/sidekiq_unique_jobs/lock/until_and_while_executing.rb

@@ -21,7 +21,7 @@ def execute
             runtime_lock.execute { return yield }
           end
         else
-          log_warn "couldn't unlock digest: #{item[LOCK_DIGEST]} #{item[JID]}"
+          log_warn("Couldn't unlock digest: #{item[LOCK_DIGEST]}, jid: #{item[JID]}")
         end
       end
 
@@ -30,7 +30,7 @@ def execute
       def lock_on_failure
         yield
       rescue Exception # rubocop:disable Lint/RescueException
-        log_error("Runtime lock failed to execute job, restoring server lock")
+        log_error("Runtime lock failed to execute job, restoring server lock", item)
         lock
         raise
       end

lib/sidekiq_unique_jobs/lock_config.rb

@@ -71,6 +71,10 @@ def initialize(job_hash = {})
       @on_server_conflict = job_hash[ON_SERVER_CONFLICT]
     end
 
+    def lock_info?
+      lock_info
+    end
+
     #
     # Indicate if timeout was set
     #

lib/sidekiq_unique_jobs/locksmith.rb

@@ -199,7 +199,7 @@ def lock_async(conn)
     def primed_async(conn)
       return yield if Concurrent::Promises
                       .future(conn) { |red_con| pop_queued(red_con) }
-                      .value(drift(config.ttl))
+                      .value(drift(config.pttl) / 1000) # Important to reduce time spent waiting
 
       warn_about_timeout
     end
@@ -220,7 +220,7 @@ def lock_sync(conn)
       enqueue(conn) do
         primed_sync(conn) do
           locked_token = call_script(:lock, key.to_a, argv, conn)
-          return yield if locked_token
+          return yield locked_token if locked_token
         end
       end
     end
@@ -235,7 +235,9 @@ def lock_sync(conn)
     # @return [Object] whatever the block returns when lock was acquired
     #
     def primed_sync(conn)
-      return yield if pop_queued(conn)
+      if (popped_jid = pop_queued(conn))
+        return yield popped_jid
+      end
 
       warn_about_timeout
     end
@@ -260,7 +262,7 @@ def pop_queued(conn)
     #
     def brpoplpush(conn)
       # passing timeout 0 to brpoplpush causes it to block indefinitely
-      conn.brpoplpush(key.queued, key.primed, timeout: config.timeout || 0)
+      conn.brpoplpush(key.queued, key.primed, timeout: config.timeout)
     end
 
     #
@@ -288,7 +290,7 @@ def enqueue(conn)
       return unless queued_token && (validity >= 0 || config.pttl.zero?)
 
       write_lock_info(conn)
-      yield
+      yield queued_token
     end
 
     #
@@ -299,7 +301,7 @@ def enqueue(conn)
     # @return [void]
     #
     def write_lock_info(conn)
-      return unless config.lock_info
+      return unless config.lock_info?
 
       conn.set(key.info, lock_info)
     end
@@ -315,7 +317,7 @@ def drift(val)
       # Add 2 milliseconds to the drift to account for Redis expires
       # precision, which is 1 millisecond, plus 1 millisecond min drift
       # for small TTLs.
-      (val.to_i * CLOCK_DRIFT_FACTOR).to_i + 2
+      (val.to_f * CLOCK_DRIFT_FACTOR).to_f + 2
     end
 
     #

lib/sidekiq_unique_jobs/logging.rb

@@ -29,8 +29,9 @@ def logger
     #
     # @yield [String, Exception] the message or exception to use for log message
     #
-    def log_debug(message_or_exception = nil, &block)
-      logger.debug(message_or_exception, &block)
+    def log_debug(message_or_exception = nil, item = nil, &block)
+      message = build_message(message_or_exception, item)
+      logger.debug(message, &block)
       nil
     end
 
@@ -43,8 +44,9 @@ def log_debug(message_or_exception = nil, &block)
     #
     # @yield [String, Exception] the message or exception to use for log message
     #
-    def log_info(message_or_exception = nil, &block)
-      logger.info(message_or_exception, &block)
+    def log_info(message_or_exception = nil, item = nil, &block)
+      message = build_message(message_or_exception, item)
+      logger.info(message, &block)
       nil
     end
 
@@ -57,8 +59,9 @@ def log_info(message_or_exception = nil, &block)
     #
     # @yield [String, Exception] the message or exception to use for log message
     #
-    def log_warn(message_or_exception = nil, &block)
-      logger.warn(message_or_exception, &block)
+    def log_warn(message_or_exception = nil, item = nil, &block)
+      message = build_message(message_or_exception, item)
+      logger.warn(message, &block)
       nil
     end
 
@@ -71,8 +74,9 @@ def log_warn(message_or_exception = nil, &block)
     #
     # @yield [String, Exception] the message or exception to use for log message
     #
-    def log_error(message_or_exception = nil, &block)
-      logger.error(message_or_exception, &block)
+    def log_error(message_or_exception = nil, item = nil, &block)
+      message = build_message(message_or_exception, item)
+      logger.error(message, &block)
       nil
     end
 
@@ -85,11 +89,27 @@ def log_error(message_or_exception = nil, &block)
     #
     # @yield [String, Exception] the message or exception to use for log message
     #
-    def log_fatal(message_or_exception = nil, &block)
-      logger.fatal(message_or_exception, &block)
+    def log_fatal(message_or_exception = nil, item = nil, &block)
+      message = build_message(message_or_exception, item)
+      logger.fatal(message, &block)
       nil
     end
 
+    def build_message(message_or_exception, item = nil)
+      return nil if message_or_exception.nil?
+      return message_or_exception if item.nil?
+
+      message = message_or_exception.dup
+      details = item.slice(LOCK, QUEUE, CLASS, JID, LOCK_DIGEST).each_with_object([]) do |(key, value), memo|
+        memo << "#{key}=#{value}"
+      end
+      message << " ("
+      message << details.join(" ")
+      message << ")"
+
+      message
+    end
+
     #
     # Wraps the middleware logic with context aware logging
     #
@@ -172,7 +192,7 @@ def sidekiq_context_method
     end
 
     def sidekiq_logger_context_method
-      logger.method(:with_context)           if logger_respond_to_with_context?
+      logger.method(:with_context) if logger_respond_to_with_context?
     end
 
     def sidekiq_logging_context_method

spec/sidekiq_unique_jobs/lock/base_lock_spec.rb

@@ -4,10 +4,12 @@
   let(:lock)     { described_class.new(item, callback) }
   let(:callback) { -> { p "debug" } }
   let(:strategy) { :replace }
+  let(:jid)      { "bogusjobid" }
   let(:item) do
     { "class" => "JustAWorker",
       "queue" => "testqueue",
       "on_conflict" => strategy,
+      "jid" => jid,
       "args" => [{ foo: "bar" }] }
   end
 
@@ -42,6 +44,25 @@
     end
   end
 
+  describe "#unlock_with_callback" do
+    subject(:unlock_with_callback) { lock.send(:unlock_with_callback) }
+
+    context "when lock can't be unlocked" do
+      before do
+        allow(callback).to receive(:call)
+
+        allow(lock).to receive(:unlock).and_return(false)
+        allow(lock).to receive(:log_warn)
+      end
+
+      it "logs a warning" do
+        expect(unlock_with_callback).not_to eq(jid)
+        expect(callback).not_to have_received(:call)
+        expect(lock).to have_received(:log_warn).with("Might need to be unlocked manually", item)
+      end
+    end
+  end
+
   describe "#callback_safely" do
     subject(:callback_safely) { lock.send(:callback_safely) }
 
@@ -53,7 +74,7 @@
 
       it "logs a warning" do
         expect { callback_safely }.to raise_error(RuntimeError, "Hell")
-        expect(lock).to have_received(:log_warn).with("unlocked successfully but the #after_unlock callback failed!")
+        expect(lock).to have_received(:log_warn).with("Unlocked successfully but the #after_unlock callback failed!", item)
       end
     end
   end