refactor: observed receives start_time (7f550e5f) · Commits · GitLab.org / ruby / gems / labkit-ruby

lib/labkit/user_experience_sli.rb

+3 −3

Original line number	Diff line number	Diff line
		@@ -100,13 +100,13 @@ module Labkit
		# Records a past user experience by its duration atomically.
		#
		# @param experience_id [String, Symbol] The ID of the experience.
		# @param duration_s [Numeric] Elapsed duration in seconds.
		# @param start_time [Time] The time when the experience started.
		# @param extra [Hash] Additional data to include in the log events.
		# @return [Experience, Null] The observed experience or a Null object if not found (in production/staging).
		def observed(experience_id, duration_s:, **extra)
		def observed(experience_id, start_time:, **extra)
		definition = registry[experience_id]
		experience = definition ? Experience.new(definition) : raise_or_null(experience_id)
		experience.observed(duration_s: duration_s, **extra)
		experience.observed(start_time: start_time, **extra)
		end

		# Resumes a user experience using the experience_id.

lib/labkit/user_experience_sli/README.md

+3 −5

Original line number	Diff line number	Diff line
		@@ -166,21 +166,19 @@ experience.complete
		When an action already happened and you want to record its duration retroactively, use `observed`. It fires the start and end metrics without registering in the active context:

		```ruby
		duration_s = Time.now - start_time_of_past_action

		Labkit::UserExperienceSli.observed('merge_request_creation', duration_s: duration_s)
		Labkit::UserExperienceSli.observed('merge_request_creation', start_time: start_time_of_past_action)
		```

		You can also signal that an error occurred during the action:

		```ruby
		Labkit::UserExperienceSli.observed('merge_request_creation', duration_s: duration_s, error: true)
		Labkit::UserExperienceSli.observed('merge_request_creation', start_time: start_time_of_past_action, error: true)
		```

		Extra labels are forwarded to both the start and end log events:

		```ruby
		Labkit::UserExperienceSli.observed('merge_request_creation', duration_s: duration_s, worker: 'MyWorker')
		Labkit::UserExperienceSli.observed('merge_request_creation', start_time: start_time_of_past_action, worker: 'MyWorker')
		```

		#### Resuming Experiences

lib/labkit/user_experience_sli/experience.rb

+4 −5

Original line number	Diff line number	Diff line
		@@ -137,13 +137,13 @@ module Labkit

		# Records a past User Experience by its duration.
		#
		# @param duration_s [Numeric] The elapsed duration in seconds.
		# @param start_time [Time] The time when the experience started.
		# @param error [Boolean] Whether the experience ended in an error.
		# @param extra [Hash] Additional data to include in the log events.
		# @return [self]
		def observed(duration_s:, error: false, **extra)
		@start_time = @end_time = Time.now.utc
		@observed_duration_s = duration_s
		def observed(start_time:, error: false, **extra)
		@start_time = start_time.utc
		@end_time = Time.now.utc
		error!("observed_error") if error

		checkpoint_counter.increment(checkpoint: "start", **base_labels)
		@@ -214,7 +214,6 @@ module Labkit
		end

		def elapsed_time
		return @observed_duration_s unless @observed_duration_s.nil?
		return 0 unless @start_time

		last_time = @end_time \|\| @checkpoint_time \|\| @start_time

spec/labkit/user_experience_sli/experience_spec.rb

+11 −9

