Skip to content

Commit 06a59ec

Browse files
samuel-williams-shopifysamuel-williams-shopify
committed
Add request queue time histogram metric to server metrics provider
- Adds ASYNC_HTTP_SERVER_REQUEST_QUEUE_TIME histogram metric - Calculates queue time from x-request-start header - Supports multiple timestamp formats: - nginx format with 't=' prefix (t=1234567890.123) - Plain Unix timestamp in seconds (1234567890.123) - Unix timestamp in milliseconds (1234567890123) - Unix timestamp in microseconds (1234567890123456) - Includes sanity checks for reasonable queue times (< 1 hour) - Adds comprehensive test coverage for various timestamp formats - Gracefully handles missing or invalid headers
1 parent 5929731 commit 06a59ec

File tree

2 files changed

+230
-0
lines changed

2 files changed

+230
-0
lines changed

‎lib/metrics/provider/async/http/server.rb‎

Lines changed: 54 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,10 +9,20 @@
99
Metrics::Provider(Async::HTTP::Server) do
1010
ASYNC_HTTP_SERVER_REQUEST_INITIATED = Metrics.metric("async.http.server.request.initiated", :counter, description: "The number of HTTP server requests initiated.")
1111
ASYNC_HTTP_SERVER_REQUEST_FINISHED = Metrics.metric("async.http.server.request.finished", :counter, description: "The number of HTTP server requests finished.")
12+
ASYNC_HTTP_SERVER_REQUEST_QUEUE_TIME = Metrics.metric("async.http.server.request.queue_time", :histogram, description: "The time spent waiting in queue before processing (in seconds), based on the x-request-start header.")
1213

1314
def call(request)
1415
ASYNC_HTTP_SERVER_REQUEST_INITIATED.emit(1, tags: ["method:#{request.method}"])
1516

17+
# Calculate queue time from x-request-start header if present
18+
if request_start_header = request.headers["x-request-start"]
19+
queue_time = calculate_queue_time(request_start_header.first)
20+
21+
if queue_time
22+
ASYNC_HTTP_SERVER_REQUEST_QUEUE_TIME.emit(queue_time, tags: ["method:#{request.method}"])
23+
end
24+
end
25+
1626
if response = super(request)
1727
ASYNC_HTTP_SERVER_REQUEST_FINISHED.emit(1, tags: ["method:#{request.method}", "status:#{response.status}"])
1828
return response
@@ -24,4 +34,48 @@ def call(request)
2434
ASYNC_HTTP_SERVER_REQUEST_FINISHED.emit(1, tags: ["method:#{request.method}", "status:failed"])
2535
end
2636
end
37+
38+
private
39+
40+
# Parse x-request-start header and calculate queue time in seconds.
41+
# Supports multiple formats:
42+
# - "t=1234567890.123" (nginx format with 't=' prefix)
43+
# - "1234567890.123" (Unix timestamp in seconds)
44+
# - "1234567890123" (Unix timestamp in milliseconds)
45+
def calculate_queue_time(header_value)
46+
return nil unless header_value
47+
48+
# Remove 't=' prefix if present (nginx format)
49+
timestamp_str = header_value.sub(/^t=/, "")
50+
51+
begin
52+
timestamp = Float(timestamp_str)
53+
54+
# If timestamp is very large, it's likely in milliseconds or microseconds
55+
# Convert to seconds if necessary
56+
if timestamp > 10_000_000_000
57+
# Likely milliseconds (13 digits) or microseconds (16 digits)
58+
if timestamp > 10_000_000_000_000
59+
# Microseconds (16 digits)
60+
timestamp = timestamp / 1_000_000.0
61+
else
62+
# Milliseconds (13 digits)
63+
timestamp = timestamp / 1000.0
64+
end
65+
end
66+
67+
current_time = Process.clock_gettime(Process::CLOCK_REALTIME)
68+
queue_time = current_time - timestamp
69+
70+
# Sanity check: queue time should be positive and reasonable (< 1 hour)
71+
if queue_time > 0 && queue_time < 3600
72+
return queue_time
73+
end
74+
rescue ArgumentError, TypeError
75+
# Invalid timestamp format, ignore
76+
return nil
77+
end
78+
79+
return nil
80+
end
2781
end

‎test/metrics/provider/async/http/server.rb‎

