diff --git a/CHANGELOG.md b/CHANGELOG.md index 64d884f..0c3c758 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,12 @@ ### Unreleased * Measure render collection +* Requests now report the time they have been queued by the proxy before reaching the application. + + A section with the kind `queue` reports the time between the timestamp set by the HTTP proxy + when the request was received and the time the application started processing the request. + + This time is also included into the total runtime of the request. ## 1.8.1 (2024-10-17) diff --git a/lib/rorvswild/agent.rb b/lib/rorvswild/agent.rb index 4a56c6f..019f5a6 100644 --- a/lib/rorvswild/agent.rb +++ b/lib/rorvswild/agent.rb @@ -114,8 +114,8 @@ def measure_job(name, parameters: nil, &block) end end - def start_request - current_data || initialize_data + def start_request(queue_time_ms = 0) + current_data || initialize_data(queue_time_ms) end def stop_request @@ -195,9 +195,9 @@ def ignored_exception?(exception) private - def initialize_data + def initialize_data(queue_time_ms = 0) Thread.current[:rorvswild_data] = { - started_at: RorVsWild.clock_milliseconds, + started_at: RorVsWild.clock_milliseconds - queue_time_ms, gc_section: Section.start_gc_timing, environment: Host.to_h, section_stack: [], diff --git a/lib/rorvswild/plugin/middleware.rb b/lib/rorvswild/plugin/middleware.rb index ea514c3..931b972 100644 --- a/lib/rorvswild/plugin/middleware.rb +++ b/lib/rorvswild/plugin/middleware.rb @@ -3,6 +3,49 @@ module RorVsWild module Plugin class Middleware + module RequestQueueTime + + ACCEPTABLE_HEADERS = [ + 'HTTP_X_REQUEST_START', + 'HTTP_X_QUEUE_START', + 'HTTP_X_MIDDLEWARE_START' + ].freeze + + MINIMUM_TIMESTAMP = 1577836800.freeze # 2020/01/01 UTC + DIVISORS = [1_000_000, 1_000, 1].freeze + + def parse_queue_time_header(env) + return unless env + + earliest = nil + + ACCEPTABLE_HEADERS.each do |header| + if (header_value = env[header]) + timestamp = parse_timestamp(header_value.delete_prefix("t=")) + if timestamp && (!earliest || timestamp < earliest) + earliest = timestamp + end + end + end + + [earliest, Time.now.to_f].min if earliest + end + + private + + def parse_timestamp(timestamp) + timestamp = timestamp.to_f + return unless timestamp.finite? + + DIVISORS.each do |divisor| + t = timestamp / divisor + return t if t > MINIMUM_TIMESTAMP + end + end + end + + include RequestQueueTime + def self.setup return if @installed Rails.application.config.middleware.unshift(RorVsWild::Plugin::Middleware, nil) if defined?(Rails) @@ -14,8 +57,10 @@ def initialize(app, config) end def call(env) - RorVsWild.agent.start_request + queue_time_ms = calculate_queue_time(env) + RorVsWild.agent.start_request(queue_time_ms || 0) RorVsWild.agent.current_data[:path] = env["ORIGINAL_FULLPATH"] + add_queue_time_section(queue_time_ms) section = RorVsWild::Section.start section.file, section.line = rails_engine_location section.commands << "Rails::Engine#call" @@ -28,6 +73,25 @@ def call(env) private + def add_queue_time_section(queue_time_ms) + return unless queue_time_ms + + section = Section.new + section.stop + section.total_ms = queue_time_ms + section.gc_time_ms = 0 + section.file = "request-queue" + section.line = 0 + section.kind = "queue" + RorVsWild.agent.add_section(section) + end + + def calculate_queue_time(env) + queue_time_from_header = parse_queue_time_header(env) + + ((Time.now.to_f - queue_time_from_header) * 1000).round if queue_time_from_header + end + def rails_engine_location @rails_engine_location = ::Rails::Engine.instance_method(:call).source_location end diff --git a/test/plugin/middleware_test.rb b/test/plugin/middleware_test.rb index 94e1a8a..b285898 100644 --- a/test/plugin/middleware_test.rb +++ b/test/plugin/middleware_test.rb @@ -14,5 +14,71 @@ def test_callback assert_equal(1, agent.current_data[:sections].size) assert_equal("Rails::Engine#call", agent.current_data[:sections][0].command) end -end + def test_queue_time_section + agent # Load agent + request = {"HTTP_X_REQUEST_START" => unix_timestamp_seconds.to_s} + app = mock(call: nil) + middleware = RorVsWild::Plugin::Middleware.new(app, nil) + middleware.stubs(rails_engine_location: ["/rails/lib/engine.rb", 12]) + + middleware.call(request) + + assert_equal(2, agent.current_data[:sections].size) + queue_time_section = agent.current_data[:sections][0] + assert_equal "request-queue", queue_time_section.file + assert_equal "queue", queue_time_section.kind + assert_equal 0, queue_time_section.line + assert_equal 0, queue_time_section.gc_time_ms + end + + def test_queue_time_secs + agent # Load agent + request_start = unix_timestamp_seconds - 0.123 + request = {"HTTP_X_REQUEST_START" => request_start.to_s} + app = mock(call: nil) + middleware = RorVsWild::Plugin::Middleware.new(app, nil) + middleware.stubs(rails_engine_location: ["/rails/lib/engine.rb", 12]) + + middleware.call(request) + + assert_equal(2, agent.current_data[:sections].size) + queue_time_section = agent.current_data[:sections][0] + assert_in_delta(123, queue_time_section.total_ms, 10) + end + + def test_queue_time_millis + agent # Load agent + request_start = unix_timestamp_seconds * 1000 - 234 + request = { "HTTP_X_QUEUE_START" => request_start.to_s } + app = mock(call: nil) + middleware = RorVsWild::Plugin::Middleware.new(app, nil) + middleware.stubs(rails_engine_location: ["/rails/lib/engine.rb", 12]) + + middleware.call(request) + + assert_equal(2, agent.current_data[:sections].size) + queue_time_section = agent.current_data[:sections][0] + assert_in_delta(234, queue_time_section.total_ms, 10) + end + + def test_queue_time_micros + agent # Load agent + request_start = unix_timestamp_seconds * 1_000_000 - 345_000 + request = { "HTTP_X_MIDDLEWARE_START" => request_start.to_s } + app = mock(call: nil) + middleware = RorVsWild::Plugin::Middleware.new(app, nil) + middleware.stubs(rails_engine_location: ["/rails/lib/engine.rb", 12]) + middleware.call(request) + + assert_equal(2, agent.current_data[:sections].size) + queue_time_section = agent.current_data[:sections][0] + assert_in_delta(345, queue_time_section.total_ms, 10) + end + + private + + def unix_timestamp_seconds + Time.now.to_f + end +end