From 3c100ddff32227637e84aa44e2c58a67ec0d6ec8 Mon Sep 17 00:00:00 2001 From: Nilton Vasques Date: Mon, 19 Jun 2023 10:58:44 -0300 Subject: [PATCH 1/6] 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 | 6 ++- 4 files changed, 84 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 6671c55be..ad7037b08 100644 --- a/lib/elastic_apm/transaction.rb +++ b/lib/elastic_apm/transaction.rb @@ -94,7 +94,9 @@ def initialize( :outcome, :sampled, :sample_rate, - :started_spans + :started_spans, + :clock_start, + :timestamp ) attr_reader( @@ -107,7 +109,7 @@ def initialize( :notifications, :self_time, :span_frames_min_duration, - :timestamp, + :started_spans, :trace_context, :transaction_max_spans, :config From f822cf29a6b029ba7be7151bcf5d41b811349da6 Mon Sep 17 00:00:00 2001 From: Gustavo de Oliveira Date: Mon, 12 Jan 2026 20:51:21 -0300 Subject: [PATCH 2/6] Fix stacktrace bug --- .../transport/serializers/span_serializer.rb | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/lib/elastic_apm/transport/serializers/span_serializer.rb b/lib/elastic_apm/transport/serializers/span_serializer.rb index 4ea73d347..c5caeb2d5 100644 --- a/lib/elastic_apm/transport/serializers/span_serializer.rb +++ b/lib/elastic_apm/transport/serializers/span_serializer.rb @@ -31,7 +31,7 @@ def initialize(config) attr_reader :context_serializer def build(span) - { + payload = { span: { id: span.id, transaction_id: span.transaction.id, @@ -40,13 +40,23 @@ def build(span) type: join_type(span), duration: ms(span.duration), context: context_serializer.build(span.context), - stacktrace: span.stacktrace.to_a, timestamp: span.timestamp, trace_id: span.trace_id, sample_rate: span.sample_rate, outcome: keyword_field(span.outcome) } } + + # Only include stacktrace if it exists, has frames, and frames are valid + if span.stacktrace && !span.stacktrace.to_a.empty? + stacktrace_array = span.stacktrace.to_a + # Check if at least one frame has valid data (filename or classname) + if stacktrace_array.any? { |frame| frame[:filename] || frame[:classname] } + payload[:span][:stacktrace] = stacktrace_array + end + end + + payload end # @api private From 1488f530515388f70e3ab040bf828f3484fc3250 Mon Sep 17 00:00:00 2001 From: Gustavo de Oliveira Date: Mon, 12 Jan 2026 20:55:30 -0300 Subject: [PATCH 3/6] Remove comments --- lib/elastic_apm/transport/serializers/span_serializer.rb | 2 -- 1 file changed, 2 deletions(-) diff --git a/lib/elastic_apm/transport/serializers/span_serializer.rb b/lib/elastic_apm/transport/serializers/span_serializer.rb index c5caeb2d5..6c3b18094 100644 --- a/lib/elastic_apm/transport/serializers/span_serializer.rb +++ b/lib/elastic_apm/transport/serializers/span_serializer.rb @@ -47,10 +47,8 @@ def build(span) } } - # Only include stacktrace if it exists, has frames, and frames are valid if span.stacktrace && !span.stacktrace.to_a.empty? stacktrace_array = span.stacktrace.to_a - # Check if at least one frame has valid data (filename or classname) if stacktrace_array.any? { |frame| frame[:filename] || frame[:classname] } payload[:span][:stacktrace] = stacktrace_array end From b8c00d93309cc5ad33233f522391fe70d4f55d42 Mon Sep 17 00:00:00 2001 From: Gustavo de Oliveira Date: Mon, 12 Jan 2026 21:28:42 -0300 Subject: [PATCH 4/6] Remove duplicated attribute --- lib/elastic_apm/transaction.rb | 1 - 1 file changed, 1 deletion(-) diff --git a/lib/elastic_apm/transaction.rb b/lib/elastic_apm/transaction.rb index ad7037b08..bf149deab 100644 --- a/lib/elastic_apm/transaction.rb +++ b/lib/elastic_apm/transaction.rb @@ -109,7 +109,6 @@ def initialize( :notifications, :self_time, :span_frames_min_duration, - :started_spans, :trace_context, :transaction_max_spans, :config From 2426afe88ae6cc6709b44ecf7d12024064cba4fe Mon Sep 17 00:00:00 2001 From: Gustavo de Oliveira Date: Mon, 12 Jan 2026 21:29:03 -0300 Subject: [PATCH 5/6] Add tests to RequestMetrics --- .../metrics/request_metrics_spec.rb | 202 ++++++++++++++++++ 1 file changed, 202 insertions(+) create mode 100644 spec/elastic_apm/metrics/request_metrics_spec.rb diff --git a/spec/elastic_apm/metrics/request_metrics_spec.rb b/spec/elastic_apm/metrics/request_metrics_spec.rb new file mode 100644 index 000000000..ed95e2991 --- /dev/null +++ b/spec/elastic_apm/metrics/request_metrics_spec.rb @@ -0,0 +1,202 @@ +# Licensed to Elasticsearch B.V. under one or more contributor +# license agreements. See the NOTICE file distributed with +# this work for additional information regarding copyright +# ownership. Elasticsearch B.V. licenses this file to you under +# the Apache License, Version 2.0 (the "License"); you may +# not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, +# software distributed under the License is distributed on an +# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +# KIND, either express or implied. See the License for the +# specific language governing permissions and limitations +# under the License. + +# frozen_string_literal: true + +require 'spec_helper' +require 'elastic_apm/metrics/request_metrics' +require 'stringio' + +module ElasticAPM + RSpec.describe RequestMetrics do + let(:base_env) do + { + "HTTP_X_REQUEST_ID" => "test-request-123", + "rack.input" => StringIO.new("test body"), + "puma.request_body_wait" => 10 + } + end + + describe '#initialize' do + it 'extracts request_id from env' do + metrics = described_class.new(base_env) + expect(metrics.request_id).to eq "test-request-123" + end + + it 'extracts body size from rack.input' do + metrics = described_class.new(base_env) + expect(metrics.size).to eq 9 # "test body".length + end + + it 'extracts network_time from puma.request_body_wait' do + metrics = described_class.new(base_env) + expect(metrics.network_time).to eq 10 + end + + it 'handles missing rack.input size method' do + env = base_env.merge("rack.input" => Object.new) + metrics = described_class.new(env) + expect(metrics.size).to eq 0 + end + + it 'handles missing puma.request_body_wait' do + env = base_env.dup + env.delete("puma.request_body_wait") + metrics = described_class.new(env) + expect(metrics.network_time).to eq 0 + end + end + + describe '#started_at' do + context 'when HTTP_X_REQUEST_START is not present' do + it 'returns nil' do + metrics = described_class.new(base_env) + expect(metrics.started_at).to be_nil + end + end + + context 'with fractional seconds (NGINX format)' do + it 'parses correctly' do + timestamp = Time.now.to_f + env = base_env.merge("HTTP_X_REQUEST_START" => timestamp.to_s) + metrics = described_class.new(env) + + expect(metrics.started_at).to be_within(0.001).of(Time.at(timestamp)) + end + + it 'handles t= prefix (NGINX format)' do + timestamp = Time.now.to_f + env = base_env.merge("HTTP_X_REQUEST_START" => "t=#{timestamp}") + metrics = described_class.new(env) + + expect(metrics.started_at).to be_within(0.001).of(Time.at(timestamp)) + end + end + + context 'with whole milliseconds (Heroku format)' do + it 'parses correctly' do + timestamp_ms = (Time.now.to_f * 1000).to_i + env = base_env.merge("HTTP_X_REQUEST_START" => timestamp_ms.to_s) + metrics = described_class.new(env) + + expect(metrics.started_at).to be_within(1).of(Time.at(timestamp_ms / 1000.0)) + end + end + + context 'with whole microseconds' do + it 'parses correctly' do + timestamp_us = (Time.now.to_f * 1_000_000).to_i + env = base_env.merge("HTTP_X_REQUEST_START" => timestamp_us.to_s) + metrics = described_class.new(env) + + expect(metrics.started_at).to be_within(0.001).of(Time.at(timestamp_us / 1_000_000.0)) + end + end + + context 'with whole nanoseconds (Render format)' do + it 'parses correctly' do + timestamp_ns = (Time.now.to_f * 1_000_000_000).to_i + env = base_env.merge("HTTP_X_REQUEST_START" => timestamp_ns.to_s) + metrics = described_class.new(env) + + expect(metrics.started_at).to be_within(0.001).of(Time.at(timestamp_ns / 1_000_000_000.0)) + end + end + end + + describe '#queue_time' do + context 'when started_at is nil' do + it 'returns 0.0' do + metrics = described_class.new(base_env) + expect(metrics.queue_time).to eq 0.0 + end + end + + context 'when started_at is present' do + it 'calculates queue time in milliseconds' do + # Set request start to 100ms ago + timestamp = Time.now.to_f - 0.1 + env = base_env.merge( + "HTTP_X_REQUEST_START" => timestamp.to_s, + "puma.request_body_wait" => 0 + ) + metrics = described_class.new(env) + + # Queue time should be approximately 100ms + expect(metrics.queue_time).to be_within(20).of(100) + end + + it 'subtracts network_time from queue_time' do + # Set request start to 100ms ago + timestamp = Time.now.to_f - 0.1 + env = base_env.merge( + "HTTP_X_REQUEST_START" => timestamp.to_s, + "puma.request_body_wait" => 50 # 50ms network wait + ) + metrics = described_class.new(env) + + # Queue time should be approximately 50ms (100ms - 50ms network) + expect(metrics.queue_time).to be_within(20).of(50) + end + + it 'returns 0 for negative queue times' do + # Set request start to the future (simulating clock skew) + timestamp = Time.now.to_f + 1.0 + env = base_env.merge("HTTP_X_REQUEST_START" => timestamp.to_s) + metrics = described_class.new(env) + + expect(metrics.queue_time).to eq 0 + end + end + end + + describe '#queue_time_micros' do + it 'returns queue_time in microseconds' do + # Set request start to 100ms ago + timestamp = Time.now.to_f - 0.1 + env = base_env.merge( + "HTTP_X_REQUEST_START" => timestamp.to_s, + "puma.request_body_wait" => 0 + ) + metrics = described_class.new(env) + + # Queue time should be approximately 100,000 microseconds + expect(metrics.queue_time_micros).to be_within(20_000).of(100_000) + end + + it 'returns 0 when no request start header' do + metrics = described_class.new(base_env) + expect(metrics.queue_time_micros).to eq 0 + end + end + + describe 'timestamp cutoff constants' do + it 'has correct MILLISECONDS_CUTOFF' do + # Should be approximately year 2000 in milliseconds + expect(described_class::MILLISECONDS_CUTOFF).to eq(Time.new(2000, 1, 1).to_i * 1000) + end + + it 'has correct MICROSECONDS_CUTOFF' do + expect(described_class::MICROSECONDS_CUTOFF).to eq(described_class::MILLISECONDS_CUTOFF * 1000) + end + + it 'has correct NANOSECONDS_CUTOFF' do + expect(described_class::NANOSECONDS_CUTOFF).to eq(described_class::MICROSECONDS_CUTOFF * 1000) + end + end + end +end From b872db2c11f54bd257e9d335ace2b52527b6c4cf Mon Sep 17 00:00:00 2001 From: Gustavo de Oliveira Date: Mon, 12 Jan 2026 21:39:24 -0300 Subject: [PATCH 6/6] Add labels to metadata --- lib/elastic_apm/middleware.rb | 17 ++++++++++++++++- 1 file changed, 16 insertions(+), 1 deletion(-) diff --git a/lib/elastic_apm/middleware.rb b/lib/elastic_apm/middleware.rb index a6c166981..3fa8983f0 100644 --- a/lib/elastic_apm/middleware.rb +++ b/lib/elastic_apm/middleware.rb @@ -104,10 +104,13 @@ def config def register_queue_time(transaction, env) request_metrics = RequestMetrics.new(env) queue_time_micros = request_metrics.queue_time_micros + + add_request_metrics_labels(transaction, request_metrics) + return if queue_time_micros.zero? transaction.clock_start -= queue_time_micros - transaction.timestamp -= queue_time_micros # 350ms before + transaction.timestamp -= queue_time_micros span = ElasticAPM.start_span 'Queue Time', 'queue', subtype: 'nginx', action: 'awaiting' @@ -116,5 +119,17 @@ def register_queue_time(transaction, env) ElasticAPM.end_span(span) end + + def add_request_metrics_labels(transaction, request_metrics) + labels = transaction.context.labels + + queue_time_ms = request_metrics.queue_time + labels[:queue_time_ms] = queue_time_ms if queue_time_ms > 0 + + network_time_ms = request_metrics.network_time + labels[:network_time_ms] = network_time_ms if network_time_ms > 0 + + labels[:request_id] = request_metrics.request_id if request_metrics.request_id + end end end