From c1425c5cc5cf1c494bfa9b7bb5195b7d02821fad Mon Sep 17 00:00:00 2001 From: Kyrylo Silin Date: Thu, 19 Dec 2019 16:50:35 +0800 Subject: [PATCH] Deprecate :{start,end}_time, add :timing instead There are a few reasons for this change: 1. We use realtime to measure performance for the `:total` stat. This is no good, especially since we use monotonic time for other groups. It is inconsitent and confusing 2. New functionality requires a better API. Specifically, we want to be able to send timing of a certain job. To achieve that we wrap the job in a benchmark `measure` call. The problem is that our API doesn't make it easy to send already calculated timing. `start_time` makes the user code very clunky and confusing Before: ``` start_time = Time.now calculate_operation Airbrake.notify_request( ..., start_time: start_time, end_time: Time.now, ) ``` After: ``` timing = Airbrake::Benchmark.measure do calculate_operation end Airbrake.notify_request( ..., timing: timing, ) ``` --- README.md | 8 +- lib/airbrake-ruby.rb | 49 +++++------ lib/airbrake-ruby/benchmark.rb | 2 +- lib/airbrake-ruby/performance_breakdown.rb | 17 ++-- lib/airbrake-ruby/performance_notifier.rb | 15 +++- lib/airbrake-ruby/query.rb | 18 ++-- lib/airbrake-ruby/queue.rb | 20 +++-- lib/airbrake-ruby/request.rb | 20 +++-- spec/performance_notifier_spec.rb | 98 ++++++++++++++-------- 9 files changed, 150 insertions(+), 97 deletions(-) diff --git a/README.md b/README.md index 7e0738bc..fe5b3d35 100644 --- a/README.md +++ b/README.md @@ -737,8 +737,7 @@ Airbrake.notify_request( method: 'GET', route: '/things/1', status_code: 200, - start_time: Time.new - 200, - end_time: Time.new + timing: 123.45 # ms ) ``` @@ -792,8 +791,7 @@ Airbrake.notify_query( func: 'foo', # optional file: 'foo.rb', # optional line: 123, # optional - start_time: Time.new - 200, - end_time: Time.new # optional + timing: 123.45 # ms ) ``` @@ -844,7 +842,7 @@ Airbrake.notify_performance_breakdown( route: '/things/1', response_type: 'json', groups: { db: 24.0, view: 0.4 }, # ms - start_time: Time.new + timing: 123.45 # ms ) ``` diff --git a/lib/airbrake-ruby.rb b/lib/airbrake-ruby.rb index 760a9830..ea12f38f 100644 --- a/lib/airbrake-ruby.rb +++ b/lib/airbrake-ruby.rb @@ -328,9 +328,8 @@ def merge_context(context) notice_notifier.merge_context(context) end - # Increments request statistics of a certain +route+ that was invoked on - # +start_time+ and ended on +end_time+ with +method+, and returned - # +status_code+. + # Increments request statistics of a certain +route+ invoked with +method+, + # which returned +status_code+. # # After a certain amount of time (n seconds) the aggregated route # information will be sent to Airbrake. @@ -343,8 +342,7 @@ def merge_context(context) # func: 'do_stuff', # file: 'app/models/foo.rb', # line: 452, - # start_time: timestamp, - # end_time: Time.now + # timing: 123.45 # ms # ) # # @param [Hash{Symbol=>Object}] request_info @@ -358,8 +356,8 @@ def merge_context(context) # called the query (optional) # @option request_info [Integer] :line The line that executes the query # (optional) - # @option request_info [Date] :start_time When the request started - # @option request_info [Time] :end_time When the request ended (optional) + # @option request_info [Float] :timing How much time it took to process the + # request (in ms) # @param [Hash] stash What needs to be appeneded to the stash, so it's # available in filters # @return [void] @@ -371,9 +369,8 @@ def notify_request(request_info, stash = {}) performance_notifier.notify(request) end - # Synchronously Increments request statistics of a certain +route+ that was - # invoked on +start_time+ and ended on +end_time+ with +method+, and - # returned +status_code+. + # Synchronously increments request statistics of a certain +route+ invoked + # with +method+, which returned +status_code+. # @since v4.10.0 # @see .notify_request def notify_request_sync(request_info, stash = {}) @@ -382,9 +379,8 @@ def notify_request_sync(request_info, stash = {}) performance_notifier.notify_sync(request) end - # Increments SQL statistics of a certain +query+ that was invoked on - # +start_time+ and finished on +end_time+. When +method+ and +route+ are - # provided, the query is grouped by these parameters. + # Increments SQL statistics of a certain +query+. When +method+ and +route+ + # are provided, the query is grouped by these parameters. # # After a certain amount of time (n seconds) the aggregated query # information will be sent to Airbrake. @@ -394,18 +390,17 @@ def notify_request_sync(request_info, stash = {}) # method: 'GET', # route: '/things', # query: 'SELECT * FROM things', - # start_time: timestamp, - # end_time: Time.now + # timing: 123.45 # ms # ) # # @param [Hash{Symbol=>Object}] query_info - # @option request_info [String] :method The HTTP method that triggered this + # @option query_info [String] :method The HTTP method that triggered this # SQL query (optional) - # @option request_info [String] :route The route that triggered this SQL + # @option query_info [String] :route The route that triggered this SQL # query (optional) - # @option request_info [String] :query The query that was executed - # @option request_info [Date] :start_time When the query started executing - # @option request_info [Time] :end_time When the query finished (optional) + # @option query_info [String] :query The query that was executed + # @option query_info [Float] :timing How much time it took to process the + # query (in ms) # @param [Hash] stash What needs to be appeneded to the stash, so it's # available in filters # @return [void] @@ -417,9 +412,9 @@ def notify_query(query_info, stash = {}) performance_notifier.notify(query) end - # Synchronously increments SQL statistics of a certain +query+ that was - # invoked on +start_time+ and finished on +end_time+. When +method+ and - # +route+ are provided, the query is grouped by these parameters. + # Synchronously increments SQL statistics of a certain +query+. When + # +method+ and +route+ are provided, the query is grouped by these + # parameters. # @since v4.10.0 # @see .notify_query def notify_query_sync(query_info, stash = {}) @@ -436,8 +431,7 @@ def notify_query_sync(query_info, stash = {}) # route: '/thing/:id/create', # response_type: 'json', # groups: { db: 24.0, view: 0.4 }, # ms - # start_time: timestamp, - # end_time: Time.now + # timing: 123.45 # ms # ) # # @param [Hash{Symbol=>Object}] breakdown_info @@ -445,7 +439,8 @@ def notify_query_sync(query_info, stash = {}) # @option breakdown_info [String] :route # @option breakdown_info [String] :response_type # @option breakdown_info [ArrayFloat}>] :groups - # @option breakdown_info [Date] :start_time + # @option breakdown_info [Float] :timing How much time it took to process + # the performance breakdown (in ms) # @param [Hash] stash What needs to be appeneded to the stash, so it's # available in filters # @return [void] @@ -481,6 +476,8 @@ def notify_performance_breakdown_sync(breakdown_info, stash = {}) # failed # @option queue_info [ArrayFloat}>] :groups Where the job # spent its time + # @option breakdown_info [Float] :timing How much time it took to process + # the queue (in ms) # @param [Hash] stash What needs to be appended to the stash, so it's # available in filters # @return [void] diff --git a/lib/airbrake-ruby/benchmark.rb b/lib/airbrake-ruby/benchmark.rb index 7eecb8fb..1d213793 100644 --- a/lib/airbrake-ruby/benchmark.rb +++ b/lib/airbrake-ruby/benchmark.rb @@ -2,7 +2,7 @@ module Airbrake # Benchmark benchmarks Ruby code. # # @since v4.2.4 - # @api private + # @api public class Benchmark # Measures monotonic time for the given operation. # diff --git a/lib/airbrake-ruby/performance_breakdown.rb b/lib/airbrake-ruby/performance_breakdown.rb index 45ff7d48..05c28aa6 100644 --- a/lib/airbrake-ruby/performance_breakdown.rb +++ b/lib/airbrake-ruby/performance_breakdown.rb @@ -7,7 +7,8 @@ module Airbrake # @since v4.2.0 # rubocop:disable Metrics/BlockLength, Metrics/ParameterLists PerformanceBreakdown = Struct.new( - :method, :route, :response_type, :groups, :start_time, :end_time + :method, :route, :response_type, :groups, :start_time, :end_time, :timing, + :time ) do include HashKeyable include Ignorable @@ -19,11 +20,15 @@ def initialize( route:, response_type:, groups:, - start_time:, - end_time: start_time + 1 + start_time: Time.now, + end_time: start_time + 1, + timing: nil, + time: Time.now ) - @start_time_utc = TimeTruncate.utc_truncate_minutes(start_time) - super(method, route, response_type, groups, start_time, end_time) + @time_utc = TimeTruncate.utc_truncate_minutes(time) + super( + method, route, response_type, groups, start_time, end_time, timing, time + ) end def destination @@ -39,7 +44,7 @@ def to_h 'method' => method, 'route' => route, 'responseType' => response_type, - 'time' => @start_time_utc, + 'time' => @time_utc, }.delete_if { |_key, val| val.nil? } end end diff --git a/lib/airbrake-ruby/performance_notifier.rb b/lib/airbrake-ruby/performance_notifier.rb index bc8aeb31..faf448cb 100644 --- a/lib/airbrake-ruby/performance_notifier.rb +++ b/lib/airbrake-ruby/performance_notifier.rb @@ -62,7 +62,7 @@ def update_payload(resource) @payload[resource] = { total: Airbrake::Stat.new } end - @payload[resource][:total].increment(resource.start_time, resource.end_time) + update_total(resource, @payload[resource][:total]) resource.groups.each do |name, ms| @payload[resource][name] ||= Airbrake::Stat.new @@ -70,6 +70,19 @@ def update_payload(resource) end end + def update_total(resource, total) + if resource.timing + total.increment_ms(resource.timing) + else + loc = caller_locations(6..6).first + Kernel.warn( + "#{loc.path}:#{loc.lineno}: warning: :start_time and :end_time are " \ + "deprecated. Use :timing & :time instead", + ) + total.increment(resource.start_time, resource.end_time) + end + end + def schedule_flush return if @payload.empty? diff --git a/lib/airbrake-ruby/query.rb b/lib/airbrake-ruby/query.rb index 843d34e8..edc23752 100644 --- a/lib/airbrake-ruby/query.rb +++ b/lib/airbrake-ruby/query.rb @@ -6,7 +6,8 @@ module Airbrake # @since v3.2.0 # rubocop:disable Metrics/ParameterLists, Metrics/BlockLength Query = Struct.new( - :method, :route, :query, :func, :file, :line, :start_time, :end_time + :method, :route, :query, :func, :file, :line, :start_time, :end_time, + :timing, :time ) do include HashKeyable include Ignorable @@ -21,11 +22,16 @@ def initialize( func: nil, file: nil, line: nil, - start_time:, - end_time: start_time + 1 + start_time: Time.now, + end_time: start_time + 1, + timing: nil, + time: Time.now ) - @start_time_utc = TimeTruncate.utc_truncate_minutes(start_time) - super(method, route, query, func, file, line, start_time, end_time) + @time_utc = TimeTruncate.utc_truncate_minutes(time) + super( + method, route, query, func, file, line, start_time, end_time, timing, + time + ) end def destination @@ -41,7 +47,7 @@ def to_h 'method' => method, 'route' => route, 'query' => query, - 'time' => @start_time_utc, + 'time' => @time_utc, 'function' => func, 'file' => file, 'line' => line, diff --git a/lib/airbrake-ruby/queue.rb b/lib/airbrake-ruby/queue.rb index fea775fd..7b298fca 100644 --- a/lib/airbrake-ruby/queue.rb +++ b/lib/airbrake-ruby/queue.rb @@ -4,8 +4,10 @@ module Airbrake # @see Airbrake.notify_queue # @api public # @since v4.9.0 - # rubocop:disable Metrics/BlockLength - Queue = Struct.new(:queue, :error_count, :groups, :start_time, :end_time) do + # rubocop:disable Metrics/BlockLength, Metrics/ParameterLists + Queue = Struct.new( + :queue, :error_count, :groups, :start_time, :end_time, :timing, :time + ) do include HashKeyable include Ignorable include Stashable @@ -15,10 +17,12 @@ def initialize( error_count:, groups: {}, start_time: Time.now, - end_time: start_time + 1 + end_time: start_time + 1, + timing: nil, + time: Time.now ) - @start_time_utc = TimeTruncate.utc_truncate_minutes(start_time) - super(queue, error_count, groups, start_time, end_time) + @time_utc = TimeTruncate.utc_truncate_minutes(time) + super(queue, error_count, groups, start_time, end_time, timing, time) end def destination @@ -33,14 +37,14 @@ def to_h { 'queue' => queue, 'errorCount' => error_count, - 'time' => @start_time_utc, + 'time' => @time_utc, } end def hash { 'queue' => queue, - 'time' => @start_time_utc, + 'time' => @time_utc, }.hash end @@ -48,5 +52,5 @@ def merge(other) self.error_count += other.error_count end end - # rubocop:enable Metrics/BlockLength + # rubocop:enable Metrics/BlockLength, Metrics/ParameterLists end diff --git a/lib/airbrake-ruby/request.rb b/lib/airbrake-ruby/request.rb index 17e50f83..d19cf0ba 100644 --- a/lib/airbrake-ruby/request.rb +++ b/lib/airbrake-ruby/request.rb @@ -4,8 +4,10 @@ module Airbrake # @see Airbrake.notify_request # @api public # @since v3.2.0 - # rubocop:disable Metrics/BlockLength - Request = Struct.new(:method, :route, :status_code, :start_time, :end_time) do + # rubocop:disable Metrics/BlockLength, Metrics/ParameterLists + Request = Struct.new( + :method, :route, :status_code, :start_time, :end_time, :timing, :time + ) do include HashKeyable include Ignorable include Stashable @@ -16,11 +18,13 @@ def initialize( method:, route:, status_code:, - start_time:, - end_time: start_time + 1 + start_time: Time.now, + end_time: start_time + 1, + timing: nil, + time: Time.now ) - @start_time_utc = TimeTruncate.utc_truncate_minutes(start_time) - super(method, route, status_code, start_time, end_time) + @time_utc = TimeTruncate.utc_truncate_minutes(time) + super(method, route, status_code, start_time, end_time, timing, time) end def destination @@ -36,9 +40,9 @@ def to_h 'method' => method, 'route' => route, 'statusCode' => status_code, - 'time' => @start_time_utc, + 'time' => @time_utc, }.delete_if { |_key, val| val.nil? } end end - # rubocop:enable Metrics/BlockLength + # rubocop:enable Metrics/BlockLength, Metrics/ParameterLists end diff --git a/spec/performance_notifier_spec.rb b/spec/performance_notifier_spec.rb index d0bd9254..9ebde68f 100644 --- a/spec/performance_notifier_spec.rb +++ b/spec/performance_notifier_spec.rb @@ -29,8 +29,8 @@ func: 'foo', file: 'foo.rb', line: 123, - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), - end_time: Time.new(2018, 1, 1, 0, 50, 0, 0), + timing: 60000, + time: Time.new(2018, 1, 1, 0, 49, 0, 0), ), ) subject.close @@ -59,8 +59,8 @@ method: 'POST', route: '/foo', status_code: 200, - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), - end_time: Time.new(2018, 1, 1, 0, 50, 0, 0), + timing: 60000, + time: Time.new(2018, 1, 1, 0, 49, 0, 0), ), ) subject.close @@ -86,8 +86,8 @@ method: 'DELETE', route: '/routes-breakdowns', response_type: 'json', - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), - end_time: Time.new(2018, 1, 1, 0, 50, 0, 0), + timing: 60000, + time: Time.new(2018, 1, 1, 0, 49, 0, 0), groups: { db: 131, view: 421 }, ), ) @@ -128,8 +128,8 @@ queue: 'emails', error_count: 2, groups: { redis: 131, sql: 421 }, - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), - end_time: Time.new(2018, 1, 1, 0, 50, 0, 0), + timing: 60000, + time: Time.new(2018, 1, 1, 0, 49, 0, 0), ), ) subject.close @@ -168,7 +168,8 @@ method: 'GET', route: '/foo', status_code: 200, - start_time: Time.new(2018, 1, 1, 0, 0, 20, 0), + timing: 60000, + time: Time.new(2018, 1, 1, 0, 0, 20, 0), ), ) subject.close @@ -184,7 +185,7 @@ method: 'GET', route: '/foo', status_code: 200, - start_time: Time.new(2018, 1, 1, 0, 0, 20, 0), + timing: 213, ), ) subject.notify( @@ -192,7 +193,7 @@ method: 'GET', route: '/foo', status_code: 200, - start_time: Time.new(2018, 1, 1, 0, 0, 50, 0), + timing: 123, ), ) subject.close @@ -208,8 +209,8 @@ method: 'GET', route: '/foo', status_code: 200, - start_time: Time.new(2018, 1, 1, 0, 0, 49, 0), - end_time: Time.new(2018, 1, 1, 0, 0, 50, 0), + timing: 1000, + time: Time.new(2018, 1, 1, 0, 0, 49, 0), ), ) subject.notify( @@ -217,8 +218,8 @@ method: 'GET', route: '/foo', status_code: 200, - start_time: Time.new(2018, 1, 1, 0, 1, 49, 0), - end_time: Time.new(2018, 1, 1, 0, 1, 55, 0), + timing: 6000, + time: Time.new(2018, 1, 1, 0, 1, 49, 0), ), ) subject.close @@ -244,8 +245,8 @@ method: 'GET', route: '/foo', status_code: 200, - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), - end_time: Time.new(2018, 1, 1, 0, 50, 0, 0), + timing: 60000, + time: Time.new(2018, 1, 1, 0, 49, 0, 0), ), ) subject.notify( @@ -253,8 +254,8 @@ method: 'POST', route: '/foo', status_code: 200, - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), - end_time: Time.new(2018, 1, 1, 0, 50, 0, 0), + timing: 60000, + time: Time.new(2018, 1, 1, 0, 49, 0, 0), ), ) subject.close @@ -280,8 +281,8 @@ method: 'DELETE', route: '/routes-breakdowns', response_type: 'json', - start_time: Time.new(2018, 1, 1, 0, 0, 20, 0), - end_time: Time.new(2018, 1, 1, 0, 0, 22, 0), + timing: 2000, + time: Time.new(2018, 1, 1, 0, 0, 20, 0), groups: { db: 131, view: 421 }, ), ) @@ -290,8 +291,8 @@ method: 'DELETE', route: '/routes-breakdowns', response_type: 'json', - start_time: Time.new(2018, 1, 1, 0, 0, 30, 0), - end_time: Time.new(2018, 1, 1, 0, 0, 32, 0), + timing: 2000, + time: Time.new(2018, 1, 1, 0, 0, 30, 0), groups: { db: 55, view: 11 }, ), ) @@ -332,8 +333,8 @@ queue: 'emails', error_count: 2, groups: { redis: 131, sql: 421 }, - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), - end_time: Time.new(2018, 1, 1, 0, 50, 0, 0), + timing: 60000, + time: Time.new(2018, 1, 1, 0, 49, 0, 0), ), ) subject.notify( @@ -341,8 +342,8 @@ queue: 'emails', error_count: 3, groups: { redis: 131, sql: 421 }, - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), - end_time: Time.new(2018, 1, 1, 0, 50, 0, 0), + timing: 60000, + time: Time.new(2018, 1, 1, 0, 49, 0, 0), ), ) subject.close @@ -381,7 +382,7 @@ method: 'GET', route: '/foo', status_code: 200, - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), + timing: 123, ), ) subject.close @@ -392,7 +393,7 @@ it "checks performance stat configuration" do request = Airbrake::Request.new( - method: 'GET', route: '/foo', status_code: 200, start_time: Time.new, + method: 'GET', route: '/foo', status_code: 200, timing: 123, ) expect(Airbrake::Config.instance).to receive(:check_performance_options) .with(request).and_return(Airbrake::Promise.new) @@ -408,7 +409,7 @@ method: 'POST', route: '/foo', status_code: 200, - start_time: Time.new, + timing: 123, ), ) subject.close @@ -445,7 +446,7 @@ method: 'GET', route: '/foo', status_code: 200, - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), + timing: 123, ), ) @@ -454,7 +455,7 @@ method: 'POST', route: '/foo', query: 'SELECT * FROM things', - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), + timing: 123, ), ) @@ -510,7 +511,7 @@ method: 'POST', route: '/foo', query: 'SELECT * FROM things', - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), + timing: 123, ), ) subject.close @@ -522,6 +523,31 @@ ).to have_been_made end end + + context "when :start_time is specified (deprecated)" do + before do + allow(Kernel).to receive(:warn) + end + + it "uses the value of :start_time to update stat" do + subject.notify( + Airbrake::Query.new( + method: 'POST', + route: '/foo', + query: 'SELECT * FROM things', + start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), + end_time: Time.new(2018, 1, 1, 0, 50, 0, 0), + ), + ) + subject.close + + expect( + a_request(:put, queries).with( + body: /"count":1,"sum":60000.0,"sumsq":3600000000.0/, + ), + ).to have_been_made + end + end end describe "#notify_sync" do @@ -531,7 +557,7 @@ method: 'POST', route: '/foo', query: 'SELECT * FROM things', - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), + timing: 123, ), ) @@ -560,7 +586,7 @@ method: 'POST', route: '/foo', query: 'SELECT * FROM things', - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), + timing: 123, ), ) subject.close @@ -591,7 +617,7 @@ def call(resource); end method: 'POST', route: '/foo', status_code: 200, - start_time: Time.new(2018, 1, 1, 0, 49, 0, 0), + timing: 123, ), ) subject.close