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

sl0thentr0py · sl0thentr0py · commit 8909e8692e74 · 2024-03-12T15:42:47.000+01:00
diff --git a/CHANGELOG.md b/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))
diff --git a/sentry-ruby/lib/sentry/metrics.rb b/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
diff --git a/sentry-ruby/lib/sentry/metrics/aggregator.rb b/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
diff --git a/sentry-ruby/lib/sentry/metrics/configuration.rb b/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
diff --git a/sentry-ruby/spec/sentry/metrics/aggregator_spec.rb b/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, :pre_context, :context_line, :post_context, :lineno)
+
+          location_2 = mapping['d:dis_t@second'].first
+          expect(location_2[:type]).to eq('location')
+          expect(location_2).to include(:abs_path, :filename, :pre_context, :context_line, :post_context, :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
diff --git a/sentry-ruby/spec/sentry/metrics_spec.rb b/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
