Merge pull request #476 from airbrake/custom-performance-group

Add TimedTrace

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

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
 ----------------
 

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

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

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 [Hash<String=>Float>]
+    def spans
+      @spans.each_with_object({}) do |(label, benchmark), new_spans|
+        new_spans[label] = benchmark.duration
+      end
+    end
+  end
+end

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

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