diff --git a/CHANGELOG.md b/CHANGELOG.md index a5ffc0b6f..0310ac9a5 100644 --- 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/backtrace.rb b/sentry-ruby/lib/sentry/backtrace.rb index 23ac75648..b7ebb2159 100644 --- a/sentry-ruby/lib/sentry/backtrace.rb +++ b/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 diff --git a/sentry-ruby/lib/sentry/interfaces/stacktrace_builder.rb b/sentry-ruby/lib/sentry/interfaces/stacktrace_builder.rb index af247e02e..5edac90c5 100644 --- a/sentry-ruby/lib/sentry/interfaces/stacktrace_builder.rb +++ b/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) diff --git a/sentry-ruby/lib/sentry/metrics.rb b/sentry-ruby/lib/sentry/metrics.rb index 83048420e..e67fc769f 100644 --- 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 index 18b1af8f7..4624a3559 100644 --- a/sentry-ruby/lib/sentry/metrics/aggregator.rb +++ b/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,11 +40,14 @@ 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, @@ -46,35 +55,26 @@ def add(type, 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 diff --git a/sentry-ruby/lib/sentry/metrics/configuration.rb b/sentry-ruby/lib/sentry/metrics/configuration.rb index e45b43bd5..84681f31e 100644 --- a/sentry-ruby/lib/sentry/metrics/configuration.rb +++ b/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) diff --git a/sentry-ruby/spec/sentry/interfaces/stacktrace_builder_spec.rb b/sentry-ruby/spec/sentry/interfaces/stacktrace_builder_spec.rb index d1cc5257a..637aff2ad 100644 --- a/sentry-ruby/spec/sentry/interfaces/stacktrace_builder_spec.rb +++ b/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 diff --git a/sentry-ruby/spec/sentry/metrics/aggregator_spec.rb b/sentry-ruby/spec/sentry/metrics/aggregator_spec.rb index 1edbfe215..9a6de80fb 100644 --- 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, :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 diff --git a/sentry-ruby/spec/sentry/metrics_spec.rb b/sentry-ruby/spec/sentry/metrics_spec.rb index 094aee347..42d9ad754 100644 --- 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