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 diff --git a/lib/elastic_apm/transaction.rb b/lib/elastic_apm/transaction.rb index fefec9253..a09a39373 100644 --- a/lib/elastic_apm/transaction.rb +++ b/lib/elastic_apm/transaction.rb @@ -110,8 +110,6 @@ def initialize( :self_time, :sample_rate, :span_frames_min_duration, - :started_spans, - :timestamp, :trace_context, :transaction_max_spans, :config diff --git a/lib/elastic_apm/transport/serializers/span_serializer.rb b/lib/elastic_apm/transport/serializers/span_serializer.rb index 4ea73d347..6c3b18094 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,21 @@ 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) } } + + if span.stacktrace && !span.stacktrace.to_a.empty? + stacktrace_array = span.stacktrace.to_a + if stacktrace_array.any? { |frame| frame[:filename] || frame[:classname] } + payload[:span][:stacktrace] = stacktrace_array + end + end + + payload end # @api private 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