From fc075db1c03fc5d562423beaf4c231bec9b21ff5 Mon Sep 17 00:00:00 2001 From: Mikael Henriksson Date: Wed, 14 Apr 2021 10:38:59 +0200 Subject: [PATCH] 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 | 4 +- .github/workflows/rspec.yml | 4 +- .reek.yml | 2 + Gemfile | 4 +- gemfiles/sidekiq_5.0.gemfile | 4 +- gemfiles/sidekiq_5.1.gemfile | 4 +- gemfiles/sidekiq_5.2.gemfile | 4 +- gemfiles/sidekiq_6.0.gemfile | 4 +- gemfiles/sidekiq_6.1.gemfile | 4 +- gemfiles/sidekiq_develop.gemfile | 4 +- lib/sidekiq_unique_jobs/lock/base_lock.rb | 4 +- .../lock/until_and_while_executing.rb | 4 +- lib/sidekiq_unique_jobs/lock_config.rb | 4 ++ lib/sidekiq_unique_jobs/locksmith.rb | 16 ++++--- lib/sidekiq_unique_jobs/logging.rb | 42 ++++++++++++----- .../lock/base_lock_spec.rb | 23 ++++++++- spec/sidekiq_unique_jobs/logging_spec.rb | 47 +++++++++++++++---- 17 files changed, 134 insertions(+), 44 deletions(-) diff --git a/.github/workflows/lint.yml b/.github/workflows/lint.yml index 1ac91e49b..0505f5bd3 100644 --- a/.github/workflows/lint.yml +++ b/.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 . diff --git a/.github/workflows/rspec.yml b/.github/workflows/rspec.yml index f852775b2..6281d330d 100644 --- a/.github/workflows/rspec.yml +++ b/.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 diff --git a/.reek.yml b/.reek.yml index 381fd1277..019128d58 100644 --- a/.reek.yml +++ b/.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 diff --git a/Gemfile b/Gemfile index d65af6756..b440607fc 100644 --- a/Gemfile +++ b/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 diff --git a/gemfiles/sidekiq_5.0.gemfile b/gemfiles/sidekiq_5.0.gemfile index 585fd0877..8ee7bc4a8 100644 --- a/gemfiles/sidekiq_5.0.gemfile +++ b/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 diff --git a/gemfiles/sidekiq_5.1.gemfile b/gemfiles/sidekiq_5.1.gemfile index a350fd5db..93554aed3 100644 --- a/gemfiles/sidekiq_5.1.gemfile +++ b/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 diff --git a/gemfiles/sidekiq_5.2.gemfile b/gemfiles/sidekiq_5.2.gemfile index 3a7c05d9d..2d4359862 100644 --- a/gemfiles/sidekiq_5.2.gemfile +++ b/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 diff --git a/gemfiles/sidekiq_6.0.gemfile b/gemfiles/sidekiq_6.0.gemfile index 9ba88e069..868e553dc 100644 --- a/gemfiles/sidekiq_6.0.gemfile +++ b/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 diff --git a/gemfiles/sidekiq_6.1.gemfile b/gemfiles/sidekiq_6.1.gemfile index 4c8102300..2afb44f88 100644 --- a/gemfiles/sidekiq_6.1.gemfile +++ b/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 diff --git a/gemfiles/sidekiq_develop.gemfile b/gemfiles/sidekiq_develop.gemfile index 9224c0238..453cdc893 100644 --- a/gemfiles/sidekiq_develop.gemfile +++ b/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 diff --git a/lib/sidekiq_unique_jobs/lock/base_lock.rb b/lib/sidekiq_unique_jobs/lock/base_lock.rb index 4b0872a4e..3595e967e 100644 --- a/lib/sidekiq_unique_jobs/lock/base_lock.rb +++ b/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 diff --git a/lib/sidekiq_unique_jobs/lock/until_and_while_executing.rb b/lib/sidekiq_unique_jobs/lock/until_and_while_executing.rb index de23e6e63..5bcf9eb95 100644 --- a/lib/sidekiq_unique_jobs/lock/until_and_while_executing.rb +++ b/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 diff --git a/lib/sidekiq_unique_jobs/lock_config.rb b/lib/sidekiq_unique_jobs/lock_config.rb index ae4d7c96b..a31d638f3 100644 --- a/lib/sidekiq_unique_jobs/lock_config.rb +++ b/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 # diff --git a/lib/sidekiq_unique_jobs/locksmith.rb b/lib/sidekiq_unique_jobs/locksmith.rb index 67f139883..7f4bfe47a 100644 --- a/lib/sidekiq_unique_jobs/locksmith.rb +++ b/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 # diff --git a/lib/sidekiq_unique_jobs/logging.rb b/lib/sidekiq_unique_jobs/logging.rb index 400d8b1db..da26aa184 100644 --- a/lib/sidekiq_unique_jobs/logging.rb +++ b/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 diff --git a/spec/sidekiq_unique_jobs/lock/base_lock_spec.rb b/spec/sidekiq_unique_jobs/lock/base_lock_spec.rb index eb13a52a4..83c9c4d9c 100644 --- a/spec/sidekiq_unique_jobs/lock/base_lock_spec.rb +++ b/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 diff --git a/spec/sidekiq_unique_jobs/logging_spec.rb b/spec/sidekiq_unique_jobs/logging_spec.rb index ba291c180..8f78525c8 100644 --- a/spec/sidekiq_unique_jobs/logging_spec.rb +++ b/spec/sidekiq_unique_jobs/logging_spec.rb @@ -4,6 +4,18 @@ let(:logger) { SidekiqUniqueJobs.logger } let(:message) { "A log message" } let(:level) { nil } + let(:worker) { "JustAWorker" } + let(:queue) { "testqueue" } + let(:args) { [{ foo: "bar" }] } + let(:jid) { "jobid" } + let(:digest) { "digestable" } + let(:item) do + { "class" => worker, + "queue" => queue, + "args" => args, + "jid" => jid, + "lock_digest" => digest } + end before do allow(logger).to receive(level) @@ -15,8 +27,11 @@ let(:level) { :debug } it "delegates to logger.debug" do - expect(log_debug(message)).to be_nil - expect(logger).to have_received(level).with(message) + expect(log_debug(message, item)).to be_nil + expect(logger).to have_received(level).with( + a_string_starting_with(message) + .and(ending_with("(queue=#{queue} class=#{worker} jid=#{jid} lock_digest=#{digest})")), + ) end end @@ -24,8 +39,11 @@ let(:level) { :info } it "delegates to logger.info" do - expect(log_info(message)).to be_nil - expect(logger).to have_received(level).with(message) + expect(log_info(message, item)).to be_nil + expect(logger).to have_received(level).with( + a_string_starting_with(message) + .and(ending_with("(queue=#{queue} class=#{worker} jid=#{jid} lock_digest=#{digest})")), + ) end end @@ -33,8 +51,11 @@ let(:level) { :warn } it "delegates to logger.warn" do - expect(log_warn(message)).to be_nil - expect(logger).to have_received(level).with(message) + expect(log_warn(message, item)).to be_nil + expect(logger).to have_received(level).with( + a_string_starting_with(message) + .and(ending_with("(queue=#{queue} class=#{worker} jid=#{jid} lock_digest=#{digest})")), + ) end end @@ -42,8 +63,11 @@ let(:level) { :error } it "delegates to logger.error" do - expect(log_error(message)).to be_nil - expect(logger).to have_received(level).with(message) + expect(log_error(message, item)).to be_nil + expect(logger).to have_received(level).with( + a_string_starting_with(message) + .and(ending_with("(queue=#{queue} class=#{worker} jid=#{jid} lock_digest=#{digest})")), + ) end end @@ -51,8 +75,11 @@ let(:level) { :fatal } it "delegates to logger.fatal" do - expect(log_fatal(message)).to be_nil - expect(logger).to have_received(level).with(message) + expect(log_fatal(message, item)).to be_nil + expect(logger).to have_received(level).with( + a_string_starting_with(message) + .and(ending_with("(queue=#{queue} class=#{worker} jid=#{jid} lock_digest=#{digest})")), + ) end end