Support profiling with vernier

Gemfile

@@ -18,3 +18,4 @@ gem "rubyzip"
 gem "sidekiq"
 gem "sorbet", require: false
 gem "tapioca", require: false
+gem "vernier"

Gemfile.lock

@@ -243,6 +243,7 @@ GEM
     unicode-emoji (4.2.0)
     uri (1.1.1)
     useragent (0.16.11)
+    vernier (1.11.0)
     zeitwerk (2.8.3)
 
 PLATFORMS
@@ -266,6 +267,7 @@ DEPENDENCIES
   singed!
   sorbet
   tapioca
+  vernier
 
 BUNDLED WITH
   4.0.15

README.md

@@ -1,6 +1,6 @@
 # Singed
 
-Singed makes it easy to get a flamegraph anywhere in your code base. It wraps profiling your code with [stackprof](https://github.com/tmm1/stackprof) or [rbspy](https://github.com/rbspy/rbspy), and then launching [speedscope](https://github.com/jlfwong/speedscope) to view it.
+Singed makes it easy to get a flamegraph anywhere in your code base. It wraps profiling your code with [stackprof](https://github.com/tmm1/stackprof), [vernier](https://github.com/jhawthorn/vernier) or [rbspy](https://github.com/rbspy/rbspy), and then launching [speedscope](https://github.com/jlfwong/speedscope) to view it.
 
 ## Installation
 
@@ -66,6 +66,40 @@ flamegraph.open
 
 Note that `Singed.start` can't be run multiple times in parallel, instantiate multiple `Singed::Flamegraph` objects instead and call `start` on them.
 
+### Vernier
+
+Singed profiles with stackprof by default. [Vernier](https://github.com/jhawthorn/vernier) profiles each thread separately instead, so a flamegraph from a multi-threaded app like Puma or Sidekiq isn't a mix of what all its threads were doing. Singed doesn't depend on vernier, so add it (1.5 or newer) to your Gemfile:
+
+```ruby
+gem "vernier"
+```
+
+Then ask for it when capturing a flamegraph. `Singed.start` and controllers' `flamegraph` take `profiler:` too:
+
+```ruby
+flamegraph(profiler: :vernier) {
+  # your code here
+}
+```
+
+Or make it the default, which the RSpec, controller, Rack and Sidekiq integrations below then use as well:
+
+```ruby
+Singed.profiler = :vernier
+```
+
+That loads vernier straight away, so a missing or outdated gem fails at boot. If vernier is only in some of your Gemfile's groups, set this only in the environments that load them, e.g. in `config/environments/development.rb`.
+
+speedscope then gets a profile per thread, and opens on the thread that ran your code. Pick another thread from its title bar, or step through them with `n` and `p`. Vernier keeps sampling threads that are waiting, so their stacks end in `(idle)` while sleeping or waiting on I/O or a lock, and in `(waiting for GVL)` while another thread holds the GVL.
+
+Vernier doesn't sample a thread while it's running garbage collection, so `ignore_gc` makes no difference with it. The `singed` command line always uses rbspy.
+
+The flamegraph's `profile` is Vernier's own result, which you can also save for [vernier.prof](https://vernier.prof) to show GVL and GC activity alongside the flamegraph:
+
+```ruby
+Singed.stop.profile.write(out: "tmp/profile.vernier.json.gz")
+```
+
 ### RSpec
 
 If you are using RSpec, you can use the `flamegraph` metadata to capture it for you.
@@ -173,3 +207,4 @@ The `open` command is expected to be available.
 
 - using [rbspy](https://rbspy.github.io/) directly
 - using [stackprof](https://github.com/tmm1/stackprof) (a dependency of singed) directly
+- using [vernier](https://github.com/jhawthorn/vernier) directly

lib/singed.rb

@@ -33,6 +33,18 @@ def enabled?
     @enabled = true
   end
 
+  # Which profiler records flamegraphs that aren't given one: :stackprof or :vernier.
+  #: (Symbol) -> void
+  def profiler=(profiler)
+    Flamegraph.load_profiler(profiler)
+    @profiler = profiler #: Symbol?
+  end
+
+  #: () -> Symbol
+  def profiler
+    @profiler || :stackprof
+  end
+
   # Not ActiveSupport::BacktraceCleaner: apps' Tapioca evaluates these sigs even when ActiveSupport isn't loaded.
   #: (untyped) -> void
   def backtrace_cleaner=(backtrace_cleaner)
@@ -60,12 +72,12 @@ def filter_line(line)
     line
   end
 
-  #: (?String?, ?ignore_gc: bool, ?interval: Integer) -> Flamegraph?
-  def start(label = nil, ignore_gc: false, interval: 1000)
+  #: (?String?, ?ignore_gc: bool, ?interval: Integer, ?profiler: Symbol?) -> Flamegraph?
+  def start(label = nil, ignore_gc: false, interval: 1000, profiler: nil)
     return unless enabled?
     return if profiling?
 
-    @current_flamegraph = Flamegraph.new(label:, ignore_gc:, interval:)
+    @current_flamegraph = Flamegraph.new(label:, ignore_gc:, interval:, profiler:)
     @current_flamegraph.tap(&:start)
   end
 
@@ -90,6 +102,7 @@ def profiling?
   autoload :Report, "singed/report"
   autoload :RackMiddleware, "singed/rack_middleware"
   autoload :Speedscope, "singed/speedscope"
+  autoload :VernierReport, "singed/vernier_report"
 end
 
 require "singed/kernel_ext"

lib/singed/controller_ext.rb

@@ -11,10 +11,10 @@ module ControllerExt
     # @requires_ancestor: AbstractController::Callbacks::ClassMethods
     module ClassMethods
       # Define an around_action to generate flamegraph for a controller action.
-      #: (Symbol | String | Array[Symbol | String], ?ignore_gc: bool, ?interval: Integer) -> void
-      def flamegraph(target_action, ignore_gc: false, interval: 1000)
+      #: (Symbol | String | Array[Symbol | String], ?ignore_gc: bool, ?interval: Integer, ?profiler: Symbol?) -> void
+      def flamegraph(target_action, ignore_gc: false, interval: 1000, profiler: nil)
         around_action(only: target_action) do |controller, action|
-          controller.flamegraph(ignore_gc:, interval:, &action)
+          controller.flamegraph(ignore_gc:, interval:, profiler:, &action)
         end
       end
     end

lib/singed/flamegraph.rb

@@ -3,15 +3,24 @@
 
 module Singed
   class Flamegraph
-    # The StackProf.results hash; its values vary by key.
-    #: Hash[Symbol, untyped]?
+    PROFILERS = [:stackprof, :vernier].freeze
+    # The first with Vernier::Result#stack_table.
+    MINIMUM_VERNIER_VERSION = "1.5"
+
+    # The StackProf.results hash, whose values vary by key, or a Vernier::Result when profiling with Vernier.
+    # Not typed as Vernier::Result: apps' Tapioca evaluates this sig even when Vernier isn't loaded.
+    #: untyped
     attr_accessor :profile
 
     #: Pathname
     attr_accessor :filename
 
-    #: (?label: String?, ?ignore_gc: bool, ?interval: Integer, ?filename: Pathname?) -> void
-    def initialize(label: nil, ignore_gc: false, interval: 1000, filename: nil)
+    # nil when wrapping an existing file.
+    #: Symbol?
+    attr_reader :profiler
+
+    #: (?label: String?, ?ignore_gc: bool, ?interval: Integer, ?profiler: Symbol?, ?filename: Pathname?) -> void
+    def initialize(label: nil, ignore_gc: false, interval: 1000, profiler: nil, filename: nil)
       # it's been created elsewhere, ie rbspy
       if filename
         if ignore_gc
@@ -22,9 +31,17 @@ def initialize(label: nil, ignore_gc: false, interval: 1000, filename: nil)
           raise ArgumentError, "label not supported when given an existing file"
         end
 
+        if profiler
+          raise ArgumentError, "profiler not supported when given an existing file"
+        end
+
         @filename = filename #: Pathname
       else
+        profiler ||= Singed.profiler
+        self.class.load_profiler(profiler)
+
         # Nilable because they stay unset when wrapping an existing file, and #start still reads them.
+        @profiler = profiler #: Symbol?
         @ignore_gc = ignore_gc #: bool?
         @interval = interval #: Integer?
         @time = Time.now #: Time
@@ -46,17 +63,28 @@ def start
       return false if filename.exist? # file existing means its been captured already
       return false if started?
 
-      StackProf.start(mode: :wall, raw: true, ignore_gc: @ignore_gc, interval: @interval)
+      if vernier?
+        # A collector per flamegraph, rather than Vernier.start_profile, which raises if a profile is already running.
+        # There's no ignore_gc to pass: Vernier doesn't sample a thread while it's running GC.
+        @collector = Vernier::Collector.new(:wall, interval: @interval) #: untyped
+        @collector.start
+      else
+        StackProf.start(mode: :wall, raw: true, ignore_gc: @ignore_gc, interval: @interval)
+      end
       @started = true
     end
 
-    #: () -> Hash[Symbol, untyped]?
+    #: () -> untyped
     def stop
       return nil unless started?
 
       @started = false #: bool?
-      StackProf.stop
-      @profile = StackProf.results
+      if vernier?
+        @profile = @collector.stop
+      else
+        StackProf.stop
+        @profile = StackProf.results
+      end
     end
 
     #: () -> bool
@@ -70,8 +98,12 @@ def save
         raise ArgumentError, "File #{filename} already exists"
       end
 
-      report = Singed::Report.new(@profile)
-      report.filter!
+      if vernier?
+        report = Singed::VernierReport.new(@profile)
+      else
+        report = Singed::Report.new(@profile)
+        report.filter!
+      end
       filename.dirname.mkpath
       filename.open("w") { |f| report.print_json(f) }
     end
@@ -99,5 +131,34 @@ def self.generate_filename(label: nil, time: Time.now)
       file = file.relative_path_from(pwd) if file.absolute? && file.to_s.start_with?(pwd.to_s)
       file
     end
+
+    # Raises unless Singed supports the profiler. Requires vernier, which Singed doesn't depend on, when it's the one asked for.
+    #: (Symbol) -> void
+    def self.load_profiler(profiler)
+      unless PROFILERS.include?(profiler)
+        raise ArgumentError, "Unsupported profiler #{profiler.inspect}, expected one of #{PROFILERS.inspect}"
+      end
+      return unless profiler == :vernier
+
+      begin
+        require "vernier"
+      rescue LoadError => e
+        # Other paths mean vernier is installed but broken, e.g. its native extension didn't load.
+        raise unless e.path == "vernier"
+
+        raise LoadError, "Profiling with vernier needs the vernier gem in your bundle (#{e.message})"
+      end
+
+      if Gem::Version.new(Vernier::VERSION) < Gem::Version.new(MINIMUM_VERNIER_VERSION)
+        raise LoadError, "Profiling with vernier needs vernier #{MINIMUM_VERNIER_VERSION} or newer, not #{Vernier::VERSION}"
+      end
+    end
+
+    private
+
+    #: () -> bool
+    def vernier?
+      @profiler == :vernier
+    end
   end
 end

lib/singed/kernel_ext.rb

@@ -7,10 +7,11 @@ module Kernel
   #|   ?open: bool,
   #|   ?ignore_gc: bool,
   #|   ?interval: Integer,
+  #|   ?profiler: Symbol?,
   #|   ?io: IO | StringIO
   #| ) { () -> Result } -> Result
-  def flamegraph(label = nil, open: true, ignore_gc: false, interval: 1000, io: $stdout, &block)
-    fg = Singed::Flamegraph.new(label:, ignore_gc:, interval:)
+  def flamegraph(label = nil, open: true, ignore_gc: false, interval: 1000, profiler: nil, io: $stdout, &block) # rubocop:disable Metrics/ParameterLists -- all optional keywords
+    fg = Singed::Flamegraph.new(label:, ignore_gc:, interval:, profiler:)
     result = fg.record(&block)
     fg.save
 

lib/singed/vernier_report.rb

@@ -0,0 +1,122 @@
+# typed: strict
+# frozen_string_literal: true
+
+module Singed
+  # Converts a Vernier::Result to speedscope's file format, with a profile for each thread:
+  # https://github.com/jlfwong/speedscope/blob/v1.24.0/src/lib/file-format-spec.ts
+  class VernierReport
+    # Vernier keeps sampling threads that are waiting, and categorizes those samples. Topping their
+    # stacks with one of these frames keeps waiting from reading as time spent running Ruby code.
+    CATEGORY_FRAMES = {
+      1 => { name: "(idle)" }, # sleeping, or waiting on I/O or a lock
+      2 => { name: "(waiting for GVL)" }, # ready to run, but another thread holds the GVL
+    }.freeze #: Hash[Integer, Hash[Symbol, String]]
+
+    # Not Vernier::Result: apps' Tapioca evaluates these sigs even when Vernier isn't loaded.
+    #: (untyped) -> void
+    def initialize(result)
+      @result = result
+      @frames = [] #: Array[Hash[Symbol, untyped]]
+      @func_frame_indexes = {} #: Hash[Integer, Integer]
+      @category_frame_indexes = {} #: Hash[Integer, Integer]
+      @stacks = {} #: Hash[[Integer, Integer], Array[Integer]]
+    end
+
+    #: (IO | StringIO) -> void
+    def print_json(io)
+      io.write(JSON.generate(to_h))
+    end
+
+    #: () -> Hash[Symbol, untyped]
+    def to_h
+      interval = @result.meta.fetch(:interval)
+      # Threads that never ran while profiling have no samples, so would only add empty profiles.
+      threads = @result.threads.values.select { |thread| thread[:is_start] || thread[:samples].any? }
+      profiles = threads.map { |thread| profile(thread, interval) }
+
+      {
+        "$schema": "https://www.speedscope.app/file-format-schema.json",
+        shared: { frames: @frames },
+        profiles:,
+        # The thread that started profiling is the one that ran the profiled code.
+        activeProfileIndex: threads.index { |thread| thread[:is_start] },
+      }
+    end
+
+    private
+
+    #: (Hash[Symbol, untyped], Integer) -> Hash[Symbol, untyped]
+    def profile(thread, interval)
+      samples = thread[:samples].zip(thread[:sample_categories]).map do |stack_idx, category|
+        stack(stack_idx, category)
+      end
+      # Vernier merges consecutive samples of the same stack into one, counting them in its weight.
+      weights = thread[:weights].map { |weight| weight * interval }
+
+      {
+        type: "sampled",
+        name: utf8(thread[:name]),
+        unit: "microseconds",
+        startValue: 0,
+        endValue: weights.sum,
+        samples:,
+        weights:,
+      }
+    end
+
+    # Vernier links each stack to its parent, but speedscope lists a stack's frames from the root.
+    #: (Integer, Integer) -> Array[Integer]
+    def stack(stack_idx, category)
+      @stacks[[stack_idx, category]] ||= begin
+        frames = [] #: Array[Integer]
+        idx = stack_idx #: Integer?
+        while idx
+          frames << func_frame_index(stack_table.frame_func_idx(stack_table.stack_frame_idx(idx)))
+          idx = stack_table.stack_parent_idx(idx)
+        end
+        frames.reverse!
+        frames << category_frame_index(category) if CATEGORY_FRAMES.key?(category)
+        frames
+      end
+    end
+
+    # One frame per method rather than per line, so each method is a single box in the flamegraph.
+    #: (Integer) -> Integer
+    def func_frame_index(func_idx)
+      @func_frame_indexes[func_idx] ||= begin
+        frame = {
+          name: utf8(stack_table.func_name(func_idx)),
+          file: Singed.filter_line(utf8(stack_table.func_filename(func_idx))),
+        } #: Hash[Symbol, untyped]
+        line = stack_table.func_first_lineno(func_idx)
+        frame[:line] = line if line.positive? # C functions have no line
+        add_frame(frame)
+      end
+    end
+
+    #: (Integer) -> Integer
+    def category_frame_index(category)
+      @category_frame_indexes[category] ||= add_frame(CATEGORY_FRAMES.fetch(category))
+    end
+
+    #: (Hash[Symbol, untyped]) -> Integer
+    def add_frame(frame)
+      @frames << frame
+      @frames.size - 1
+    end
+
+    # JSON needs valid UTF-8. Vernier guesses its stack table's strings are UTF-8, so they may need scrubbing:
+    # https://github.com/jhawthorn/vernier/blob/v1.11.0/ext/vernier/stack_table.cc#L179-L191
+    # It names threads that have no name after Thread#inspect, which is binary.
+    #: (String) -> String
+    def utf8(string)
+      string = string.dup.force_encoding(Encoding::UTF_8) if string.encoding == Encoding::BINARY
+      string.scrub
+    end
+
+    #: () -> untyped
+    def stack_table
+      @result.stack_table
+    end
+  end
+end