Add metrics code locations (#2263)

* sent once a day or once per application run on that day
* sent as separate json envelope item `metric_meta`
* controlled with `config.metrics.enable_code_locations`, defaults to true

part of #2246

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/backtrace.rb

@@ -35,7 +35,7 @@ class Line
       # Parses a single line of a given backtrace
       # @param [String] unparsed_line The raw line from +caller+ or some backtrace
       # @return [Line] The parsed backtrace line
-      def self.parse(unparsed_line, in_app_pattern)
+      def self.parse(unparsed_line, in_app_pattern = nil)
         ruby_match = unparsed_line.match(RUBY_INPUT_FORMAT)
         if ruby_match
           _, file, number, _, method = ruby_match.to_a
@@ -57,6 +57,8 @@ def initialize(file, number, method, module_name, in_app_pattern)
       end
 
       def in_app
+        return false unless in_app_pattern
+
         if file =~ in_app_pattern
           true
         else

sentry-ruby/lib/sentry/interfaces/stacktrace_builder.rb

@@ -62,6 +62,14 @@ def build(backtrace:, &frame_callback)
       StacktraceInterface.new(frames: frames)
     end
 
+    # Get the code location hash for a single line for where metrics where added.
+    # @return [Hash]
+    def metrics_code_location(unparsed_line)
+      parsed_line = Backtrace::Line.parse(unparsed_line)
+      frame = convert_parsed_line_into_frame(parsed_line)
+      frame.to_hash.reject { |k, _| %i[project_root in_app].include?(k) }
+    end
+
     private
 
     def convert_parsed_line_into_frame(line)

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

@@ -8,6 +8,10 @@ class Aggregator
       FLUSH_INTERVAL = 5
       ROLLUP_IN_SECONDS = 10
 
+      # this is how far removed from user code in the backtrace we are
+      # when we record code locations
+      DEFAULT_STACKLEVEL = 4
+
       KEY_SANITIZATION_REGEX = /[^a-zA-Z0-9_\/.-]+/
       VALUE_SANITIZATION_REGEX = /[^[[:word:]][[:digit:]][[:space:]]_:\/@\.{}\[\]$-]+/
 
@@ -19,12 +23,14 @@ 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
         @logger = configuration.logger
         @before_emit = configuration.metrics.before_emit
+        @enable_code_locations = configuration.metrics.enable_code_locations
+        @stacktrace_builder = configuration.stacktrace_builder
 
         @default_tags = {}
         @default_tags['release'] = configuration.release if configuration.release
@@ -34,47 +40,41 @@ def initialize(configuration, client)
         @exited = false
         @mutex = Mutex.new
 
-        # buckets are a nested hash of timestamp -> bucket keys -> Metric instance
+        # a nested hash of timestamp -> bucket keys -> Metric instance
         @buckets = {}
 
         # the flush interval needs to be shifted once per startup to create jittering
         @flush_shift = Random.rand * ROLLUP_IN_SECONDS
+
+        # a nested hash of timestamp (start of day) -> meta keys -> frame
+        @code_locations = {}
       end
 
       def add(type,
               key,
               value,
               unit: 'none',
               tags: {},
-              timestamp: nil)
+              timestamp: nil,
+              stacklevel: nil)
         return unless ensure_thread
         return unless METRIC_TYPES.keys.include?(type)
 
-        timestamp = timestamp.to_i if timestamp.is_a?(Time)
-        timestamp ||= Sentry.utc_now.to_i
+        updated_tags = get_updated_tags(tags)
+        return if @before_emit && !@before_emit.call(key, updated_tags)
+
+        timestamp ||= Sentry.utc_now
 
         # this is integer division and thus takes the floor of the division
         # and buckets into 10 second intervals
-        bucket_timestamp = (timestamp / ROLLUP_IN_SECONDS) * ROLLUP_IN_SECONDS
-        updated_tags = get_updated_tags(tags)
-
-        return if @before_emit && !@before_emit.call(key, updated_tags)
+        bucket_timestamp = (timestamp.to_i / ROLLUP_IN_SECONDS) * ROLLUP_IN_SECONDS
 
         serialized_tags = serialize_tags(updated_tags)
         bucket_key = [type, key, unit, serialized_tags]
 
         added = @mutex.synchronize do
-          @buckets[bucket_timestamp] ||= {}
-
-          if (metric = @buckets[bucket_timestamp][bucket_key])
-            old_weight = metric.weight
-            metric.add(value)
-            metric.weight - old_weight
-          else
-            metric = METRIC_TYPES[type].new(value)
-            @buckets[bucket_timestamp][bucket_key] = metric
-            metric.weight
-          end
+          record_code_location(type, key, unit, timestamp, stacklevel: stacklevel) if @enable_code_locations
+          process_bucket(bucket_timestamp, bucket_key, type, value)
         end
 
         # for sets, we pass on if there was a new entry to the local gauge
