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..8fe6e64 --- /dev/null +++ b/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) 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..22febeb --- /dev/null +++ b/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, +) 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..76ec5a1 --- /dev/null +++ b/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 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/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..23b45b7 --- /dev/null +++ b/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 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..e084b20 --- /dev/null +++ b/spec/umbrellio_utils/patches/rails_semantic_logger_spec.rb @@ -0,0 +1,105 @@ +# 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), + malloc_increase_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 + + 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 + + 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 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..c192914 --- /dev/null +++ b/spec/umbrellio_utils/semantic_logger/sidekiq_job_metrics_spec.rb @@ -0,0 +1,74 @@ +# 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: "Sidekiq job stats", + 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), + malloc_increase_bytes: be_an(Integer), + }, + ), + ) + end + + 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(:info).with( + hash_including( + message: "Sidekiq job stats", + 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 + 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 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"