Add GVL/allocation instrumentation and optional log fields

Gemfile

@@ -11,6 +11,7 @@ gem "ci-helper"
 gem "click_house", github: "umbrellio/click_house", branch: "master"
 gem "clickhouse-native"
 gem "csv"
+gem "gvltools"
 gem "http"
 gem "net-pop"
 gem "nokogiri"

Gemfile.lock

@@ -11,7 +11,7 @@ GIT
 PATH
   remote: .
   specs:
-    umbrellio-utils (1.14.3)
+    umbrellio-utils (1.15.0)
       memery (~> 1)
 
 GEM
@@ -139,6 +139,7 @@ GEM
       net-http (~> 0.5)
     globalid (1.3.0)
       activesupport (>= 6.1)
+    gvltools (0.5.0)
     http (6.0.3)
       http-cookie (~> 1.0)
       llhttp (~> 0.6.1)
@@ -415,6 +416,7 @@ DEPENDENCIES
   click_house!
   clickhouse-native
   csv
+  gvltools
   http
   net-pop
   nokogiri

README.md

@@ -115,6 +115,32 @@ end
 Utils::Constants.useful_method #=> "Just string"
 ```
 
+### Instrumentation
+
+The gem ships a set of opt-in files for collecting GVL and allocation stats
+(they are not loaded by default and require the `gvltools` gem in your app):
+
+```ruby
+# Extends ActiveSupport::Notifications::Event with #gvl_time and #malloc_increase_bytes
+require "umbrellio_utils/patches/active_support_event"
+
+# Enriches the "Completed" action controller log entry (rails_semantic_logger)
+# with GC, GVL and allocation stats
+require "umbrellio_utils/patches/rails_semantic_logger"
+
+# Logs Sidekiq job completion with the same stats. Relies on the
+# "perform.sidekiq_job" notification published by the umbrellio fork of yabeda-sidekiq
+require "umbrellio_utils/semantic_logger/sidekiq_job_metrics"
+UmbrellioUtils::SemanticLogger::SidekiqJobMetrics.subscribe!
+```
+
+Don't forget to enable the GVL timer as early as possible (e.g. right after
+`Bundler.require` in `config/application.rb`):
+
+```ruby
+GVLTools::LocalTimer.enable
+```
+
 ## Contributing
 
 Bug reports and pull requests are welcome on GitHub at https://github.com/umbrellio/utils.

lib/umbrellio_utils/patches/active_support_event.rb

@@ -0,0 +1,64 @@
+# frozen_string_literal: true
+
+require "gvltools"
+require "active_support/notifications"
+
+module UmbrellioUtils
+  # Namespace for opt-in monkey-patches. None of these files are loaded by default,
+  # require them explicitly from your application.
+  module Patches
+    # Extends ActiveSupport::Notifications::Event with GVL wait time and malloc stats.
+    # https://github.com/rails/rails/blob/main/activesupport/lib/active_support/notifications/instrumenter.rb # rubocop:disable Layout/LineLength
+    #
+    # The GVL timer must be enabled in the application as early as possible:
+    #   GVLTools::LocalTimer.enable
+    module ActiveSupportEvent
+      STATS_PRECISION = 6
+
+      def initialize(...)
+        super
+        @gvl_time_start = 0
+        @gvl_time_finish = 0
+        @malloc_increase_bytes_start = 0
+        @malloc_increase_bytes_finish = 0
+      end
+
+      def start!
+        super
+        @gvl_time_start = GVLTools::LocalTimer.monotonic_time
+        @malloc_increase_bytes_start = GC.stat(:malloc_increase_bytes)
+      end
+
+      def finish!
+        super
+        @gvl_time_finish = GVLTools::LocalTimer.monotonic_time
+        @malloc_increase_bytes_finish = GC.stat(:malloc_increase_bytes)
+      end
+
+      # Time the thread spent waiting for the GVL, in milliseconds
+      def gvl_time
+        (@gvl_time_finish - @gvl_time_start) / 1_000_000.0
+      end
+
+      # Delta of the process-global malloc counter: can be negative (it resets on GC)
+      # and includes sibling threads' allocations under threaded servers. Guard with
+      # #positive? where a counter is expected.
+      def malloc_increase_bytes
+        @malloc_increase_bytes_finish - @malloc_increase_bytes_start
+      end
+
+      def stats(precision: STATS_PRECISION)
+        {
+          gc_time: gc_time.round(precision),
+          gvl_time: gvl_time.round(precision),
+          cpu_time: cpu_time.round(precision),
+          idle_time: idle_time.round(precision),
+          allocations:,
+          malloc_increase_bytes:,
+        }
+      end
+    end
+  end
+end
+
+ActiveSupport::Notifications::Event.prepend(UmbrellioUtils::Patches::ActiveSupportEvent)

lib/umbrellio_utils/patches/rails_semantic_logger.rb

@@ -0,0 +1,62 @@
+# frozen_string_literal: true
+
+require_relative "active_support_event"
+
+module UmbrellioUtils
+  module Patches
+    # Simplifies the "Completed" action controller log entry and enriches it with
+    # GC, GVL and allocation stats.
+    # https://github.com/reidmorrison/rails_semantic_logger/blob/master/lib/rails_semantic_logger/action_controller/log_subscriber.rb # rubocop:disable Layout/LineLength
+    #
+    # Require this file after the rails_semantic_logger gem has been loaded
+    # (e.g. from an initializer).
+    module RailsSemanticLogger
+      PRECISION = 6
+      PARAMS_SIZE_LIMIT = 10_000
+
+      def process_action(event)
+        ::Rails.logger.info do
+          payload = event.payload.dup
+          payload[:path] = extract_path(payload[:path]) if payload.key?(:path)
+          payload[:params] = cap_params(payload[:params]) if payload.key?(:params)
+
+          payload[:view_time] = payload.delete(:view_runtime).to_f.round(PRECISION)
+          payload[:db_time] = payload.delete(:db_runtime).to_f.round(PRECISION)
+          payload.merge!(event.stats)
+
+          # Causes excessive log output with Rails 5 RC1
+          payload.delete(:headers)
+          # Causes recursion in Rails 6.1.rc1
+          payload.delete(:request)
+          payload.delete(:response)
+          # Keep only the [class, message] pair in :exception (set by ActiveSupport),
+          # not the raw exception with its backtrace — consistent with sidekiq_job_metrics.
+          payload.delete(:exception_object)
+
+          {
+            message: "Completed ##{payload[:action]}",
+            duration: event.duration,
+            payload:,
+          }
+        end
+      end
+
+      private
+
+      def cap_params(params)
+        serialized = params.to_json
+        return params if serialized.bytesize <= PARAMS_SIZE_LIMIT
+
+        {
+          truncated: true,
+          bytesize: serialized.bytesize,
+          preview: "#{serialized[0, PARAMS_SIZE_LIMIT]}...",
+        }
+      end
+    end
+  end
+end
+
+RailsSemanticLogger::ActionController::LogSubscriber.prepend(
+  UmbrellioUtils::Patches::RailsSemanticLogger,
+)

lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb

@@ -0,0 +1,44 @@
+# frozen_string_literal: true
+
+require_relative "../patches/active_support_event"
+
+module UmbrellioUtils
+  module SemanticLogger
+    # Logs Sidekiq job duration, GC, GVL and allocation stats as a dedicated line.
+    # Relies on the "perform.sidekiq_job" notification published by the umbrellio
+    # fork of yabeda-sidekiq. Call +subscribe!+ from an initializer.
+    module SidekiqJobMetrics
+      MESSAGE = "Sidekiq job stats"
+
+      extend self
+
+      def subscribe!
+        ActiveSupport::Notifications.subscribe("perform.sidekiq_job") do |event|
+          log_event(event)
+        end
+      end
+
+      private
+
+      def log_event(event)
+        logger = ::SemanticLogger[event.payload[:worker] || "Sidekiq"]
+        logger.info(
+          message: MESSAGE,
+          duration: event.duration,
+          payload: metrics_payload(event),
+        )
+      end
+
+      def metrics_payload(event)
+        payload = {
+          worker: event.payload[:worker],
+          queue: event.payload[:queue],
+          **event.stats,
+        }
+        # [class, message] pair set by ActiveSupport::Notifications when the job raised
+        payload[:exception] = event.payload[:exception] if event.payload[:exception]
+        payload
+      end
+    end
+  end
+end

lib/umbrellio_utils/semantic_logger/tiny_json_formatter.rb

@@ -20,6 +20,10 @@ class TinyJsonFormatter
         time: :time,
       }.freeze
 
+      # Fields that are included in the output only when explicitly requested
+      # via +custom_names_mapping+ (e.g. <code>{ duration: :duration }</code>).
+      OPTIONAL_FIELDS = %i[duration payload].freeze
+
       # Returns a new instance of the {UmbrellioUtils::SemanticLogger::TinyJsonFormatter}.
       # @option [Integer] message_size_limit maximum number of characters in a log message
       # @option [Hash] custom_names_mapping mapping from default field names to custom ones.
@@ -31,6 +35,12 @@ class TinyJsonFormatter
       # @option custom_names_mapping [Symbol] :tags custom name for the `tags` field.
       # @option custom_names_mapping [Symbol] :named_tags custom name for the `named_tags` field.
       # @option custom_names_mapping [Symbol] :time custom name for the `time` field.
+      # @option custom_names_mapping [Symbol] :duration enables logging of the `duration`
+      #   field under the given name. Unlike the default fields, it is not logged
+      #   unless explicitly listed in the mapping.
+      # @option custom_names_mapping [Symbol] :payload enables logging of the `payload`
+      #   field under the given name. Unlike the default fields, it is not logged
+      #   unless explicitly listed in the mapping.
       # @example Use custom name for the `message` and `time` fields
       #   UmbrellioUtils::SemanticLogger::TinyJsonFormatter.new(
       #     time: :timestamp, message: :note,
@@ -60,7 +70,17 @@ def call(log, _logger)
       # Builds hash with data from log.
       # @return [Hash] the hash, which will be converted to the JSON later.
       def build_data_for(log)
-        field_names.values_at(*DEFAULT_NAMES_MAPPING.keys).zip(pack_data(log)).to_h
+        data = field_names.values_at(*DEFAULT_NAMES_MAPPING.keys).zip(pack_data(log)).to_h
+
+        OPTIONAL_FIELDS.each do |field|
+          field_name = field_names[field]
+          next if field_name.nil?
+
+          value = log.public_send(field)
+          data[field_name] = value unless value.nil?
+        end
+
+        data
       end
 
       # Builds an [Array] with all the required fields, which are arranged

lib/umbrellio_utils/version.rb

@@ -1,5 +1,5 @@
 # frozen_string_literal: true
 
 module UmbrellioUtils
-  VERSION = "1.14.3"
+  VERSION = "1.15.0"
 end

spec/support/rails.rb

@@ -4,4 +4,8 @@ module Rails
   def self.env
     "development".inquiry
   end
+
+  def self.logger
+    nil
+  end
 end

spec/support/rails_semantic_logger.rb

@@ -0,0 +1,17 @@
+# frozen_string_literal: true
+
+# Minimal stub of the rails_semantic_logger class patched by
+# UmbrellioUtils::Patches::RailsSemanticLogger, so that specs don't have to load
+# the whole Rails stack.
+module RailsSemanticLogger
+  module ActionController
+    class LogSubscriber
+      private
+
+      def extract_path(path)
+        index = path.index("?")
+        index ? path[0, index] : path
+      end
+    end
+  end
+end

spec/umbrellio_utils/patches/active_support_event_spec.rb

@@ -0,0 +1,46 @@
+# frozen_string_literal: true
+
+require "umbrellio_utils/patches/active_support_event"
+
+describe UmbrellioUtils::Patches::ActiveSupportEvent do
+  let(:event) do
+    ActiveSupport::Notifications::Event.new("some.event", nil, nil, "42", {})
+  end
+
+  it "tracks GVL time and malloc stats between start! and finish!" do
+    event.start!
+    Array.new(100) { "x" * 100 }
+    event.finish!
+
+    expect(event.gvl_time).to be_a(Float)
+    expect(event.gvl_time).to be >= 0
+    expect(event.malloc_increase_bytes).to be_an(Integer)
+  end
+
+  it "returns zero values for a non-started event" do
+    expect(event.gvl_time).to eq(0.0)
+    expect(event.malloc_increase_bytes).to eq(0)
+  end
+
+  describe "#stats" do
+    before do
+      event.start!
+      event.finish!
+    end
+
+    it "returns the shared timing/allocation field set" do
+      expect(event.stats).to match(
+        gc_time: be_a(Numeric),
+        gvl_time: be_a(Float),
+        cpu_time: be_a(Numeric),
+        idle_time: be_a(Numeric),
+        allocations: be_an(Integer),
+        malloc_increase_bytes: be_an(Integer),
+      )
+    end
+
+    it "rounds timings to the given precision" do
+      expect(event.stats(precision: 2)[:gvl_time]).to eq(event.gvl_time.round(2))
+    end
+  end
+end