Original line number	Diff line number	Diff line
		@@ -377,8 +377,9 @@ RSpec.describe Labkit::UserExperienceSli::Experience, :with_metrics_config do

		describe '#observed' do
		let(:duration_s) { 1.5 }
		let(:start_time) { Time.now.utc - duration_s }

		subject(:observed) { experience.observed(duration_s: duration_s) }
		subject(:observed) { experience.observed(start_time: start_time) }

		it { is_expected.to be(experience) }

		@@ -386,20 +387,21 @@ RSpec.describe Labkit::UserExperienceSli::Experience, :with_metrics_config do
		expect { observed }.to observed_user_experience(:testing_sample)
		end

		it 'sets start_time and end_time to the same timestamp' do
		it 'sets start_time to the provided value and end_time to now' do
		observed

		expect(experience.start_time).to eq(experience.instance_variable_get(:@end_time))
		expect(experience.start_time).to eq(start_time)
		expect(experience.instance_variable_get(:@end_time)).to be > start_time
		end

		it 'sets elapsed_time_s equal to duration_s' do
		it 'sets elapsed_time_s based on the provided start_time' do
		expect(Labkit::UserExperienceSli.configuration.logger).to receive(:info)
		.with(hash_including(checkpoint: 'start', elapsed_time_s: duration_s))
		.with(hash_including(checkpoint: 'start', elapsed_time_s: be_within(0.1).of(duration_s)))
		.ordered
		.and_call_original

		expect(Labkit::UserExperienceSli.configuration.logger).to receive(:info)
		.with(hash_including(checkpoint: 'end', elapsed_time_s: duration_s))
		.with(hash_including(checkpoint: 'end', elapsed_time_s: be_within(0.1).of(duration_s)))
		.ordered
		.and_call_original

		@@ -425,11 +427,11 @@ RSpec.describe Labkit::UserExperienceSli::Experience, :with_metrics_config do
		.ordered
		.and_call_original

		experience.observed(duration_s: duration_s, **extra_info)
		experience.observed(start_time: start_time, **extra_info)
		end

		context 'when error: true' do
		subject(:observed) { experience.observed(duration_s: duration_s, error: true) }
		subject(:observed) { experience.observed(start_time: start_time, error: true) }

		it 'fires total with error=true and skips apdex' do
		expect { observed }.to observed_user_experience(:testing_sample, error: true)
		@@ -452,7 +454,7 @@ RSpec.describe Labkit::UserExperienceSli::Experience, :with_metrics_config do
		end

		it 'raises error when reserved keywords are used in extra' do
		expect { experience.observed(duration_s: duration_s, urgency: 'fake') }.to raise_error(
		expect { experience.observed(start_time: start_time, urgency: 'fake') }.to raise_error(
		Labkit::UserExperienceSli::ReservedKeywordError
		)
		end

spec/labkit/user_experience_sli_spec.rb

+7 −5

Original line number	Diff line number	Diff line
		@@ -419,7 +419,9 @@ RAILS_ENVIRONMENTS = %w[test development].freeze
		end

		describe '.observed' do
		subject(:observed) { described_class.observed('testing_sample', duration_s: 1.0) }
		let(:start_time) { Time.now.utc - 1.0 }

		subject(:observed) { described_class.observed('testing_sample', start_time: start_time) }

		it 'returns an Experience instance' do
		expect(observed).to be_a(described_class::Experience)
		@@ -444,7 +446,7 @@ RAILS_ENVIRONMENTS = %w[test development].freeze

		context 'with error: true' do
		it 'fires total with error=true and skips apdex' do
		expect { described_class.observed('testing_sample', duration_s: 1.0, error: true) }
		expect { described_class.observed('testing_sample', start_time: start_time, error: true) }
		.to observed_user_experience(:testing_sample, error: true)
		end
		end
		@@ -461,20 +463,20 @@ RAILS_ENVIRONMENTS = %w[test development].freeze
		.ordered
		.and_call_original

		described_class.observed('testing_sample', duration_s: 1.0, user_id: 42)
		described_class.observed('testing_sample', start_time: start_time, user_id: 42)
		end
		end

		context 'when experience_id is not found' do
		it 'returns a null object' do
		expect(described_class.observed('nonexistent', duration_s: 1.0)).to be(described_class::Null.instance)
		expect(described_class.observed('nonexistent', start_time: start_time)).to be(described_class::Null.instance)
		end

		RAILS_ENVIRONMENTS.each do \|env\|
		it "raises error when RAILS_ENV is #{env}" do
		stub_env('RAILS_ENV', env)

		expect { described_class.observed('nonexistent', duration_s: 1.0) }.to raise_error(described_class::NotFoundError, "User Experience nonexistent not found in the registry")
		expect { described_class.observed('nonexistent', start_time: start_time) }.to raise_error(described_class::NotFoundError, "User Experience nonexistent not found in the registry")
		end
		end
		end