Lines changed: 176 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,176 @@
1+
# frozen_string_literal: true
2+
3+
# Released under the MIT License.
4+
# Copyright, 2025, by Samuel Williams.
5+
6+
require "metrics/provider/async/http/server"
7+
require "async/http/server"
8+
require "async/http/endpoint"
9+
require "async/http/client"
10+
require "protocol/http/middleware"
11+
require "sus/fixtures/async"
12+
13+
describe Async::HTTP::Server do
14+
include Sus::Fixtures::Async::ReactorContext
15+
16+
let(:endpoint) {Async::HTTP::Endpoint.parse("http://localhost:0")}
17+
18+
with "metrics provider" do
19+
let(:app) do
20+
Protocol::HTTP::Middleware.for do |request|
21+
Protocol::HTTP::Response[200, {}, ["Hello, World!"]]
22+
end
23+
end
24+
25+
let(:server) {subject.new(app, endpoint)}
26+
27+
it "emits queue time metric when x-request-start header is present" do
28+
# Start the server
29+
server_task = server.run
30+
bound_endpoint = server_task.wait_until_ready
31+
32+
# Calculate a timestamp 100ms in the past (nginx format with 't=' prefix)
33+
request_start = Process.clock_gettime(Process::CLOCK_REALTIME) - 0.1
34+
35+
# Expect the histogram metric to be emitted with a value around 0.1 seconds
36+
expect(Async::HTTP::Server::ASYNC_HTTP_SERVER_REQUEST_QUEUE_TIME).to receive(:emit) do |value, tags:|
37+
expect(value).to be_within(0.05).of(0.1)
38+
expect(tags).to be == ["method:GET"]
39+
end
40+
41+
# Make a request with the x-request-start header
42+
client = Async::HTTP::Client.new(bound_endpoint)
43+
headers = [["x-request-start", "t=#{request_start}"]]
44+
response = client.get("/", headers)
45+
46+
expect(response.status).to be == 200
47+
response.finish
48+
49+
client.close
50+
server_task.stop
51+
end
52+
53+
it "handles nginx-style timestamp format (t=prefix)" do
54+
server_task = server.run
55+
bound_endpoint = server_task.wait_until_ready
56+
57+
request_start = Process.clock_gettime(Process::CLOCK_REALTIME) - 0.05
58+
59+
expect(Async::HTTP::Server::ASYNC_HTTP_SERVER_REQUEST_QUEUE_TIME).to receive(:emit) do |value, tags:|
60+
expect(value).to be > 0
61+
expect(value).to be < 1
62+
end
63+
64+
client = Async::HTTP::Client.new(bound_endpoint)
65+
headers = [["x-request-start", "t=#{request_start}"]]
66+
response = client.get("/", headers)
67+
68+
expect(response.status).to be == 200
69+
response.finish
70+
71+
client.close
72+
server_task.stop
73+
end
74+
75+
it "handles plain Unix timestamp format" do
76+
server_task = server.run
77+
bound_endpoint = server_task.wait_until_ready
78+
79+
request_start = Process.clock_gettime(Process::CLOCK_REALTIME) - 0.05
80+
81+
expect(Async::HTTP::Server::ASYNC_HTTP_SERVER_REQUEST_QUEUE_TIME).to receive(:emit) do |value, tags:|
82+
expect(value).to be > 0
83+
expect(value).to be < 1
84+
end
85+
86+
client = Async::HTTP::Client.new(bound_endpoint)
87+
headers = [["x-request-start", request_start.to_s]]
88+
response = client.get("/", headers)
89+
90+
expect(response.status).to be == 200
91+
response.finish
92+
93+
client.close
94+
server_task.stop
95+
end
96+
97+
it "handles millisecond timestamp format" do
98+
server_task = server.run
99+
bound_endpoint = server_task.wait_until_ready
100+
101+
request_start_ms = (Process.clock_gettime(Process::CLOCK_REALTIME) * 1000).to_i - 50
102+
103+
expect(Async::HTTP::Server::ASYNC_HTTP_SERVER_REQUEST_QUEUE_TIME).to receive(:emit) do |value, tags:|
104+
expect(value).to be > 0
105+
expect(value).to be < 1
106+
end
107+
108+
client = Async::HTTP::Client.new(bound_endpoint)
109+
headers = [["x-request-start", request_start_ms.to_s]]
110+
response = client.get("/", headers)
111+
112+
expect(response.status).to be == 200
113+
response.finish
114+
115+
client.close
116+
server_task.stop
117+
end
118+
119+
it "does not emit queue time metric when x-request-start header is missing" do
120+
server_task = server.run
121+
bound_endpoint = server_task.wait_until_ready
122+
123+
# Should not emit the queue time metric
124+
expect(Async::HTTP::Server::ASYNC_HTTP_SERVER_REQUEST_QUEUE_TIME).not.to receive(:emit)
125+
126+
client = Async::HTTP::Client.new(bound_endpoint)
127+
response = client.get("/")
128+
129+
expect(response.status).to be == 200
130+
response.finish
131+
132+
client.close
133+
server_task.stop
134+
end
135+
136+
it "ignores invalid timestamp formats" do
137+
server_task = server.run
138+
bound_endpoint = server_task.wait_until_ready
139+
140+
# Should not emit the queue time metric for invalid timestamp
141+
expect(Async::HTTP::Server::ASYNC_HTTP_SERVER_REQUEST_QUEUE_TIME).not.to receive(:emit)
142+
143+
client = Async::HTTP::Client.new(bound_endpoint)
144+
headers = [["x-request-start", "invalid-timestamp"]]
145+
response = client.get("/", headers)
146+
147+
expect(response.status).to be == 200
148+
response.finish
149+
150+
client.close
151+
server_task.stop
152+
end
153+
154+
it "ignores unreasonable queue times" do
155+
server_task = server.run
156+
bound_endpoint = server_task.wait_until_ready
157+
158+
# Timestamp from 2 hours ago (unreasonable)
159+
request_start = Process.clock_gettime(Process::CLOCK_REALTIME) - 7200
160+
161+
# Should not emit the queue time metric for unreasonable timestamp
162+
expect(Async::HTTP::Server::ASYNC_HTTP_SERVER_REQUEST_QUEUE_TIME).not.to receive(:emit)
163+
164+
client = Async::HTTP::Client.new(bound_endpoint)
165+
headers = [["x-request-start", "t=#{request_start}"]]
166+
response = client.get("/", headers)
167+
168+
expect(response.status).to be == 200
169+
response.finish
170+
171+
client.close
172+
server_task.stop
173+
end
174+
end
175+
end
176+

0 commit comments

Comments
 (0)