From 1fc754f054f9816b47b25b084e56f9488b024948 Mon Sep 17 00:00:00 2001 From: Nilton Vasques Date: Mon, 19 Jun 2023 10:58:44 -0300 Subject: [PATCH 1/2] Allow to create events/spans before the transaction start to compute queue time --- lib/elastic_apm/metrics/request_metrics.rb | 58 ++++++++++++++++++++++ lib/elastic_apm/middleware.rb | 19 +++++++ lib/elastic_apm/span.rb | 5 +- lib/elastic_apm/transaction.rb | 3 +- 4 files changed, 81 insertions(+), 4 deletions(-) create mode 100644 lib/elastic_apm/metrics/request_metrics.rb diff --git a/lib/elastic_apm/metrics/request_metrics.rb b/lib/elastic_apm/metrics/request_metrics.rb new file mode 100644 index 000000000..366cdfd6e --- /dev/null +++ b/lib/elastic_apm/metrics/request_metrics.rb @@ -0,0 +1,58 @@ +module ElasticAPM + class RequestMetrics + MILLISECONDS_CUTOFF = Time.new(2000, 1, 1).to_i * 1000 + MICROSECONDS_CUTOFF = MILLISECONDS_CUTOFF * 1000 + NANOSECONDS_CUTOFF = MICROSECONDS_CUTOFF * 1000 + + attr_reader :request_id, :size, :network_time + + def initialize(env) + @request_id = env["HTTP_X_REQUEST_ID"] + @size = env["rack.input"].respond_to?(:size) ? env["rack.input"].size : 0 + @network_time = env["puma.request_body_wait"].to_i + @request_start_header = env["HTTP_X_REQUEST_START"] + end + + def started_at + if @request_start_header + # There are several variants of this header. We handle these: + # - whole milliseconds (Heroku) + # - whole microseconds (???) + # - whole nanoseconds (Render) + # - fractional seconds (NGINX) + # - preceeding "t=" (NGINX) + value = @request_start_header.gsub(/[^0-9.]/, "").to_f + + # `value` could be seconds, milliseconds, microseconds or nanoseconds. + # We use some arbitrary cutoffs to determine which one it is. + + if value > NANOSECONDS_CUTOFF + Time.at(value / 1_000_000_000.0) + elsif value > MICROSECONDS_CUTOFF + Time.at(value / 1_000_000.0) + elsif value > MILLISECONDS_CUTOFF + Time.at(value / 1000.0) + else + Time.at(value) + end + end + end + + def queue_time(now = Time.now) + return 0.0 if started_at.nil? + + queue_time = ((now - started_at) * 1000).to_i + + # Subtract the time Puma spent waiting on the request body, i.e. the network time. It's irrelevant to + # capacity-related queue time. Without this, slow clients and large request payloads will skew queue time. + queue_time -= network_time + + # Safeguard against negative queue times (should not happen in practice) + (queue_time > 0) ? queue_time : 0 + end + + def queue_time_micros(now = Time.now) + (queue_time(now) * 1000).to_i + end + end +end diff --git a/lib/elastic_apm/middleware.rb b/lib/elastic_apm/middleware.rb index 9e6aeb987..a6c166981 100644 --- a/lib/elastic_apm/middleware.rb +++ b/lib/elastic_apm/middleware.rb @@ -17,6 +17,7 @@ # # frozen_string_literal: true +require 'elastic_apm/metrics/request_metrics' module ElasticAPM # @api private @@ -33,6 +34,8 @@ def call(env) transaction = start_transaction(env) end + register_queue_time(transaction, env) if transaction + resp = @app.call env rescue InternalError raise # Don't report ElasticAPM errors @@ -97,5 +100,21 @@ def running? def config @config ||= ElasticAPM.agent.config end + + def register_queue_time(transaction, env) + request_metrics = RequestMetrics.new(env) + queue_time_micros = request_metrics.queue_time_micros + return if queue_time_micros.zero? + + transaction.clock_start -= queue_time_micros + transaction.timestamp -= queue_time_micros # 350ms before + + span = ElasticAPM.start_span 'Queue Time', 'queue', subtype: 'nginx', action: 'awaiting' + + span.clock_start = transaction.clock_start + span.timestamp = transaction.timestamp + + ElasticAPM.end_span(span) + end end end diff --git a/lib/elastic_apm/span.rb b/lib/elastic_apm/span.rb index a9b735c9f..2c8fa0ce8 100644 --- a/lib/elastic_apm/span.rb +++ b/lib/elastic_apm/span.rb @@ -84,7 +84,9 @@ def initialize( :outcome, :subtype, :trace_context, - :type + :type, + :clock_start, + :timestamp ) attr_reader( :context, @@ -93,7 +95,6 @@ def initialize( :sample_rate, :self_time, :stacktrace, - :timestamp, :transaction ) diff --git a/lib/elastic_apm/transaction.rb b/lib/elastic_apm/transaction.rb index 23731fa65..332b4ff5d 100644 --- a/lib/elastic_apm/transaction.rb +++ b/lib/elastic_apm/transaction.rb @@ -87,7 +87,7 @@ def initialize( end # rubocop:enable Metrics/ParameterLists - attr_accessor :name, :type, :result, :outcome + attr_accessor :name, :type, :result, :outcome, :clock_start, :timestamp attr_reader( :breakdown_metrics, @@ -101,7 +101,6 @@ def initialize( :sample_rate, :span_frames_min_duration, :started_spans, - :timestamp, :trace_context, :transaction_max_spans ) From 455bf3c1517710cbc00e9eb71713287d1ac0be0e Mon Sep 17 00:00:00 2001 From: Gustavo de Oliveira Date: Wed, 28 Jan 2026 10:40:55 -0300 Subject: [PATCH 2/2] Trigger github actions