From 29c1fcd173afe99392fc92554d76499d749cf9dc Mon Sep 17 00:00:00 2001 From: "dmitry.rom" Date: Mon, 6 Jul 2026 17:47:29 +0300 Subject: [PATCH 1/8] Add allocation and gvl statistics --- Gemfile | 1 + Gemfile.lock | 4 +- README.md | 26 +++++++ .../patches/active_support_event.rb | 48 +++++++++++++ .../patches/rails_semantic_logger.rb | 50 +++++++++++++ .../semantic_logger/sidekiq_job_metrics.rb | 50 +++++++++++++ lib/umbrellio_utils/version.rb | 2 +- spec/support/rails.rb | 4 ++ spec/support/rails_semantic_logger.rb | 17 +++++ .../patches/active_support_event_spec.rb | 24 +++++++ .../patches/rails_semantic_logger_spec.rb | 72 +++++++++++++++++++ .../sidekiq_job_metrics_spec.rb | 65 +++++++++++++++++ 12 files changed, 361 insertions(+), 2 deletions(-) create mode 100644 lib/umbrellio_utils/patches/active_support_event.rb create mode 100644 lib/umbrellio_utils/patches/rails_semantic_logger.rb create mode 100644 lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb create mode 100644 spec/support/rails_semantic_logger.rb create mode 100644 spec/umbrellio_utils/patches/active_support_event_spec.rb create mode 100644 spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb create mode 100644 spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb diff --git a/Gemfile b/Gemfile index c081843..d9a7908 100644 --- a/Gemfile +++ b/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" diff --git a/Gemfile.lock b/Gemfile.lock index d40faa3..a88f88c 100644 --- a/Gemfile.lock +++ b/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 diff --git a/README.md b/README.md index 6866f46..84841cd 100644 --- a/README.md +++ b/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. diff --git a/lib/umbrellio_utils/patches/active_support_event.rb b/lib/umbrellio_utils/patches/active_support_event.rb new file mode 100644 index 0000000..36e3924 --- /dev/null +++ b/lib/umbrellio_utils/patches/active_support_event.rb @@ -0,0 +1,48 @@ +# 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 + # + # The GVL timer must be enabled in the application as early as possible: + # GVLTools::LocalTimer.enable + module ActiveSupportEvent + 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 + + def malloc_increase_bytes + @malloc_increase_bytes_finish - @malloc_increase_bytes_start + end + end + end +end + +ActiveSupport::Notifications::Event.prepend(UmbrellioUtils::Patches::ActiveSupportEvent) diff --git a/lib/umbrellio_utils/patches/rails_semantic_logger.rb b/lib/umbrellio_utils/patches/rails_semantic_logger.rb new file mode 100644 index 0000000..512c750 --- /dev/null +++ b/lib/umbrellio_utils/patches/rails_semantic_logger.rb @@ -0,0 +1,50 @@ +# 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 + # + # Require this file after the rails_semantic_logger gem has been loaded + # (e.g. from an initializer). + module RailsSemanticLogger + PRECISION = 6 + + def process_action(event) + ::Rails.logger.info do + payload = event.payload.dup + payload[:path] = extract_path(payload[:path]) if payload.key?(:path) + + payload[:view_time] = payload.delete(:view_runtime).to_f.round(PRECISION) + payload[:db_time] = payload.delete(:db_runtime).to_f.round(PRECISION) + + payload[:gc_time] = event.gc_time.round(PRECISION) + payload[:gvl_time] = event.gvl_time.round(PRECISION) + payload[:cpu_time] = event.cpu_time.round(PRECISION) + payload[:idle_time] = event.idle_time.round(PRECISION) + payload[:allocations] = event.allocations + payload[:allocation_bytes] = event.malloc_increase_bytes + + # Causes excessive log output with Rails 5 RC1 + payload.delete(:headers) + # Causes recursion in Rails 6.1.rc1 + payload.delete(:request) + payload.delete(:response) + + { + message: "Completed ##{payload[:action]}", + duration: event.duration, + payload:, + } + end + end + end + end +end + +::RailsSemanticLogger::ActionController::LogSubscriber.prepend( + UmbrellioUtils::Patches::RailsSemanticLogger, +) diff --git a/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb b/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb new file mode 100644 index 0000000..b137064 --- /dev/null +++ b/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb @@ -0,0 +1,50 @@ +# frozen_string_literal: true + +require_relative "../patches/active_support_event" + +module UmbrellioUtils + module SemanticLogger + # Logs Sidekiq job completion with duration, GC, GVL and allocation stats. + # Relies on the "perform.sidekiq_job" notification published by the umbrellio + # fork of yabeda-sidekiq. Call +subscribe!+ from an initializer. + module SidekiqJobMetrics + PRECISION = 6 + + 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"] + exception = event.payload[:exception_object] + + entry = { + message: "Completed #perform", + duration: event.duration, + payload: metrics_payload(event), + } + + exception ? logger.error(exception:, **entry) : logger.info(entry) + end + + def metrics_payload(event) + { + worker: event.payload[:worker], + queue: event.payload[:queue], + gc_time: event.gc_time.round(PRECISION), + gvl_time: event.gvl_time.round(PRECISION), + cpu_time: event.cpu_time.round(PRECISION), + idle_time: event.idle_time.round(PRECISION), + allocations: event.allocations, + allocation_bytes: event.malloc_increase_bytes, + } + end + end + end +end diff --git a/lib/umbrellio_utils/version.rb b/lib/umbrellio_utils/version.rb index f5b09cb..8aa0f2f 100644 --- a/lib/umbrellio_utils/version.rb +++ b/lib/umbrellio_utils/version.rb @@ -1,5 +1,5 @@ # frozen_string_literal: true module UmbrellioUtils - VERSION = "1.14.3" + VERSION = "1.15.0" end diff --git a/spec/support/rails.rb b/spec/support/rails.rb index e79b794..45a9ea8 100644 --- a/spec/support/rails.rb +++ b/spec/support/rails.rb @@ -4,4 +4,8 @@ module Rails def self.env "development".inquiry end + + def self.logger + nil + end end diff --git a/spec/support/rails_semantic_logger.rb b/spec/support/rails_semantic_logger.rb new file mode 100644 index 0000000..e79a50c --- /dev/null +++ b/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 diff --git a/spec/umbrellio_utils/patches/active_support_event_spec.rb b/spec/umbrellio_utils/patches/active_support_event_spec.rb new file mode 100644 index 0000000..4437c46 --- /dev/null +++ b/spec/umbrellio_utils/patches/active_support_event_spec.rb @@ -0,0 +1,24 @@ +# 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 +end diff --git a/spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb b/spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb new file mode 100644 index 0000000..f51f0f9 --- /dev/null +++ b/spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb @@ -0,0 +1,72 @@ +# frozen_string_literal: true + +require "umbrellio_utils/patches/rails_semantic_logger" + +describe UmbrellioUtils::Patches::RailsSemanticLogger do + subject(:log_entry) do + subscriber.process_action(event) + logged_entries.last + end + + let(:subscriber) { RailsSemanticLogger::ActionController::LogSubscriber.new } + let(:logged_entries) { [] } + + let(:logger) do + entries = logged_entries + instance_double(SemanticLogger::Logger).tap do |logger| + allow(logger).to receive(:info) { |&block| entries << block.call } + end + end + + let(:payload) do + { + action: "show", + path: "/users/1?secret=42", + view_runtime: 1.5, + db_runtime: 2.25, + headers: { "X-Some" => "header" }, + request: :request_object, + response: :response_object, + } + end + + let(:event) do + event = ActiveSupport::Notifications::Event.new( + "process_action.action_controller", nil, nil, "42", payload + ) + event.start! + event.finish! + event + end + + before { allow(Rails).to receive(:logger).and_return(logger) } + + it "logs a simplified entry with GC, GVL and allocation stats" do + expect(log_entry).to include(message: "Completed #show", duration: be_a(Float)) + + expect(log_entry[:payload]).to include( + action: "show", + path: "/users/1", + view_time: 1.5, + db_time: 2.25, + gc_time: be_a(Numeric), + gvl_time: be_a(Float), + cpu_time: be_a(Numeric), + idle_time: be_a(Numeric), + allocations: be_a(Integer), + allocation_bytes: be_an(Integer), + ) + + expect(log_entry[:payload].keys).not_to include( + :headers, :request, :response, :view_runtime, :db_runtime + ) + end + + context "without path in the payload" do + let(:payload) { super().except(:path) } + + it "logs entry without path" do + expect(log_entry[:payload].keys).not_to include(:path) + end + end +end diff --git a/spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb b/spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb new file mode 100644 index 0000000..1af1eb1 --- /dev/null +++ b/spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb @@ -0,0 +1,65 @@ +# frozen_string_literal: true + +require "umbrellio_utils/semantic_logger/sidekiq_job_metrics" + +describe UmbrellioUtils::SemanticLogger::SidekiqJobMetrics do + let(:logger) { instance_double(SemanticLogger::Logger) } + let(:subscription) { described_class.subscribe! } + + before do + allow(SemanticLogger).to receive(:[]).and_return(logger) + allow(logger).to receive(:info) + allow(logger).to receive(:error) + subscription + end + + after { ActiveSupport::Notifications.unsubscribe(subscription) } + + def instrument(payload = { worker: "SomeWorker", queue: "default" }, &block) + block ||= proc {} + ActiveSupport::Notifications.instrument("perform.sidekiq_job", **payload, &block) + end + + it "logs completed job with metrics" do + instrument + + expect(SemanticLogger).to have_received(:[]).with("SomeWorker") + + expect(logger).to have_received(:info).with( + hash_including( + message: "Completed #perform", + duration: be_a(Float), + payload: { + worker: "SomeWorker", + queue: "default", + gc_time: be_a(Numeric), + gvl_time: be_a(Float), + cpu_time: be_a(Numeric), + idle_time: be_a(Numeric), + allocations: be_a(Integer), + allocation_bytes: be_an(Integer), + }, + ), + ) + end + + it "logs failed job as an error with exception" do + expect { instrument { raise "Boom!" } }.to raise_error("Boom!") + + expect(logger).to have_received(:error).with( + hash_including( + message: "Completed #perform", + exception: an_instance_of(RuntimeError), + ), + ) + end + + context "when worker is not specified in the payload" do + it "falls back to the Sidekiq logger name" do + instrument(queue: "default") + + expect(SemanticLogger).to have_received(:[]).with("Sidekiq") + expect(logger).to have_received(:info) + end + end +end From e61e7ed4dab5335e41b727dc320d1cee5997ecc6 Mon Sep 17 00:00:00 2001 From: "dmitry.rom" Date: Tue, 7 Jul 2026 17:37:26 +0300 Subject: [PATCH 2/8] Support optional duration and payload fields in TinyJsonFormatter --- .idea/workspace.xml | 92 +++++++++++++++++++ .../semantic_logger/tiny_json_formatter.rb | 22 ++++- .../tiny_json_formatter_spec.rb | 48 ++++++++++ 3 files changed, 161 insertions(+), 1 deletion(-) create mode 100644 .idea/workspace.xml diff --git a/.idea/workspace.xml b/.idea/workspace.xml new file mode 100644 index 0000000..b7019c2 --- /dev/null +++ b/.idea/workspace.xml @@ -0,0 +1,92 @@ + + + + + + + + + + + + + + + + + + + { + "associatedIndex": 5 +} + + + + { + "keyToString": { + "ModuleVcsDetector.initialDetectionPerformed": "true", + "RunOnceActivity.MCP Project settings loaded": "true", + "RunOnceActivity.ShowReadmeOnStart": "true", + "RunOnceActivity.TerminalTabsStorage.copyFrom.TerminalArrangementManager.252": "true", + "RunOnceActivity.git.unshallow": "true", + "RunOnceActivity.typescript.service.memoryLimit.init": "true", + "com.intellij.ml.llm.matterhorn.ej.ui.settings.DefaultModelSelectionForGA.v1": "true", + "git-widget-placeholder": "gvl-allocations", + "junie.onboarding.icon.badge.shown": "true", + "last_opened_file_path": "/Users/Dmitry/Desktop/projects/utils/lib/umbrellio_utils", + "node.js.detected.package.eslint": "true", + "node.js.detected.package.tslint": "true", + "node.js.selected.package.eslint": "(autodetect)", + "node.js.selected.package.tslint": "(autodetect)", + "nodejs_package_manager_path": "npm", + "ruby.structure.view.model.defaults.configured": "true", + "to.speed.mode.migration.done": "true", + "vue.rearranger.settings.migration": "true" + } +} + + + + + + + + + + + + + + + + + + + 1769506452634 + + + + + + \ No newline at end of file diff --git a/lib/umbrellio_utils/semantic_logger/tiny_json_formatter.rb b/lib/umbrellio_utils/semantic_logger/tiny_json_formatter.rb index d6cce44..e5d2fcb 100644 --- a/lib/umbrellio_utils/semantic_logger/tiny_json_formatter.rb +++ b/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. { duration: :duration }). + 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 diff --git a/spec/umbrellio_utils/semantic_logger/tiny_json_formatter_spec.rb b/spec/umbrellio_utils/semantic_logger/tiny_json_formatter_spec.rb index 6674257..6596f41 100644 --- a/spec/umbrellio_utils/semantic_logger/tiny_json_formatter_spec.rb +++ b/spec/umbrellio_utils/semantic_logger/tiny_json_formatter_spec.rb @@ -77,6 +77,54 @@ end end + context "with duration and payload requested via custom_names_mapping" do + let(:custom_names_mapping) { Hash[duration: :duration, payload: :payload] } + + before do + allow(log).to receive_messages( + duration: 152.3, + payload: { gvl_time: 12.4, allocations: 48_213 }, + ) + end + + it "includes duration and payload" do + expect(result).to be_json_including( + message: "Some Message", + duration: 152.3, + payload: { gvl_time: 12.4, allocations: 48_213 }, + ) + end + + context "with custom field names" do + let(:custom_names_mapping) { Hash[duration: :took_ms, payload: :details] } + + it "uses custom names" do + expect(result).to be_json_including( + took_ms: 152.3, + details: { gvl_time: 12.4, allocations: 48_213 }, + ) + end + end + + context "when values are absent" do + before { allow(log).to receive_messages(duration: nil, payload: nil) } + + it "omits the fields" do + expect(JSON.parse(result).keys).not_to include("duration", "payload") + end + end + end + + context "without duration and payload in the mapping" do + before do + allow(log).to receive_messages(duration: 152.3, payload: { some: :data }) + end + + it "does not log them" do + expect(JSON.parse(result).keys).not_to include("duration", "payload") + end + end + context "message with some colorization" do let(:log_message) do "\e[1m\e[35mSQL (Total: 9MS, CH: 2MS)\e\e[0m SELECT \"database\"\e" From ab47d49dcbe71d717256a954ba8449e710cbfa12 Mon Sep 17 00:00:00 2001 From: "dmitry.rom" Date: Tue, 7 Jul 2026 17:38:16 +0300 Subject: [PATCH 3/8] Fix rubocop offenses in patch files --- lib/umbrellio_utils/patches/active_support_event.rb | 2 +- lib/umbrellio_utils/patches/rails_semantic_logger.rb | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/umbrellio_utils/patches/active_support_event.rb b/lib/umbrellio_utils/patches/active_support_event.rb index 36e3924..bec7c06 100644 --- a/lib/umbrellio_utils/patches/active_support_event.rb +++ b/lib/umbrellio_utils/patches/active_support_event.rb @@ -8,7 +8,7 @@ module UmbrellioUtils # 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 + # 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 diff --git a/lib/umbrellio_utils/patches/rails_semantic_logger.rb b/lib/umbrellio_utils/patches/rails_semantic_logger.rb index 512c750..a891150 100644 --- a/lib/umbrellio_utils/patches/rails_semantic_logger.rb +++ b/lib/umbrellio_utils/patches/rails_semantic_logger.rb @@ -6,7 +6,7 @@ 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 + # 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). @@ -45,6 +45,6 @@ def process_action(event) end end -::RailsSemanticLogger::ActionController::LogSubscriber.prepend( +RailsSemanticLogger::ActionController::LogSubscriber.prepend( UmbrellioUtils::Patches::RailsSemanticLogger, ) From a8722748ccfc5c70aae314623e0e569a8fdb80df Mon Sep 17 00:00:00 2001 From: "dmitry.rom" Date: Wed, 8 Jul 2026 11:22:30 +0300 Subject: [PATCH 4/8] Remove ide file --- .idea/workspace.xml | 92 --------------------------------------------- 1 file changed, 92 deletions(-) delete mode 100644 .idea/workspace.xml diff --git a/.idea/workspace.xml b/.idea/workspace.xml deleted file mode 100644 index b7019c2..0000000 --- a/.idea/workspace.xml +++ /dev/null @@ -1,92 +0,0 @@ - - - - - - - - - - - - - - - - - - - { - "associatedIndex": 5 -} - - - - { - "keyToString": { - "ModuleVcsDetector.initialDetectionPerformed": "true", - "RunOnceActivity.MCP Project settings loaded": "true", - "RunOnceActivity.ShowReadmeOnStart": "true", - "RunOnceActivity.TerminalTabsStorage.copyFrom.TerminalArrangementManager.252": "true", - "RunOnceActivity.git.unshallow": "true", - "RunOnceActivity.typescript.service.memoryLimit.init": "true", - "com.intellij.ml.llm.matterhorn.ej.ui.settings.DefaultModelSelectionForGA.v1": "true", - "git-widget-placeholder": "gvl-allocations", - "junie.onboarding.icon.badge.shown": "true", - "last_opened_file_path": "/Users/Dmitry/Desktop/projects/utils/lib/umbrellio_utils", - "node.js.detected.package.eslint": "true", - "node.js.detected.package.tslint": "true", - "node.js.selected.package.eslint": "(autodetect)", - "node.js.selected.package.tslint": "(autodetect)", - "nodejs_package_manager_path": "npm", - "ruby.structure.view.model.defaults.configured": "true", - "to.speed.mode.migration.done": "true", - "vue.rearranger.settings.migration": "true" - } -} - - - - - - - - - - - - - - - - - - - 1769506452634 - - - - - - \ No newline at end of file From 299dadec647b113b1e35e250c675817c66a04d64 Mon Sep 17 00:00:00 2001 From: "dmitry.rom" Date: Mon, 13 Jul 2026 16:52:49 +0300 Subject: [PATCH 5/8] Avoid allocating full GC.stat hash in event patch --- lib/umbrellio_utils/patches/active_support_event.rb | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/lib/umbrellio_utils/patches/active_support_event.rb b/lib/umbrellio_utils/patches/active_support_event.rb index bec7c06..26a0320 100644 --- a/lib/umbrellio_utils/patches/active_support_event.rb +++ b/lib/umbrellio_utils/patches/active_support_event.rb @@ -24,13 +24,13 @@ def initialize(...) def start! super @gvl_time_start = GVLTools::LocalTimer.monotonic_time - @malloc_increase_bytes_start = GC.stat[:malloc_increase_bytes] + @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] + @malloc_increase_bytes_finish = GC.stat(:malloc_increase_bytes) end # Time the thread spent waiting for the GVL, in milliseconds @@ -38,6 +38,9 @@ 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 From cd263238195572b83fc76b24d537406e7ae2e38d Mon Sep 17 00:00:00 2001 From: "dmitry.rom" Date: Thu, 16 Jul 2026 10:14:06 +0300 Subject: [PATCH 6/8] Cap params, rename allocation_bytes to malloc_increase_bytes --- .../patches/rails_semantic_logger.rb | 34 +++++++++++++++---- .../semantic_logger/sidekiq_job_metrics.rb | 16 ++++----- .../patches/rails_semantic_logger_spec.rb | 21 +++++++++++- .../sidekiq_job_metrics_spec.rb | 17 +++++++--- 4 files changed, 68 insertions(+), 20 deletions(-) diff --git a/lib/umbrellio_utils/patches/rails_semantic_logger.rb b/lib/umbrellio_utils/patches/rails_semantic_logger.rb index a891150..cf937af 100644 --- a/lib/umbrellio_utils/patches/rails_semantic_logger.rb +++ b/lib/umbrellio_utils/patches/rails_semantic_logger.rb @@ -12,21 +12,17 @@ module Patches # (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[:gc_time] = event.gc_time.round(PRECISION) - payload[:gvl_time] = event.gvl_time.round(PRECISION) - payload[:cpu_time] = event.cpu_time.round(PRECISION) - payload[:idle_time] = event.idle_time.round(PRECISION) - payload[:allocations] = event.allocations - payload[:allocation_bytes] = event.malloc_increase_bytes + add_stats(payload, event) # Causes excessive log output with Rails 5 RC1 payload.delete(:headers) @@ -41,6 +37,30 @@ def process_action(event) } end end + + private + + def add_stats(payload, event) + payload[:gc_time] = event.gc_time.round(PRECISION) + payload[:gvl_time] = event.gvl_time.round(PRECISION) + payload[:cpu_time] = event.cpu_time.round(PRECISION) + payload[:idle_time] = event.idle_time.round(PRECISION) + payload[:allocations] = event.allocations + # Off-heap malloc increase since the last GC (lower bound, unreliable across GC); + # see UmbrellioUtils::Patches::ActiveSupportEvent#malloc_increase_bytes. + payload[:malloc_increase_bytes] = event.malloc_increase_bytes + end + + 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 diff --git a/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb b/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb index b137064..67f2b1b 100644 --- a/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb +++ b/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb @@ -22,19 +22,15 @@ def subscribe! def log_event(event) logger = ::SemanticLogger[event.payload[:worker] || "Sidekiq"] - exception = event.payload[:exception_object] - - entry = { + logger.info( message: "Completed #perform", duration: event.duration, payload: metrics_payload(event), - } - - exception ? logger.error(exception:, **entry) : logger.info(entry) + ) end def metrics_payload(event) - { + payload = { worker: event.payload[:worker], queue: event.payload[:queue], gc_time: event.gc_time.round(PRECISION), @@ -42,8 +38,12 @@ def metrics_payload(event) cpu_time: event.cpu_time.round(PRECISION), idle_time: event.idle_time.round(PRECISION), allocations: event.allocations, - allocation_bytes: event.malloc_increase_bytes, + # Off-heap malloc increase since the last GC (lower bound, unreliable across GC) + malloc_increase_bytes: event.malloc_increase_bytes, } + # [class, message] pair set by ActiveSupport::Notifications when the job raised + payload[:exception] = event.payload[:exception] if event.payload[:exception] + payload end end end diff --git a/spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb b/spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb index f51f0f9..6bc4e3a 100644 --- a/spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb +++ b/spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb @@ -54,7 +54,7 @@ cpu_time: be_a(Numeric), idle_time: be_a(Numeric), allocations: be_a(Integer), - allocation_bytes: be_an(Integer), + malloc_increase_bytes: be_an(Integer), ) expect(log_entry[:payload].keys).not_to include( @@ -69,4 +69,23 @@ expect(log_entry[:payload].keys).not_to include(:path) end end + + context "with small params" do + let(:payload) { super().merge(params: { "id" => "1" }) } + + it "keeps params as-is" do + expect(log_entry[:payload][:params]).to eq("id" => "1") + end + end + + context "with params over the size limit" do + let(:payload) { super().merge(params: { "blob" => "x" * 20_000, "id" => "1" }) } + + it "keeps a truncated preview of the values plus the size" do + params = log_entry[:payload][:params] + expect(params).to include(truncated: true, bytesize: be > 20_000) + expect(params[:preview]).to start_with('{"blob":"xxx').and(end_with("...")) + expect(params[:preview].size).to be <= (described_class::PARAMS_SIZE_LIMIT + 3) + end + end end diff --git a/spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb b/spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb index 1af1eb1..cf5aa01 100644 --- a/spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb +++ b/spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb @@ -37,21 +37,30 @@ def instrument(payload = { worker: "SomeWorker", queue: "default" }, &block) cpu_time: be_a(Numeric), idle_time: be_a(Numeric), allocations: be_a(Integer), - allocation_bytes: be_an(Integer), + malloc_increase_bytes: be_an(Integer), }, ), ) end - it "logs failed job as an error with exception" do + it "logs a failed job at info with the exception class/message (no backtrace object)" do expect { instrument { raise "Boom!" } }.to raise_error("Boom!") - expect(logger).to have_received(:error).with( + expect(logger).to have_received(:info).with( hash_including( message: "Completed #perform", - exception: an_instance_of(RuntimeError), + payload: hash_including(exception: ["RuntimeError", "Boom!"]), ), ) + expect(logger).not_to have_received(:error) + end + + it "omits the exception key for a successful job" do + instrument + + expect(logger).to have_received(:info).with( + hash_including(payload: hash_not_including(:exception)), + ) end context "when worker is not specified in the payload" do From 35d6dde3f52c6c186e634f925fdd95f9e3a11cb8 Mon Sep 17 00:00:00 2001 From: "dmitry.rom" Date: Fri, 17 Jul 2026 11:16:54 +0300 Subject: [PATCH 7/8] Add Sidekiq job stats message --- lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb | 5 +++-- .../semantic_logger/sidekiq_job_metrics_spec.rb | 4 ++-- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb b/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb index 67f2b1b..1678180 100644 --- a/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb +++ b/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb @@ -4,10 +4,11 @@ module UmbrellioUtils module SemanticLogger - # Logs Sidekiq job completion with duration, GC, GVL and allocation stats. + # 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" PRECISION = 6 extend self @@ -23,7 +24,7 @@ def subscribe! def log_event(event) logger = ::SemanticLogger[event.payload[:worker] || "Sidekiq"] logger.info( - message: "Completed #perform", + message: MESSAGE, duration: event.duration, payload: metrics_payload(event), ) diff --git a/spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb b/spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb index cf5aa01..c192914 100644 --- a/spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb +++ b/spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb @@ -27,7 +27,7 @@ def instrument(payload = { worker: "SomeWorker", queue: "default" }, &block) expect(logger).to have_received(:info).with( hash_including( - message: "Completed #perform", + message: "Sidekiq job stats", duration: be_a(Float), payload: { worker: "SomeWorker", @@ -48,7 +48,7 @@ def instrument(payload = { worker: "SomeWorker", queue: "default" }, &block) expect(logger).to have_received(:info).with( hash_including( - message: "Completed #perform", + message: "Sidekiq job stats", payload: hash_including(exception: ["RuntimeError", "Boom!"]), ), ) From 25fcc219df99ed82635452ecd75a9804c7eab068 Mon Sep 17 00:00:00 2001 From: "dmitry.rom" Date: Fri, 17 Jul 2026 12:01:24 +0300 Subject: [PATCH 8/8] DRY stats --- .../patches/active_support_event.rb | 13 +++++++++++ .../patches/rails_semantic_logger.rb | 16 ++++---------- .../semantic_logger/sidekiq_job_metrics.rb | 9 +------- .../patches/active_support_event_spec.rb | 22 +++++++++++++++++++ .../patches/rails_semantic_logger_spec.rb | 14 ++++++++++++ 5 files changed, 54 insertions(+), 20 deletions(-) diff --git a/lib/umbrellio_utils/patches/active_support_event.rb b/lib/umbrellio_utils/patches/active_support_event.rb index 26a0320..8fe6e64 100644 --- a/lib/umbrellio_utils/patches/active_support_event.rb +++ b/lib/umbrellio_utils/patches/active_support_event.rb @@ -13,6 +13,8 @@ module Patches # 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 @@ -44,6 +46,17 @@ def gvl_time 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 diff --git a/lib/umbrellio_utils/patches/rails_semantic_logger.rb b/lib/umbrellio_utils/patches/rails_semantic_logger.rb index cf937af..22febeb 100644 --- a/lib/umbrellio_utils/patches/rails_semantic_logger.rb +++ b/lib/umbrellio_utils/patches/rails_semantic_logger.rb @@ -22,13 +22,16 @@ def process_action(event) payload[:view_time] = payload.delete(:view_runtime).to_f.round(PRECISION) payload[:db_time] = payload.delete(:db_runtime).to_f.round(PRECISION) - add_stats(payload, event) + 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]}", @@ -40,17 +43,6 @@ def process_action(event) private - def add_stats(payload, event) - payload[:gc_time] = event.gc_time.round(PRECISION) - payload[:gvl_time] = event.gvl_time.round(PRECISION) - payload[:cpu_time] = event.cpu_time.round(PRECISION) - payload[:idle_time] = event.idle_time.round(PRECISION) - payload[:allocations] = event.allocations - # Off-heap malloc increase since the last GC (lower bound, unreliable across GC); - # see UmbrellioUtils::Patches::ActiveSupportEvent#malloc_increase_bytes. - payload[:malloc_increase_bytes] = event.malloc_increase_bytes - end - def cap_params(params) serialized = params.to_json return params if serialized.bytesize <= PARAMS_SIZE_LIMIT diff --git a/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb b/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb index 1678180..76ec5a1 100644 --- a/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb +++ b/lib/umbrellio_utils/semantic_logger/sidekiq_job_metrics.rb @@ -9,7 +9,6 @@ module SemanticLogger # fork of yabeda-sidekiq. Call +subscribe!+ from an initializer. module SidekiqJobMetrics MESSAGE = "Sidekiq job stats" - PRECISION = 6 extend self @@ -34,13 +33,7 @@ def metrics_payload(event) payload = { worker: event.payload[:worker], queue: event.payload[:queue], - gc_time: event.gc_time.round(PRECISION), - gvl_time: event.gvl_time.round(PRECISION), - cpu_time: event.cpu_time.round(PRECISION), - idle_time: event.idle_time.round(PRECISION), - allocations: event.allocations, - # Off-heap malloc increase since the last GC (lower bound, unreliable across GC) - malloc_increase_bytes: event.malloc_increase_bytes, + **event.stats, } # [class, message] pair set by ActiveSupport::Notifications when the job raised payload[:exception] = event.payload[:exception] if event.payload[:exception] diff --git a/spec/umbrellio_utils/patches/active_support_event_spec.rb b/spec/umbrellio_utils/patches/active_support_event_spec.rb index 4437c46..23b45b7 100644 --- a/spec/umbrellio_utils/patches/active_support_event_spec.rb +++ b/spec/umbrellio_utils/patches/active_support_event_spec.rb @@ -21,4 +21,26 @@ 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 diff --git a/spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb b/spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb index 6bc4e3a..e084b20 100644 --- a/spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb +++ b/spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb @@ -88,4 +88,18 @@ expect(params[:preview].size).to be <= (described_class::PARAMS_SIZE_LIMIT + 3) end end + + context "with a failed action" do + let(:payload) do + super().merge( + exception: ["RuntimeError", "Boom!"], + exception_object: RuntimeError.new("Boom!"), + ) + end + + it "keeps the [class, message] pair but drops the raw exception object" do + expect(log_entry[:payload]).to include(exception: ["RuntimeError", "Boom!"]) + expect(log_entry[:payload].keys).not_to include(:exception_object) + end + end end