Add stackprof based profiler

CHANGELOG.md

@@ -7,15 +7,52 @@
   - `config.enable_tracing = false` will turn off tracing even if `traces_sample_rate/traces_sampler` is set
   - `config.enable_tracing = nil` (default) will keep the current behaviour
 - Allow ignoring `excluded_exceptions` when manually capturing exceptions [#2007](https://github.com/getsentry/sentry-ruby/pull/2007)
+
   Users can now ignore the SDK's `excluded_exceptions` by passing `ignore_exclusions` hint when using `Sentry.capture_exception`.
 
   ```rb
   # assume ignored_exception.class is included in config.excluded_exception
   Sentry.capture_exception(ignored_exception) # won't be sent to Sentry
   Sentry.capture_exception(ignored_exception, hint: { ignore_exclusions: true }) # will be sent to Sentry
   ```
+
 - Add `spec` to `Backtrace::APP_DIRS_PATTERN` [#2029](https://github.com/getsentry/sentry-ruby/pull/2029)
 - Forward all `baggage` header items that are prefixed with `sentry-` [#2025](https://github.com/getsentry/sentry-ruby/pull/2025)
+- Add `stackprof` based profiler [#2024](https://github.com/getsentry/sentry-ruby/pull/2024)
+
+  The SDK now supports sending profiles taken by the [`stackprof` gem](https://github.com/tmm1/stackprof) and viewing them in the [Profiling](https://docs.sentry.io/product/profiling/) section.
+
+  To use it, first add `stackprof` to your `Gemfile` and make sure it is loaded before `sentry-ruby`.
+
+  ```ruby
+  # Gemfile
+
+  gem 'stackprof'
+  gem 'sentry-ruby'
+  ```
+
+  Then, make sure both `traces_sample_rate` and `profiles_sample_rate` are set and non-zero in your sentry initializer.
+
+  ```ruby
+  # config/initializers/sentry.rb
+
+  Sentry.init do |config|
+    config.dsn = "<dsn>"
+    config.traces_sample_rate = 1.0
+    config.profiles_sample_rate = 1.0
+  end
+  ```
+
+  Some implementation caveats:
+  - Profiles are sampled **relative** to traces, so if both rates are 0.5, we will capture 0.25 of all requests.
+  - Profiles are only captured for code running within a transaction.
+  - Profiles for multi-threaded servers like `puma` might not capture frames correctly when async I/O is happening. This is a `stackprof` limitation.
+
+  <br />
+
+  > **Warning**
+  > Profiling is currently in beta. Beta features are still in-progress and may have bugs. We recognize the irony.
+  > If you have any questions or feedback, please email us at profiling@sentry.io, reach out via Discord (#profiling), or open an issue.
 
 ### Bug Fixes
 

sentry-ruby/Gemfile

@@ -17,6 +17,7 @@ gem "timecop"
 gem "simplecov"
 gem "simplecov-cobertura", "~> 1.4"
 gem "rexml"
+gem "stackprof" unless RUBY_PLATFORM == "java"
 
 gem "object_tracer"
 gem "debug", github: "ruby/debug", platform: :ruby if RUBY_VERSION.to_f >= 2.6

sentry-ruby/lib/sentry/configuration.rb

@@ -245,6 +245,12 @@ def capture_exception_frame_locals=(value)
     # @return [Symbol]
     attr_reader :instrumenter
 
+    # Take a float between 0.0 and 1.0 as the sample rate for capturing profiles.
+    # Note that this rate is relative to traces_sample_rate / traces_sampler,
+    # i.e. the profile is sampled by this rate after the transaction is sampled.
+    # @return [Float, nil]
+    attr_reader :profiles_sample_rate
+
     # these are not config options
     # @!visibility private
     attr_reader :errors, :gem_specs
@@ -395,6 +401,11 @@ def enable_tracing=(enable_tracing)
       @traces_sample_rate ||= 1.0 if enable_tracing
     end
 
+    def profiles_sample_rate=(profiles_sample_rate)
+      log_info("Please make sure to include the 'stackprof' gem in your Gemfile to use Profiling with Sentry.") unless defined?(StackProf)
+      @profiles_sample_rate = profiles_sample_rate
+    end
+
     def sending_allowed?
       @errors = []
 
@@ -433,6 +444,14 @@ def tracing_enabled?
       (@enable_tracing != false) && valid_sampler && sending_allowed?
     end
 
+    def profiling_enabled?
+      valid_sampler = !!(@profiles_sample_rate &&
+                         @profiles_sample_rate >= 0.0 &&
+                         @profiles_sample_rate <= 1.0)
+
+      tracing_enabled? && valid_sampler && sending_allowed?
+    end
+
     # @return [String, nil]
     def csp_report_uri
       if dsn && dsn.valid?

sentry-ruby/lib/sentry/envelope.rb

@@ -19,10 +19,7 @@ def type
       end
 
       def to_s
-        <<~ITEM
-          #{JSON.generate(@headers)}
-          #{JSON.generate(@payload)}
-        ITEM
+        [JSON.generate(@headers), JSON.generate(@payload)].join("\n")
       end
 
       def serialize

sentry-ruby/lib/sentry/hub.rb

@@ -88,8 +88,10 @@ def start_transaction(transaction: nil, custom_sampling_context: {}, instrumente
       }
 
       sampling_context.merge!(custom_sampling_context)
-
       transaction.set_initial_sample_decision(sampling_context: sampling_context)
+
+      transaction.start_profiler!
+
       transaction
     end
 

sentry-ruby/lib/sentry/profiler.rb

@@ -0,0 +1,222 @@
+# frozen_string_literal: true
+
+require 'securerandom'
+
+module Sentry
+  class Profiler
+    VERSION = '1'
+    PLATFORM = 'ruby'
+    # 101 Hz in microseconds
+    DEFAULT_INTERVAL = 1e6 / 101
+    MICRO_TO_NANO_SECONDS = 1e3
+
+    attr_reader :sampled, :started, :event_id
+
+    def initialize(configuration)
+      @event_id = SecureRandom.uuid.delete('-')
+      @started = false
+      @sampled = nil
+
+      @profiling_enabled = defined?(StackProf) && configuration.profiling_enabled?
+      @profiles_sample_rate = configuration.profiles_sample_rate
+      @project_root = configuration.project_root
+      @app_dirs_pattern = configuration.app_dirs_pattern || Backtrace::APP_DIRS_PATTERN
+      @in_app_pattern = Regexp.new("^(#{@project_root}/)?#{@app_dirs_pattern}")
+    end
+
+    def start
+      return unless @sampled
+
+      @started = StackProf.start(interval: DEFAULT_INTERVAL,
+                                 mode: :wall,
+                                 raw: true,
+                                 aggregate: false)
+
+      @started ? log('Started') : log('Not started since running elsewhere')
+    end
+
+    def stop
+      return unless @sampled
+      return unless @started
+
+      StackProf.stop
+      log('Stopped')
+    end
+
+    # Sets initial sampling decision of the profile.
+    # @return [void]
+    def set_initial_sample_decision(transaction_sampled)
+      unless @profiling_enabled
+        @sampled = false
+        return
+      end
+
+      unless transaction_sampled
+        @sampled = false
+        log('Discarding profile because transaction not sampled')
+        return
+      end
+
+      case @profiles_sample_rate
+      when 0.0
+        @sampled = false
+        log('Discarding profile because sample_rate is 0')
+        return
+      when 1.0
+        @sampled = true
+        return
+      else
+        @sampled = Random.rand < @profiles_sample_rate
+      end
+
+      log('Discarding profile due to sampling decision') unless @sampled
+    end
+
+    def to_hash
+      return {} unless @sampled
+      return {} unless @started
+
+      results = StackProf.results
+      return {} unless results
+      return {} if results.empty?
+      return {} if results[:samples] == 0
+      return {} unless results[:raw]
+
+      frame_map = {}
+
+      frames = results[:frames].to_enum.with_index.map do |frame, idx|
+        frame_id, frame_data = frame
+
+        # need to map over stackprof frame ids to ours
+        frame_map[frame_id] = idx
+
+        file_path = frame_data[:file]
+        in_app = in_app?(file_path)
+        filename = compute_filename(file_path, in_app)
+        function, mod = split_module(frame_data[:name])
+
+        frame_hash = {
+          abs_path: file_path,
+          function: function,
+          filename: filename,
+          in_app: in_app
+        }
+
+        frame_hash[:module] = mod if mod
+        frame_hash[:lineno] = frame_data[:line] if frame_data[:line]
+
+        frame_hash
+      end
+
+      idx = 0
+      stacks = []
+      num_seen = []
+
+      # extract stacks from raw
+      # raw is a single array of [.., len_stack, *stack_frames(len_stack), num_stack_seen , ..]
+      while (len = results[:raw][idx])
+        idx += 1
+
+        # our call graph is reversed
+        stack = results[:raw].slice(idx, len).map { |id| frame_map[id] }.compact.reverse
+        stacks << stack
+
+        num_seen << results[:raw][idx + len]
+        idx += len + 1
+
+        log('Unknown frame in stack') if stack.size != len
+      end
+
+      idx = 0
+      elapsed_since_start_ns = 0
+      samples = []
+
+      num_seen.each_with_index do |n, i|
+        n.times do
+          # stackprof deltas are in microseconds
+          delta = results[:raw_timestamp_deltas][idx]
+          elapsed_since_start_ns += (delta * MICRO_TO_NANO_SECONDS).to_i
+          idx += 1
+
+          # Not sure why but some deltas are very small like 0/1 values,
+          # they pollute our flamegraph so just ignore them for now.
+          # Open issue at https://github.com/tmm1/stackprof/issues/201
+          next if delta < 10
+
+          samples << {
+            stack_id: i,
+            # TODO-neel-profiler we need to patch rb_profile_frames and write our own C extension to enable threading info.
+            # Till then, on multi-threaded servers like puma, we will get frames from other active threads when the one
+            # we're profiling is idle/sleeping/waiting for IO etc.
+            # https://bugs.ruby-lang.org/issues/10602
+            thread_id: '0',
+            elapsed_since_start_ns: elapsed_since_start_ns.to_s
+          }
+        end
+      end
+
+      log('Some samples thrown away') if samples.size != results[:samples]
+
+      if samples.size <= 2
+        log('Not enough samples, discarding profiler')
+        return {}
+      end
+
+      profile = {
+        frames: frames,
+        stacks: stacks,
+        samples: samples
+      }
+
+      {
+        event_id: @event_id,
+        platform: PLATFORM,
+        version: VERSION,
+        profile: profile
+      }
+    end
+
+    private
+
+    def log(message)
+      Sentry.logger.debug(LOGGER_PROGNAME) { "[Profiler] #{message}" }
+    end
+
+    def in_app?(abs_path)
+      abs_path.match?(@in_app_pattern)
+    end
+
+    # copied from stacktrace.rb since I don't want to touch existing code
+    # TODO-neel-profiler try to fetch this from stackprof once we patch
+    # the native extension
+    def compute_filename(abs_path, in_app)
+      return nil if abs_path.nil?
+
+      under_project_root = @project_root && abs_path.start_with?(@project_root)
+
+      prefix =
+        if under_project_root && in_app
+          @project_root
+        else
+          longest_load_path = $LOAD_PATH.select { |path| abs_path.start_with?(path.to_s) }.max_by(&:size)
+
+          if under_project_root
+            longest_load_path || @project_root
+          else
+            longest_load_path
+          end
+        end
+
+      prefix ? abs_path[prefix.to_s.chomp(File::SEPARATOR).length + 1..-1] : abs_path
+    end
+
+    def split_module(name)
+      # last module plus class/instance method
+      i = name.rindex('::')
+      function = i ? name[(i + 2)..-1] : name
+      mod = i ? name[0...i] : nil
+
+      [function, mod]
+    end
+  end
+end

sentry-ruby/lib/sentry/scope.rb

@@ -309,7 +309,8 @@ def os_context
               name: uname[:sysname] || RbConfig::CONFIG["host_os"],
               version: uname[:version],
               build: uname[:release],
-              kernel_version: uname[:version]
+              kernel_version: uname[:version],
+              machine: uname[:machine]
             }
           end
       end