Merge remote-tracking branch 'origin/master' into neel/metrics/code-l…

…ocations

CHANGELOG.md

@@ -10,6 +10,7 @@
  - Add `Sentry::Metrics.timing` API for measuring block duration [#2254](https://github.com/getsentry/sentry-ruby/pull/2254)
  - Add metric summaries on spans [#2255](https://github.com/getsentry/sentry-ruby/pull/2255)
  - Add `config.metrics.before_emit` callback [#2258](https://github.com/getsentry/sentry-ruby/pull/2258)
+ - Add code locations for metrics [#2263](https://github.com/getsentry/sentry-ruby/pull/2263)
 
  The SDK now supports recording and aggregating metrics. A new thread will be started
  for aggregation and will flush the pending data to Sentry every 5 seconds.
@@ -45,11 +46,14 @@
  Sentry::Metrics.timing('how_long') { sleep(1) }
  # timing - measure duration of code block in other duraton units
  Sentry::Metrics.timing('how_long_ms', unit: 'millisecond') { sleep(0.5) }
+ ```
+
+ You can filter some keys or update tags on the fly with the `before_emit` callback, which will be triggered before a metric is aggregated.
 
- # add a before_emit callback to filter keys or update tags
+ ```ruby
  Sentry.init do |config|
  # ...
- config.metrics.enabled = true
+ # the 'foo' metric will be filtered and the tags will be updated to add :bar and remove :baz
  config.metrics.before_emit = lambda do |key, tags|
  return nil if key == 'foo'
  tags[:bar] = 42
@@ -59,6 +63,16 @@
  end
  ```
 
+ By default, the SDK will send code locations for unique metrics (defined by type, key and unit) once a day and with every startup/shutdown of your application.
+ You can turn this off with the following:
+
+ ```ruby
+ Sentry.init do |config|
+ # ...
+ config.metrics.enable_code_locations = false
+ end
+ ```
+
 ### Bug Fixes
 
 - Fix undefined method 'constantize' issue in `sentry-resque` ([#2248](https://github.com/getsentry/sentry-ruby/pull/2248))

sentry-ruby/lib/sentry/metrics.rb

@@ -35,17 +35,20 @@ def gauge(key, value, unit: 'none', tags: {}, timestamp: nil)
 
  def timing(key, unit: 'second', tags: {}, timestamp: nil, &block)
  return unless block_given?
- return unless DURATION_UNITS.include?(unit)
+ return yield unless DURATION_UNITS.include?(unit)
 
- Sentry.with_child_span(op: OP_NAME, description: key) do |span|
+ result, value = Sentry.with_child_span(op: OP_NAME, description: key) do |span|
  tags.each { |k, v| span.set_tag(k, v.is_a?(Array) ? v.join(', ') : v.to_s) } if span
 
  start = Timing.send(unit.to_sym)
- yield
+ result = yield
  value = Timing.send(unit.to_sym) - start
 
- Sentry.metrics_aggregator&.add(:d, key, value, unit: unit, tags: tags, timestamp: timestamp)
+ [result, value]
  end
+
+ Sentry.metrics_aggregator&.add(:d, key, value, unit: unit, tags: tags, timestamp: timestamp)
+ result
  end
  end
  end

sentry-ruby/lib/sentry/metrics/aggregator.rb

@@ -23,7 +23,7 @@ class Aggregator
  }
 
  # exposed only for testing
- attr_reader :thread, :buckets, :flush_shift
+ attr_reader :thread, :buckets, :flush_shift, :code_locations
 
  def initialize(configuration, client)
  @client = client
@@ -55,7 +55,8 @@ def add(type,
  value,
  unit: 'none',
  tags: {},
- timestamp: nil)
+ timestamp: nil,
+ stacklevel: nil)
  return unless ensure_thread
  return unless METRIC_TYPES.keys.include?(type)
 
@@ -72,7 +73,7 @@ def add(type,
  bucket_key = [type, key, unit, serialized_tags]
 
  added = @mutex.synchronize do
- record_code_location(type, key, unit, timestamp) if @enable_code_locations
+ record_code_location(type, key, unit, timestamp, stacklevel: stacklevel) if @enable_code_locations
  process_bucket(bucket_timestamp, bucket_key, type, value)
  end
 
@@ -247,13 +248,12 @@ def process_bucket(timestamp, key, type, value)
  end
  end
 
- # TODO-neel-metrics stacklevel
- def record_code_location(type, key, unit, timestamp)
+ def record_code_location(type, key, unit, timestamp, stacklevel: nil)
  meta_key = [type, key, unit]
  start_of_day = Time.utc(timestamp.year, timestamp.month, timestamp.day).to_i
 
  @code_locations[start_of_day] ||= {}
- @code_locations[start_of_day][meta_key] ||= @stacktrace_builder.metrics_code_location(caller[DEFAULT_STACKLEVEL])
+ @code_locations[start_of_day][meta_key] ||= @stacktrace_builder.metrics_code_location(caller[stacklevel || DEFAULT_STACKLEVEL])
  end
  end
  end

sentry-ruby/lib/sentry/metrics/configuration.rb

@@ -42,6 +42,12 @@ def before_emit=(value)
 
  @before_emit = value
  end
+
+ def before_emit=(value)
+ check_callable!("metrics.before_emit", value)
+
+ @before_emit = value
+ end
  end
  end
 end

sentry-ruby/spec/sentry/metrics/aggregator_spec.rb

@@ -270,10 +270,58 @@
  end
  end
  end
+
+ describe 'code location reporting' do
+ it 'does not record location if off' do
+ perform_basic_setup do |config|
+ config.metrics.enabled = true
+ config.metrics.enable_code_locations = false
+ end
+
+ subject.add(:c, 'incr', 1)
+ expect(subject.code_locations).to eq({})
+ end
+
+ it 'records the code location with a timestamp for the day' do
+ subject.add(:c, 'incr', 1, unit: 'second', stacklevel: 3)
+
+ timestamp = Time.now.utc
+ start_of_day = Time.utc(timestamp.year, timestamp.month, timestamp.day).to_i
+ expect(subject.code_locations.keys.first).to eq(start_of_day)
+ end
+
+ it 'has the code location keyed with mri (metric resource identifier) from type/key/unit' do
+ subject.add(:c, 'incr', 1, unit: 'second', stacklevel: 3)
+ mri = subject.code_locations.values.first.keys.first
+ expect(mri).to eq([:c, 'incr', 'second'])
+ end
+
+ it 'has the code location information in the hash' do
+ subject.add(:c, 'incr', 1, unit: 'second', stacklevel: 3)
+
+ location = subject.code_locations.values.first.values.first
+ expect(location).to include(:abs_path, :filename, :pre_context, :context_line, :post_context, :lineno)
+ expect(location[:abs_path]).to match(/aggregator_spec.rb/)
+ expect(location[:filename]).to match(/aggregator_spec.rb/)
+ expect(location[:context_line]).to include("subject.add(:c, 'incr', 1, unit: 'second', stacklevel: 3)")
+ end
+
+ it 'does not add code location for the same mri twice' do
+ subject.add(:c, 'incr', 1, unit: 'second', stacklevel: 3)
+ subject.add(:c, 'incr', 1, unit: 'second', stacklevel: 3)
+ expect(subject.code_locations.values.first.size).to eq(1)
+ end
+
+ it 'adds code location for different mris twice' do
+ subject.add(:c, 'incr', 1, unit: 'second', stacklevel: 3)
+ subject.add(:c, 'incr', 1, unit: 'none', stacklevel: 3)
+ expect(subject.code_locations.values.first.size).to eq(2)
+ end
+ end
  end
 
  describe '#flush' do
- context 'with empty buckets' do
+ context 'with empty buckets and empty locations' do
  it 'returns early and does nothing' do
  expect(sentry_envelopes.count).to eq(0)
  subject.flush
@@ -289,11 +337,11 @@
  before do
  allow(Time).to receive(:now).and_return(fake_time)
  10.times { subject.add(:c, 'incr', 1) }
- 5.times { |i| subject.add(:d, 'dist', i, unit: 'second', tags: { "foö$-bar" => "snöwmän% 23{}" }) }
+ 5.times { |i| subject.add(:d, 'disöt', i, unit: 'second', tags: { "foö$-bar" => "snöwmän% 23{}" }) }
 
  allow(Time).to receive(:now).and_return(fake_time + 9)
  5.times { subject.add(:c, 'incr', 1) }
- 5.times { |i| subject.add(:d, 'dist', i + 5, unit: 'second', tags: { "foö$-bar" => "snöwmän% 23{}" }) }
+ 5.times { |i| subject.add(:d, 'disöt', i + 5, unit: 'second', tags: { "foö$-bar" => "snöwmän% 23{}" }) }
 
  expect(subject.buckets.keys).to eq([fake_time.to_i - 3, fake_time.to_i + 7])
  expect(subject.buckets.values[0].length).to eq(2)
@@ -311,6 +359,11 @@
  expect(subject.buckets.values[0].length).to eq(2)
  end
 
+ it 'empties the pending code locations in place' do
+ subject.flush
+ expect(subject.code_locations).to eq({})
+ end
+
  it 'calls the background worker' do
  expect(Sentry.background_worker).to receive(:perform)
  subject.flush
@@ -327,10 +380,32 @@
 
  incr, dist = item.payload.split("\n")
  expect(incr).to eq("incr@none:10.0|c|#environment:test,release:test-release|T#{fake_time.to_i - 3}")
- expect(dist).to eq("dist@second:0.0:1.0:2.0:3.0:4.0|d|" +
+ expect(dist).to eq("dis_t@second:0.0:1.0:2.0:3.0:4.0|d|" +
  "#environment:test,fo_-bar:snöwmän 23{},release:test-release|" +
  "T#{fake_time.to_i - 3}")
  end
+
+ it 'sends the pending code locations in metric_meta envelope item with correct payload' do
+ subject.flush
+
+ envelope = sentry_envelopes.first
+ expect(envelope.headers).to eq({})
+
+ item = envelope.items.last
+ expect(item.headers).to eq({ type: 'metric_meta', content_type: 'application/json' })
+ expect(item.payload[:timestamp]).to be_a(Integer)
+
+ mapping = item.payload[:mapping]
+ expect(mapping.keys).to eq(['c:incr@none', 'd:dis_t@second'])
+
+ location_1 = mapping['c:incr@none'].first
+ expect(location_1[:type]).to eq('location')
+ expect(location_1).to include(:abs_path, :filename, :lineno)
+
+ location_2 = mapping['d:dis_t@second'].first
+ expect(location_2[:type]).to eq('location')
+ expect(location_2).to include(:abs_path, :filename, :lineno)
+ end
  end
 
  context 'with force' do
@@ -355,11 +430,11 @@
 
  incr1, dist1, incr2, dist2 = item.payload.split("\n")
  expect(incr1).to eq("incr@none:10.0|c|#environment:test,release:test-release|T#{fake_time.to_i - 3}")
- expect(dist1).to eq("dist@second:0.0:1.0:2.0:3.0:4.0|d|" +
+ expect(dist1).to eq("dis_t@second:0.0:1.0:2.0:3.0:4.0|d|" +
  "#environment:test,fo_-bar:snöwmän 23{},release:test-release|" +
  "T#{fake_time.to_i - 3}")
  expect(incr2).to eq("incr@none:5.0|c|#environment:test,release:test-release|T#{fake_time.to_i + 7}")
- expect(dist2).to eq("dist@second:5.0:6.0:7.0:8.0:9.0|d|" +
+ expect(dist2).to eq("dis_t@second:5.0:6.0:7.0:8.0:9.0|d|" +
  "#environment:test,fo_-bar:snöwmän 23{},release:test-release|" +
  "T#{fake_time.to_i + 7}")
  end

sentry-ruby/spec/sentry/metrics_spec.rb

@@ -91,7 +91,8 @@
 
  it 'does nothing with a non-duration unit' do
  expect(aggregator).not_to receive(:add)
- described_class.timing('foo', unit: 'ratio') { }
+ result = described_class.timing('foo', unit: 'ratio') { 42 }
+ expect(result).to eq(42)
  end
 
  it 'measures time taken as distribution and passes through args to aggregator' do
@@ -104,7 +105,8 @@
  timestamp: fake_time
  )
 
- described_class.timing('foo', unit: 'millisecond', tags: { fortytwo: 42 }, timestamp: fake_time) { sleep(0.1) }
+ result = described_class.timing('foo', unit: 'millisecond', tags: { fortytwo: 42 }, timestamp: fake_time) { sleep(0.1); 42 }
+ expect(result).to eq(42)
  end
 
  context 'with running transaction' do