From d7fb0f2d9965741a7fef21ba40971734cf87b709 Mon Sep 17 00:00:00 2001 From: Axel Gustav Date: Tue, 10 Dec 2024 21:03:01 -0400 Subject: [PATCH 1/6] Track request queue time based on available request headers --- lib/rorvswild/plugin/middleware.rb | 53 ++++++++++++++++++++++++++++++ test/plugin/middleware_test.rb | 43 ++++++++++++++++++++++-- 2 files changed, 94 insertions(+), 2 deletions(-) diff --git a/lib/rorvswild/plugin/middleware.rb b/lib/rorvswild/plugin/middleware.rb index ea514c3..5c4fe24 100644 --- a/lib/rorvswild/plugin/middleware.rb +++ b/lib/rorvswild/plugin/middleware.rb @@ -3,6 +3,52 @@ module RorVsWild module Plugin class Middleware + module RequestQueueTime + REQUEST_START_HEADER = 'HTTP_X_REQUEST_START'.freeze + QUEUE_START_HEADER = 'HTTP_X_QUEUE_START'.freeze + MIDDLEWARE_START_HEADER = 'HTTP_X_MIDDLEWARE_START'.freeze + + ACCEPTABLE_HEADERS = [ + REQUEST_START_HEADER, + QUEUE_START_HEADER, + MIDDLEWARE_START_HEADER + ].freeze + + MINIMUM_TIMESTAMP = 1577836800.freeze # 2020/01/01 UTC + DIVISORS = [1_000_000, 1_000, 1].freeze + + def parse_queue_time_header(headers) + return unless headers + + earliest = nil + + ACCEPTABLE_HEADERS.each do |header| + next unless headers[header] + + timestamp = parse_timestamp(headers[header].gsub("t=", "")) + if timestamp && (!earliest || timestamp < earliest) + earliest = timestamp + end + end + + [earliest, Time.now.to_f].min if earliest + end + + private + + def parse_timestamp(timestamp) + DIVISORS.each do |divisor| + begin + t = (timestamp.to_f / divisor) + return t if t > MINIMUM_TIMESTAMP + rescue RangeError + end + end + end + end + + include RequestQueueTime + def self.setup return if @installed Rails.application.config.middleware.unshift(RorVsWild::Plugin::Middleware, nil) if defined?(Rails) @@ -16,6 +62,7 @@ def initialize(app, config) def call(env) RorVsWild.agent.start_request RorVsWild.agent.current_data[:path] = env["ORIGINAL_FULLPATH"] + RorVsWild.agent.current_data[:queue_time] = calculate_queue_time(env) section = RorVsWild::Section.start section.file, section.line = rails_engine_location section.commands << "Rails::Engine#call" @@ -28,6 +75,12 @@ def call(env) private + def calculate_queue_time(headers) + queue_time_from_header = parse_queue_time_header(headers) + + ((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..3ffa3bc 100644 --- a/test/plugin/middleware_test.rb +++ b/test/plugin/middleware_test.rb @@ -5,7 +5,7 @@ class RorVsWild::Plugin::MiddlewareTest < Minitest::Test def test_callback agent # Load agent - request = {"ORIGINAL_FULLPATH" => "/foo/bar"} + request = { "ORIGINAL_FULLPATH" => "/foo/bar" } app = mock(call: nil) middleware = RorVsWild::Plugin::Middleware.new(app, nil) middleware.stubs(rails_engine_location: ["/rails/lib/engine.rb", 12]) @@ -13,6 +13,45 @@ def test_callback assert_equal("/foo/bar", agent.current_data[:path]) assert_equal(1, agent.current_data[:sections].size) assert_equal("Rails::Engine#call", agent.current_data[:sections][0].command) + assert_nil(agent.current_data[:queue_time]) end -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_in_delta(123, agent.current_data[:queue_time], 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_in_delta(234, agent.current_data[:queue_time], 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_in_delta(345, agent.current_data[:queue_time], 10) + end + + private + + def unix_timestamp_seconds + Time.now.to_f + end +end From b943b3f7e5c818b82c02964f704936b914417d49 Mon Sep 17 00:00:00 2001 From: Axel Gustav Date: Sun, 29 Dec 2024 13:59:19 -0400 Subject: [PATCH 2/6] Move queue_time into separate section --- lib/rorvswild/plugin/middleware.rb | 33 ++++++++++++++++++-------- test/plugin/middleware_test.rb | 37 ++++++++++++++++++++++++++---- 2 files changed, 55 insertions(+), 15 deletions(-) diff --git a/lib/rorvswild/plugin/middleware.rb b/lib/rorvswild/plugin/middleware.rb index 5c4fe24..22d86e1 100644 --- a/lib/rorvswild/plugin/middleware.rb +++ b/lib/rorvswild/plugin/middleware.rb @@ -17,17 +17,17 @@ module RequestQueueTime MINIMUM_TIMESTAMP = 1577836800.freeze # 2020/01/01 UTC DIVISORS = [1_000_000, 1_000, 1].freeze - def parse_queue_time_header(headers) - return unless headers + def parse_queue_time_header(env) + return unless env earliest = nil ACCEPTABLE_HEADERS.each do |header| - next unless headers[header] - - timestamp = parse_timestamp(headers[header].gsub("t=", "")) - if timestamp && (!earliest || timestamp < earliest) - earliest = timestamp + if (header_value = env[header]) + timestamp = parse_timestamp(header_value.gsub("t=", "")) + if timestamp && (!earliest || timestamp < earliest) + earliest = timestamp + end end end @@ -61,8 +61,8 @@ def initialize(app, config) def call(env) RorVsWild.agent.start_request + report_queue_time(env) RorVsWild.agent.current_data[:path] = env["ORIGINAL_FULLPATH"] - RorVsWild.agent.current_data[:queue_time] = calculate_queue_time(env) section = RorVsWild::Section.start section.file, section.line = rails_engine_location section.commands << "Rails::Engine#call" @@ -75,8 +75,21 @@ def call(env) private - def calculate_queue_time(headers) - queue_time_from_header = parse_queue_time_header(headers) + def report_queue_time(env) + if queue_time = calculate_queue_time(env) + section = Section.new + section.stop + section.total_ms = queue_time + section.gc_time_ms = 0 + section.file = "request-queue" + section.line = 0 + section.kind = "queue" + RorVsWild.agent.add_section(section) + end + 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 diff --git a/test/plugin/middleware_test.rb b/test/plugin/middleware_test.rb index 3ffa3bc..b285898 100644 --- a/test/plugin/middleware_test.rb +++ b/test/plugin/middleware_test.rb @@ -5,7 +5,7 @@ class RorVsWild::Plugin::MiddlewareTest < Minitest::Test def test_callback agent # Load agent - request = { "ORIGINAL_FULLPATH" => "/foo/bar" } + request = {"ORIGINAL_FULLPATH" => "/foo/bar"} app = mock(call: nil) middleware = RorVsWild::Plugin::Middleware.new(app, nil) middleware.stubs(rails_engine_location: ["/rails/lib/engine.rb", 12]) @@ -13,7 +13,23 @@ def test_callback assert_equal("/foo/bar", agent.current_data[:path]) assert_equal(1, agent.current_data[:sections].size) assert_equal("Rails::Engine#call", agent.current_data[:sections][0].command) - assert_nil(agent.current_data[:queue_time]) + 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 @@ -23,8 +39,12 @@ def test_queue_time_secs 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_in_delta(123, agent.current_data[:queue_time], 10) + + 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 @@ -34,8 +54,12 @@ def test_queue_time_millis 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_in_delta(234, agent.current_data[:queue_time], 10) + + 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 @@ -46,7 +70,10 @@ def test_queue_time_micros middleware = RorVsWild::Plugin::Middleware.new(app, nil) middleware.stubs(rails_engine_location: ["/rails/lib/engine.rb", 12]) middleware.call(request) - assert_in_delta(345, agent.current_data[:queue_time], 10) + + 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 From 784b1bacca5212b960411545ac3e3ec6a1d85bdc Mon Sep 17 00:00:00 2001 From: Axel Gustav Date: Fri, 24 Jan 2025 20:10:14 -0400 Subject: [PATCH 3/6] Feedback --- lib/rorvswild/agent.rb | 1 + lib/rorvswild/plugin/middleware.rb | 11 ++++------- 2 files changed, 5 insertions(+), 7 deletions(-) diff --git a/lib/rorvswild/agent.rb b/lib/rorvswild/agent.rb index 4a56c6f..fceb1bf 100644 --- a/lib/rorvswild/agent.rb +++ b/lib/rorvswild/agent.rb @@ -123,6 +123,7 @@ def stop_request gc = Section.stop_gc_timing(data[:gc_section]) data[:sections] << gc if gc.calls > 0 && gc.total_ms > 0 data[:runtime] = RorVsWild.clock_milliseconds - current_data[:started_at] + data[:runtime] += data[:sections].sum(0) { |s| s.kind == "queue" ? s.self_ms : 0 } queue_request end diff --git a/lib/rorvswild/plugin/middleware.rb b/lib/rorvswild/plugin/middleware.rb index 22d86e1..adc4a29 100644 --- a/lib/rorvswild/plugin/middleware.rb +++ b/lib/rorvswild/plugin/middleware.rb @@ -4,14 +4,11 @@ module RorVsWild module Plugin class Middleware module RequestQueueTime - REQUEST_START_HEADER = 'HTTP_X_REQUEST_START'.freeze - QUEUE_START_HEADER = 'HTTP_X_QUEUE_START'.freeze - MIDDLEWARE_START_HEADER = 'HTTP_X_MIDDLEWARE_START'.freeze ACCEPTABLE_HEADERS = [ - REQUEST_START_HEADER, - QUEUE_START_HEADER, - MIDDLEWARE_START_HEADER + 'HTTP_X_REQUEST_START', + 'HTTP_X_QUEUE_START', + 'HTTP_X_MIDDLEWARE_START' ].freeze MINIMUM_TIMESTAMP = 1577836800.freeze # 2020/01/01 UTC @@ -24,7 +21,7 @@ def parse_queue_time_header(env) ACCEPTABLE_HEADERS.each do |header| if (header_value = env[header]) - timestamp = parse_timestamp(header_value.gsub("t=", "")) + timestamp = parse_timestamp(header_value.delete_prefix("t=")) if timestamp && (!earliest || timestamp < earliest) earliest = timestamp end From 5aa9d03c50bccc4329dc7d1f76fb987bae6e36a3 Mon Sep 17 00:00:00 2001 From: Axel Gustav Date: Sat, 25 Jan 2025 12:50:09 -0400 Subject: [PATCH 4/6] Use current_data[:queued_at] for runtime calculation --- lib/rorvswild/agent.rb | 3 +-- lib/rorvswild/plugin/middleware.rb | 1 + test/plugin/middleware_test.rb | 3 +++ 3 files changed, 5 insertions(+), 2 deletions(-) diff --git a/lib/rorvswild/agent.rb b/lib/rorvswild/agent.rb index fceb1bf..54292a9 100644 --- a/lib/rorvswild/agent.rb +++ b/lib/rorvswild/agent.rb @@ -122,8 +122,7 @@ def stop_request return unless data = current_data gc = Section.stop_gc_timing(data[:gc_section]) data[:sections] << gc if gc.calls > 0 && gc.total_ms > 0 - data[:runtime] = RorVsWild.clock_milliseconds - current_data[:started_at] - data[:runtime] += data[:sections].sum(0) { |s| s.kind == "queue" ? s.self_ms : 0 } + data[:runtime] = RorVsWild.clock_milliseconds - (current_data[:queued_at] || current_data[:started_at]) queue_request end diff --git a/lib/rorvswild/plugin/middleware.rb b/lib/rorvswild/plugin/middleware.rb index adc4a29..fe4bdea 100644 --- a/lib/rorvswild/plugin/middleware.rb +++ b/lib/rorvswild/plugin/middleware.rb @@ -82,6 +82,7 @@ def report_queue_time(env) section.line = 0 section.kind = "queue" RorVsWild.agent.add_section(section) + RorVsWild.agent.current_data[:queued_at] = RorVsWild.agent.current_data[:started_at] - queue_time end end diff --git a/test/plugin/middleware_test.rb b/test/plugin/middleware_test.rb index b285898..331dda0 100644 --- a/test/plugin/middleware_test.rb +++ b/test/plugin/middleware_test.rb @@ -24,6 +24,9 @@ def test_queue_time_section middleware.call(request) + assert_predicate agent.current_data[:queued_at], :present? + assert agent.current_data[:queued_at] <= agent.current_data[:started_at] + assert_equal(2, agent.current_data[:sections].size) queue_time_section = agent.current_data[:sections][0] assert_equal "request-queue", queue_time_section.file From 945195ece832ece7d74bff67635e536d3b9223fc Mon Sep 17 00:00:00 2001 From: Axel Gustav Date: Sun, 26 Jan 2025 13:04:12 -0400 Subject: [PATCH 5/6] Refactor queue_time_ms --- lib/rorvswild/agent.rb | 10 ++++---- lib/rorvswild/plugin/middleware.rb | 38 +++++++++++++++--------------- test/plugin/middleware_test.rb | 3 --- 3 files changed, 24 insertions(+), 27 deletions(-) diff --git a/lib/rorvswild/agent.rb b/lib/rorvswild/agent.rb index 54292a9..019f5a6 100644 --- a/lib/rorvswild/agent.rb +++ b/lib/rorvswild/agent.rb @@ -114,15 +114,15 @@ 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 return unless data = current_data gc = Section.stop_gc_timing(data[:gc_section]) data[:sections] << gc if gc.calls > 0 && gc.total_ms > 0 - data[:runtime] = RorVsWild.clock_milliseconds - (current_data[:queued_at] || current_data[:started_at]) + data[:runtime] = RorVsWild.clock_milliseconds - current_data[:started_at] queue_request end @@ -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 fe4bdea..931b972 100644 --- a/lib/rorvswild/plugin/middleware.rb +++ b/lib/rorvswild/plugin/middleware.rb @@ -34,12 +34,12 @@ def parse_queue_time_header(env) private def parse_timestamp(timestamp) + timestamp = timestamp.to_f + return unless timestamp.finite? + DIVISORS.each do |divisor| - begin - t = (timestamp.to_f / divisor) - return t if t > MINIMUM_TIMESTAMP - rescue RangeError - end + t = timestamp / divisor + return t if t > MINIMUM_TIMESTAMP end end end @@ -57,9 +57,10 @@ def initialize(app, config) end def call(env) - RorVsWild.agent.start_request - report_queue_time(env) + 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" @@ -72,18 +73,17 @@ def call(env) private - def report_queue_time(env) - if queue_time = calculate_queue_time(env) - section = Section.new - section.stop - section.total_ms = queue_time - section.gc_time_ms = 0 - section.file = "request-queue" - section.line = 0 - section.kind = "queue" - RorVsWild.agent.add_section(section) - RorVsWild.agent.current_data[:queued_at] = RorVsWild.agent.current_data[:started_at] - queue_time - end + 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) diff --git a/test/plugin/middleware_test.rb b/test/plugin/middleware_test.rb index 331dda0..b285898 100644 --- a/test/plugin/middleware_test.rb +++ b/test/plugin/middleware_test.rb @@ -24,9 +24,6 @@ def test_queue_time_section middleware.call(request) - assert_predicate agent.current_data[:queued_at], :present? - assert agent.current_data[:queued_at] <= agent.current_data[:started_at] - assert_equal(2, agent.current_data[:sections].size) queue_time_section = agent.current_data[:sections][0] assert_equal "request-queue", queue_time_section.file From 60611123ce4a42dc6d22200a198649d82a84b79f Mon Sep 17 00:00:00 2001 From: Axel Gustav Date: Mon, 27 Jan 2025 20:29:03 -0400 Subject: [PATCH 6/6] Add changelog entry --- CHANGELOG.md | 6 ++++++ 1 file changed, 6 insertions(+) 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)