@@ -84,14 +84,28 @@ def add(type,
 
       def flush(force: false)
         flushable_buckets = get_flushable_buckets!(force)
-        return if flushable_buckets.empty?
+        code_locations = get_code_locations!
+        return if flushable_buckets.empty? && code_locations.empty?
 
-        payload = serialize_buckets(flushable_buckets)
         envelope = Envelope.new
-        envelope.add_item(
-          { type: 'statsd', length: payload.bytesize },
-          payload
-        )
+
+        unless flushable_buckets.empty?
+          payload = serialize_buckets(flushable_buckets)
+          envelope.add_item(
+            { type: 'statsd', length: payload.bytesize },
+            payload
+          )
+        end
+
+        unless code_locations.empty?
+          code_locations.each do |timestamp, locations|
+            payload = serialize_locations(timestamp, locations)
+            envelope.add_item(
+              { type: 'metric_meta', content_type: 'application/json' },
+              payload
+            )
+          end
+        end
 
         Sentry.background_worker.perform do
           @client.transport.send_envelope(envelope)
@@ -154,6 +168,14 @@ def get_flushable_buckets!(force)
         end
       end
 
+      def get_code_locations!
+        @mutex.synchronize do
+          code_locations = @code_locations
+          @code_locations = {}
+          code_locations
+        end
+      end
+
       # serialize buckets to statsd format
       def serialize_buckets(buckets)
         buckets.map do |timestamp, timestamp_buckets|
@@ -167,6 +189,18 @@ def serialize_buckets(buckets)
         end.flatten.join("\n")
       end
 
+      def serialize_locations(timestamp, locations)
+        mapping = locations.map do |meta_key, location|
+          type, key, unit = meta_key
+          mri = "#{type}:#{sanitize_key(key)}@#{unit}"
+
+          # note this needs to be an array but it really doesn't serve a purpose right now
+          [mri, [location.merge(type: 'location')]]
+        end.to_h
+
+        { timestamp: timestamp, mapping: mapping }
+      end
+
       def sanitize_key(key)
         key.gsub(KEY_SANITIZATION_REGEX, '_')
       end
@@ -199,6 +233,28 @@ def process_span_aggregator(key, value)
 
         scope.span.metrics_local_aggregator.add(key, value)
       end
+
+      def process_bucket(timestamp, key, type, value)
+        @buckets[timestamp] ||= {}
+
+        if (metric = @buckets[timestamp][key])
+          old_weight = metric.weight
+          metric.add(value)
+          metric.weight - old_weight
+        else
+          metric = METRIC_TYPES[type].new(value)
+          @buckets[timestamp][key] = metric
+          metric.weight
+        end
+      end
+
+      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[stacklevel || DEFAULT_STACKLEVEL])
+      end
     end
   end
 end

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

@@ -5,12 +5,18 @@ module Metrics
     class Configuration
       include ArgumentCheckingHelper
 
-      # Enable metrics usage
+      # Enable metrics usage.
       # Starts a new {Sentry::Metrics::Aggregator} instance to aggregate metrics
       # and a thread to aggregate flush every 5 seconds.
       # @return [Boolean]
       attr_accessor :enabled
 
+      # Enable code location reporting.
+      # Will be sent once per day.
+      # True by default.
+      # @return [Boolean]
+      attr_accessor :enable_code_locations
+
       # Optional Proc, called before emitting a metric to the aggregator.
       # Use it to filter keys (return false/nil) or update tags.
       # Make sure to return true at the end.
@@ -28,6 +34,7 @@ class Configuration
 
       def initialize
         @enabled = false
+        @enable_code_locations = true
       end
 
       def before_emit=(value)

sentry-ruby/spec/sentry/interfaces/stacktrace_builder_spec.rb

@@ -1,26 +1,26 @@
 require 'spec_helper'
 
 RSpec.describe Sentry::StacktraceBuilder do
-  describe "#build" do
-    let(:fixture_root) { File.join(Dir.pwd, "spec", "support") }
-    let(:fixture_file) { File.join(fixture_root, "stacktrace_test_fixture.rb") }
-    let(:configuration) do
-      Sentry::Configuration.new.tap do |config|
-        config.project_root = fixture_root
-      end
+  let(:fixture_root) { File.join(Dir.pwd, "spec", "support") }
+  let(:fixture_file) { File.join(fixture_root, "stacktrace_test_fixture.rb") }
+  let(:configuration) do
+    Sentry::Configuration.new.tap do |config|
+      config.project_root = fixture_root
     end
+  end
 
-    let(:backtrace) do
-      [
-        "#{fixture_file}:6:in `bar'",
-        "#{fixture_file}:2:in `foo'"
-      ]
-    end
+  let(:backtrace) do
+    [
+      "#{fixture_file}:6:in `bar'",
+      "#{fixture_file}:2:in `foo'"
+    ]
+  end
 
-    subject do
-      configuration.stacktrace_builder
-    end
+  subject do
+    configuration.stacktrace_builder
+  end
 
+  describe "#build" do
     it "ignores frames without filename" do
       interface = subject.build(backtrace: [":6:in `foo'"])
       expect(interface.frames).to be_empty
@@ -82,4 +82,17 @@
       end
     end
   end
+
+  describe '#metrics_code_location' do
+    it 'builds metrics code location hash for line' do
+      hash = subject.metrics_code_location(backtrace.first)
+
+      expect(hash[:filename]).to match(/stacktrace_test_fixture.rb/)
+      expect(hash[:function]).to eq("bar")
+      expect(hash[:lineno]).to eq(6)
+      expect(hash[:pre_context]).to eq(["end\n", "\n", "def bar\n"])
+      expect(hash[:context_line]).to eq("  baz\n")
+      expect(hash[:post_context]).to eq(["end\n", nil, nil])
+    end
+  end
 end