diff --git a/app/services/concerns/exclusive_lease_guard.rb b/app/services/concerns/exclusive_lease_guard.rb index 74acaa0522a74f1fb0576b968f5f749704e04051..1f557ef70bcd10d24dd25e153695fe7ec0647146 100644 --- a/app/services/concerns/exclusive_lease_guard.rb +++ b/app/services/concerns/exclusive_lease_guard.rb @@ -20,14 +20,18 @@ module ExclusiveLeaseGuard def try_obtain_lease lease = exclusive_lease.try_obtain + Gitlab::Instrumentation::ExclusiveLock.increment_requested_count + unless lease log_lease_taken return end begin + lease_start_time = Time.current yield lease ensure + Gitlab::Instrumentation::ExclusiveLock.add_hold_duration(Time.current - lease_start_time) release_lease(lease) if lease_release? end end diff --git a/lib/gitlab/exclusive_lease_helpers.rb b/lib/gitlab/exclusive_lease_helpers.rb index 8836cb34745cc735d0a3d0b7a03f6cac73d8b1e2..c9cd5bce8072728ec432ae7e90ce5693118a9b64 100644 --- a/lib/gitlab/exclusive_lease_helpers.rb +++ b/lib/gitlab/exclusive_lease_helpers.rb @@ -31,13 +31,32 @@ module ExclusiveLeaseHelpers def in_lock(key, ttl: 1.minute, retries: 10, sleep_sec: 0.01.seconds) raise ArgumentError, 'Key needs to be specified' unless key + Gitlab::Instrumentation::ExclusiveLock.increment_requested_count + lease = SleepingLock.new(key, timeout: ttl, delay: sleep_sec) - lease.obtain(1 + retries) + with_instrumentation(:wait) do + lease.obtain(1 + retries) + end - yield(lease.retried?, lease) + with_instrumentation(:hold) do + yield(lease.retried?, lease) + end ensure lease&.cancel end + + private + + def with_instrumentation(metric) + start_time = Time.current + yield + ensure + if metric == :wait + Gitlab::Instrumentation::ExclusiveLock.add_wait_duration(Time.current - start_time) + else + Gitlab::Instrumentation::ExclusiveLock.add_hold_duration(Time.current - start_time) + end + end end end diff --git a/lib/gitlab/instrumentation/exclusive_lock.rb b/lib/gitlab/instrumentation/exclusive_lock.rb new file mode 100644 index 0000000000000000000000000000000000000000..2861af771fc3ac70b0d6301c89c3cb330bec5cfc --- /dev/null +++ b/lib/gitlab/instrumentation/exclusive_lock.rb @@ -0,0 +1,54 @@ +# frozen_string_literal: true + +module Gitlab + module Instrumentation + class ExclusiveLock + EXCLUSIVE_LOCK_REQUESTED_COUNT = :exclusive_lock_requested_count + EXCLUSIVE_LOCK_WAIT_DURATION = :exclusive_lock_wait_duration_s + EXCLUSIVE_LOCK_HOLD_DURATION = :exclusive_lock_hold_duration_s + + class << self + def requested_count + ::Gitlab::SafeRequestStore[EXCLUSIVE_LOCK_REQUESTED_COUNT] || 0 + end + + def increment_requested_count + return unless Gitlab::SafeRequestStore.active? + + ::Gitlab::SafeRequestStore[EXCLUSIVE_LOCK_REQUESTED_COUNT] ||= 0 + ::Gitlab::SafeRequestStore[EXCLUSIVE_LOCK_REQUESTED_COUNT] += 1 + end + + def wait_duration + ::Gitlab::SafeRequestStore[EXCLUSIVE_LOCK_WAIT_DURATION] || 0 + end + + def add_wait_duration(duration) + return unless Gitlab::SafeRequestStore.active? + + ::Gitlab::SafeRequestStore[EXCLUSIVE_LOCK_WAIT_DURATION] ||= 0 + ::Gitlab::SafeRequestStore[EXCLUSIVE_LOCK_WAIT_DURATION] += duration + end + + def hold_duration + ::Gitlab::SafeRequestStore[EXCLUSIVE_LOCK_HOLD_DURATION] || 0 + end + + def add_hold_duration(duration) + return unless Gitlab::SafeRequestStore.active? + + ::Gitlab::SafeRequestStore[EXCLUSIVE_LOCK_HOLD_DURATION] ||= 0 + ::Gitlab::SafeRequestStore[EXCLUSIVE_LOCK_HOLD_DURATION] += duration + end + end + + def self.payload + { + EXCLUSIVE_LOCK_REQUESTED_COUNT => requested_count, + EXCLUSIVE_LOCK_WAIT_DURATION => wait_duration, + EXCLUSIVE_LOCK_HOLD_DURATION => hold_duration + } + end + end + end +end diff --git a/lib/gitlab/instrumentation_helper.rb b/lib/gitlab/instrumentation_helper.rb index 49078a7ccd0536a6842dc73ecf5c72f9ff7004ed..b893ea0c50cc3fb0190ce9db88613539e91111df 100644 --- a/lib/gitlab/instrumentation_helper.rb +++ b/lib/gitlab/instrumentation_helper.rb @@ -28,6 +28,7 @@ def add_instrumentation_data(payload) instrument_rate_limiting_gates(payload) instrument_global_search_api(payload) instrument_ldap(payload) + instrument_exclusive_lock(payload) end def instrument_gitaly(payload) @@ -139,6 +140,14 @@ def instrument_ldap(payload) payload.merge! Gitlab::Metrics::Subscribers::Ldap.payload end + def instrument_exclusive_lock(payload) + requested_count = Gitlab::Instrumentation::ExclusiveLock.requested_count + + return if requested_count == 0 + + payload.merge!(Gitlab::Instrumentation::ExclusiveLock.payload) + end + # Returns the queuing duration for a Sidekiq job in seconds, as a float, if the # `enqueued_at` field or `created_at` field is available. # diff --git a/spec/lib/gitlab/exclusive_lease_helpers_spec.rb b/spec/lib/gitlab/exclusive_lease_helpers_spec.rb index f9db93a616705fa1f94b7d779614854bff59a775..52de4220ba516fbf4f4aa1fea5f4e22c70a3d906 100644 --- a/spec/lib/gitlab/exclusive_lease_helpers_spec.rb +++ b/spec/lib/gitlab/exclusive_lease_helpers_spec.rb @@ -115,5 +115,38 @@ end end end + + describe 'instrumentation', :request_store do + let!(:lease) { stub_exclusive_lease_taken(unique_key) } + + subject do + class_instance.in_lock(unique_key, sleep_sec: 0.1, retries: 3) do + sleep 0.1 + end + end + + it 'increments lock requested count and computes the duration waiting for the lock and holding the lock' do + expect(lease).to receive(:try_obtain).exactly(3).times.and_return(nil) + expect(lease).to receive(:try_obtain).once.and_return(unique_key) + + subject + + expect(Gitlab::Instrumentation::ExclusiveLock.requested_count).to eq(1) + expect(Gitlab::Instrumentation::ExclusiveLock.wait_duration).to be_between(0.3, 0.31) + expect(Gitlab::Instrumentation::ExclusiveLock.hold_duration).to be_between(0.1, 0.11) + end + + context 'when exclusive lease is not obtained' do + it 'increments lock requested count and computes the duration waiting for the lock' do + expect(lease).to receive(:try_obtain).exactly(4).times.and_return(nil) + + expect { subject }.to raise_error('Failed to obtain a lock') + + expect(Gitlab::Instrumentation::ExclusiveLock.requested_count).to eq(1) + expect(Gitlab::Instrumentation::ExclusiveLock.wait_duration).to be_between(0.3, 0.31) + expect(Gitlab::Instrumentation::ExclusiveLock.hold_duration).to eq(0) + end + end + end end end diff --git a/spec/lib/gitlab/instrumentation/exclusive_lock_spec.rb b/spec/lib/gitlab/instrumentation/exclusive_lock_spec.rb new file mode 100644 index 0000000000000000000000000000000000000000..fb96c0f9762e1a23d86d10da2e4046432ad7211f --- /dev/null +++ b/spec/lib/gitlab/instrumentation/exclusive_lock_spec.rb @@ -0,0 +1,82 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe Gitlab::Instrumentation::ExclusiveLock, :request_store, feature_category: :scalability do + describe '.requested_count' do + it 'returns the value from Gitlab::SafeRequestStore' do + allow(Gitlab::SafeRequestStore).to receive(:[]).with(:exclusive_lock_requested_count).and_return(5) + + expect(described_class.requested_count).to eq(5) + end + + it 'returns 0 if value not set in Gitlab::SafeRequestStore' do + allow(Gitlab::SafeRequestStore).to receive(:[]).with(:exclusive_lock_requested_count).and_return(nil) + + expect(described_class.requested_count).to eq(0) + end + end + + describe '.increment_requested_count' do + it 'increments the lock count' do + expect { described_class.increment_requested_count } + .to change { described_class.requested_count }.from(0).to(1) + end + end + + describe '.wait_duration' do + it 'returns the value from Gitlab::SafeRequestStore' do + allow(Gitlab::SafeRequestStore).to receive(:[]).with(:exclusive_lock_wait_duration_s).and_return(5) + + expect(described_class.wait_duration).to eq(5) + end + + it 'returns 0 if value not set in Gitlab::SafeRequestStore' do + allow(Gitlab::SafeRequestStore).to receive(:[]).with(:exclusive_lock_wait_duration_s).and_return(nil) + + expect(described_class.wait_duration).to eq(0) + end + end + + describe '.add_wait_duration' do + it 'increments the duration' do + expect { described_class.add_wait_duration(5) } + .to change { described_class.wait_duration }.from(0).to(5) + end + end + + describe '.hold_duration' do + it 'returns the value from Gitlab::SafeRequestStore' do + allow(Gitlab::SafeRequestStore).to receive(:[]).with(:exclusive_lock_hold_duration_s).and_return(5) + + expect(described_class.hold_duration).to eq(5) + end + + it 'returns 0 if value not set in Gitlab::SafeRequestStore' do + allow(Gitlab::SafeRequestStore).to receive(:[]).with(:exclusive_lock_hold_duration_s).and_return(nil) + + expect(described_class.hold_duration).to eq(0) + end + end + + describe '.add_hold_duration' do + it 'increments the duration' do + expect { described_class.add_hold_duration(5) } + .to change { described_class.hold_duration }.from(0).to(5) + end + end + + describe '.payload' do + it 'returns a hash with metrics' do + described_class.increment_requested_count + described_class.add_wait_duration(2) + described_class.add_hold_duration(3) + + expect(described_class.payload).to eq({ + exclusive_lock_requested_count: 1, + exclusive_lock_wait_duration_s: 2, + exclusive_lock_hold_duration_s: 3 + }) + end + end +end diff --git a/spec/lib/gitlab/instrumentation_helper_spec.rb b/spec/lib/gitlab/instrumentation_helper_spec.rb index f8a4d8023c1639e5e7917a7e0ce644ec7c979fcd..cf7183d139f11734d6a01066dc7bd9ed7390c6df 100644 --- a/spec/lib/gitlab/instrumentation_helper_spec.rb +++ b/spec/lib/gitlab/instrumentation_helper_spec.rb @@ -260,6 +260,38 @@ }) end end + + context 'when an excluside lock is made' do + before do + Gitlab::SafeRequestStore[:exclusive_lock_requested_count] = 1 + end + + it 'adds excluside lock data' do + subject + + expect(payload).to include({ + exclusive_lock_requested_count: 1, + exclusive_lock_wait_duration_s: 0, + exclusive_lock_hold_duration_s: 0 + }) + end + end + + context 'when an excluside lock is not made' do + before do + Gitlab::SafeRequestStore[:exclusive_lock_requested_count] = 0 + end + + it 'does not add excluside lock data' do + subject + + expect(payload.keys).not_to include( + :exclusive_lock_requested_count, + :exclusive_lock_wait_duration_s, + :exclusive_lock_hold_duration_s + ) + end + end end describe '.queue_duration_for_job' do diff --git a/spec/services/concerns/exclusive_lease_guard_spec.rb b/spec/services/concerns/exclusive_lease_guard_spec.rb index ca8bff4ecc4adcf82c36eb74a8894a0be94ae69c..8643a488f718a60b9e0bfe07c6516d76b36731d2 100644 --- a/spec/services/concerns/exclusive_lease_guard_spec.rb +++ b/spec/services/concerns/exclusive_lease_guard_spec.rb @@ -40,6 +40,50 @@ def lease_timeout expect(subject.exclusive_lease.exists?).to be_falsey end + describe 'instrumentation', :request_store do + it 'increments the lock requested count and computes the duration of holding the lock' do + subject.call do + sleep 0.1 + end + + expect(Gitlab::Instrumentation::ExclusiveLock.requested_count).to eq(1) + expect(Gitlab::Instrumentation::ExclusiveLock.hold_duration).to be_between(0.1, 0.11) + end + + context 'when exclusive lease is not obtained' do + before do + allow_next_instance_of(Gitlab::ExclusiveLease) do |instance| + allow(instance).to receive(:try_obtain).and_return(false) + end + end + + it 'increments the lock requested count and does not computes the duration of holding the lock' do + subject.call do + sleep 0.1 + end + + expect(Gitlab::Instrumentation::ExclusiveLock.requested_count).to eq(1) + expect(Gitlab::Instrumentation::ExclusiveLock.hold_duration).to eq(0) + end + end + + context 'when an exception is raised during the lease' do + subject do + subject_class.new.call do + sleep 0.1 + raise StandardError + end + end + + it 'increments the lock requested count and computes the duration of holding the lock' do + expect { subject }.to raise_error(StandardError) + + expect(Gitlab::Instrumentation::ExclusiveLock.requested_count).to eq(1) + expect(Gitlab::Instrumentation::ExclusiveLock.hold_duration).to be_between(0.1, 0.11) + end + end + end + context 'when the lease is already obtained' do before do subject.exclusive_lease.try_obtain