diff --git a/CHANGELOG.md b/CHANGELOG.md index 87b45bb6..b5672688 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,9 @@ Airbrake Ruby Changelog ### master +* Added `Airbrake::TimedTrace` for measuring performance of arbitrary code + chunks ([#476](https://github.com/airbrake/airbrake-ruby/pull/476)) + ### [v4.2.5][v4.2.5] (April 11, 2019) * Fixed `Airbrake.performance_notifier` & `Airbrake.deploy_notifier` returning diff --git a/README.md b/README.md index 46cd1405..92657617 100644 --- a/README.md +++ b/README.md @@ -928,6 +928,32 @@ puts "Time: #{time}" #=> Time: 67.40199995040894 ``` +### TimedTrace + +Represents a chunk of code performance of which was measured and stored under a +label. The chunk is called a "span". Such spans can be used for [performance +breakdown](#notify_performance_breakdown) reporting. + +#### .span + +```ruby +# Measure time for a span called 'operation'. +timed_trace = Airbrake::TimedTrace.span('operation') do + call_something +end +timed_trace.spans #=> { 'operation' => 0.123 } + +# Send the spans to the Airbrake dashboard. +Airbrake.notify_performance_breakdown( + method: 'GET', + route: '/things/1', + response_type: 'json', + groups: timed_trace.spans +) +``` + +See [full documentation][yard-api] for more examples. + Additional notes ---------------- diff --git a/lib/airbrake-ruby.rb b/lib/airbrake-ruby.rb index 12591e68..ddf0ffc8 100644 --- a/lib/airbrake-ruby.rb +++ b/lib/airbrake-ruby.rb @@ -49,6 +49,7 @@ require 'airbrake-ruby/performance_breakdown' require 'airbrake-ruby/benchmark' require 'airbrake-ruby/monotonic_time' +require 'airbrake-ruby/timed_trace' # Airbrake is a thin wrapper around instances of the notifier classes (such as # notice, performance & deploy notifiers). It creates a way to access them via a diff --git a/lib/airbrake-ruby/benchmark.rb b/lib/airbrake-ruby/benchmark.rb index eabca58e..46d7b239 100644 --- a/lib/airbrake-ruby/benchmark.rb +++ b/lib/airbrake-ruby/benchmark.rb @@ -3,12 +3,37 @@ module Airbrake # # @since v4.3.0 # @api private - module Benchmark + class Benchmark # Measures monotonic time for the given operation. + # + # @yieldreturn [void] def self.measure - start = MonotonicTime.time_in_ms + benchmark = new + yield - MonotonicTime.time_in_ms - start + + benchmark.stop + benchmark.duration + end + + # @return [Float] + attr_reader :duration + + # @since v4.3.0 + def initialize + @start = MonotonicTime.time_in_ms + @duration = 0.0 + end + + # Stops the benchmark and stores `duration`. + # + # @since v4.3.0 + # @return [Boolean] true for the first invocation, false in all other cases + def stop + return false if @duration > 0.0 + + @duration = MonotonicTime.time_in_ms - @start + true end end end diff --git a/lib/airbrake-ruby/timed_trace.rb b/lib/airbrake-ruby/timed_trace.rb new file mode 100644 index 00000000..d0e3b1fc --- /dev/null +++ b/lib/airbrake-ruby/timed_trace.rb @@ -0,0 +1,58 @@ +module Airbrake + # TimedTrace represents a chunk of code performance of which was measured and + # stored under a label. The chunk is called a "span". + # + # @example + # timed_trace = TimedTrace.new + # timed_trace.span('http request') do + # http.get('example.com') + # end + # timed_trace.spans #=> { 'http request' => 0.123 } + # + # @api public + # @since v4.3.0 + class TimedTrace + # @param [String] label + # @return [Airbrake::TimedTrace] + def self.span(label, &block) + new.tap { |timed_trace| timed_trace.span(label, &block) } + end + + def initialize + @spans = {} + end + + # @param [String] label + # @return [Boolean] + def span(label) + start_span(label) + yield + stop_span(label) + end + + # @param [String] label + # @return [Boolean] + def start_span(label) + return false if @spans.key?(label) + + @spans[label] = Airbrake::Benchmark.new + true + end + + # @param [String] label + # @return [Boolean] + def stop_span(label) + return false unless @spans.key?(label) + + @spans[label].stop + true + end + + # @return [HashFloat>] + def spans + @spans.each_with_object({}) do |(label, benchmark), new_spans| + new_spans[label] = benchmark.duration + end + end + end +end diff --git a/spec/benchmark_spec.rb b/spec/benchmark_spec.rb index 823686db..45a98909 100644 --- a/spec/benchmark_spec.rb +++ b/spec/benchmark_spec.rb @@ -1,7 +1,33 @@ RSpec.describe Airbrake::Benchmark do describe ".measure" do it "returns measured performance time" do - expect(subject.measure { '10' * 10 }).to be_kind_of(Numeric) + expect(described_class.measure { '10' * 10 }).to be_kind_of(Numeric) + end + end + + describe "#stop" do + before { subject } + + context "when called one time" do + its(:stop) { is_expected.to eq(true) } + end + + context "when called twice or more" do + before { subject.stop } + + its(:stop) { is_expected.to eq(false) } + end + end + + describe "#duration" do + context "when #stop wasn't called yet" do + its(:duration) { is_expected.to be_zero } + end + + context "when #stop was called" do + before { subject.stop } + + its(:duration) { is_expected.to be > 0 } end end end diff --git a/spec/timed_trace_spec.rb b/spec/timed_trace_spec.rb new file mode 100644 index 00000000..56808198 --- /dev/null +++ b/spec/timed_trace_spec.rb @@ -0,0 +1,125 @@ +RSpec.describe Airbrake::TimedTrace do + describe ".span" do + it "returns a timed trace" do + expect(described_class.span('operation') {}).to be_a(described_class) + end + + it "returns a timed trace with a stopped span" do + timed_trace = described_class.span('operation') {} + expect(timed_trace.spans).to match('operation' => be > 0) + end + end + + describe "#span" do + it "captures a span" do + subject.span('operation') {} + expect(subject.spans).to match('operation' => be > 0) + end + end + + describe "#start_span" do + context "when called once" do + it "returns true" do + expect(subject.start_span('operation')).to eq(true) + end + end + + context "when called multiple times" do + before { subject.start_span('operation') } + + it "returns false" do + expect(subject.start_span('operation')).to eq(false) + end + end + + context "when another span was started" do + before { subject.start_span('operation') } + + it "returns true" do + expect(subject.start_span('another operation')).to eq(true) + end + end + + context "when #spans was called" do + before { subject.start_span('operation') } + + it "returns spans with zero values" do + expect(subject.spans).to eq('operation' => 0.0) + end + end + end + + describe "#stop_span" do + context "when #start_span wasn't invoked" do + it "returns false" do + expect(subject.stop_span('operation')).to eq(false) + end + end + + context "when #start_span was invoked" do + before { subject.start_span('operation') } + + it "returns true" do + expect(subject.stop_span('operation')).to eq(true) + end + end + + context "when multiple spans were started" do + before do + subject.start_span('operation') + subject.start_span('another operation') + end + + context "and when stopping in LIFO order" do + it "returns true for all spans" do + expect(subject.stop_span('another operation')).to eq(true) + expect(subject.stop_span('operation')).to eq(true) + end + end + + context "and when stopping in FIFO order" do + it "returns true for all spans" do + expect(subject.stop_span('operation')).to eq(true) + expect(subject.stop_span('another operation')).to eq(true) + end + end + end + end + + describe "#spans" do + context "when no spans were captured" do + it "returns an empty hash" do + expect(subject.spans).to eq({}) + end + end + + context "when a span was captured" do + before do + subject.start_span('operation') + subject.stop_span('operation') + end + + it "returns a Hash with the corresponding span" do + subject.stop_span('operation') + expect(subject.spans).to match('operation' => be > 0) + end + end + + context "when multiple spans were captured" do + before do + subject.start_span('operation') + subject.stop_span('operation') + + subject.start_span('another operation') + subject.stop_span('another operation') + end + + it "returns a Hash with all spans" do + expect(subject.spans).to match( + 'operation' => be > 0, + 'another operation' => be > 0 + ) + end + end + end +end