Skip to content

Commit c9e99da

Browse files
byshingclaude
andcommitted
feat: add server processing time and request ID to timing output
Print x-envoy-upstream-service-time (server processing) and x-request-id from response headers when --timing flag is set. Also sort IPv4 before IPv6 in DNS resolver to avoid IPv6 fallback timeout inflating connect (TCP+TLS) time. Co-Authored-By: Claude Sonnet 4.6 (1M context) <noreply@anthropic.com>
1 parent 31fc132 commit c9e99da

2 files changed

Lines changed: 54 additions & 13 deletions

File tree

src/exchange/client.rs

Lines changed: 19 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -292,10 +292,16 @@ impl BitmexClient {
292292
}
293293

294294
/// Print timing summary to stderr. Call after body is fully read.
295-
fn end_request(&self, method: &str, url: &str) {
295+
fn end_request(
296+
&self,
297+
method: &str,
298+
url: &str,
299+
server_ms: Option<&str>,
300+
request_id: Option<&str>,
301+
) {
296302
if let Some(ref handle) = self.timing {
297303
if let Ok(phases) = handle.lock() {
298-
super::timing::print_timing(&phases, method, url);
304+
super::timing::print_timing(&phases, method, url, server_ms, request_id);
299305
}
300306
}
301307
}
@@ -312,6 +318,16 @@ impl BitmexClient {
312318
.get("x-ratelimit-reset")
313319
.and_then(|v| v.to_str().ok())
314320
.and_then(|s| s.parse::<u64>().ok());
321+
let server_ms = resp
322+
.headers()
323+
.get("x-envoy-upstream-service-time")
324+
.and_then(|v| v.to_str().ok())
325+
.map(str::to_owned);
326+
let request_id = resp
327+
.headers()
328+
.get("x-request-id")
329+
.and_then(|v| v.to_str().ok())
330+
.map(str::to_owned);
315331

316332
// Record TTFB — response headers have arrived.
317333
if let Some(ref handle) = self.timing {
@@ -329,7 +345,7 @@ impl BitmexClient {
329345
phases.transfer_end = Some(Instant::now());
330346
}
331347
}
332-
self.end_request(method, url);
348+
self.end_request(method, url, server_ms.as_deref(), request_id.as_deref());
333349

334350
if self.verbose {
335351
crate::cli::output::verbose(&format!("Status: {status}"));

src/exchange/timing.rs

Lines changed: 35 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -71,25 +71,40 @@ pub(crate) fn new_handle() -> TimingHandle {
7171
// Output
7272
// ---------------------------------------------------------------------------
7373

74-
pub(crate) fn print_timing(phases: &Phases, method: &str, url: &str) {
74+
pub(crate) fn print_timing(
75+
phases: &Phases,
76+
method: &str,
77+
url: &str,
78+
server_ms: Option<&str>,
79+
request_id: Option<&str>,
80+
) {
7581
let ms = |d: Option<Duration>| -> String {
7682
d.map(|d| format!("{:.0}ms", d.as_secs_f64() * 1000.0))
7783
.unwrap_or_else(|| "-".to_string())
7884
};
7985

80-
eprintln!(
86+
let mut output = format!(
8187
"\n── Timing: {method} {url}\n\
82-
{:>16} {}\n\
83-
{:>16} {}\n\
84-
{:>16} {}\n\
85-
{:>16} {}\n\
86-
{:>16} {}",
88+
{:>22} {}\n\
89+
{:>22} {}\n\
90+
{:>22} {}\n\
91+
{:>22} {}\n\
92+
{:>22} {}",
8793
"namelookup:", ms(phases.namelookup()),
8894
"connect (TCP+TLS):", ms(phases.appconnect()),
8995
"starttransfer:", ms(phases.starttransfer()),
9096
"transfer:", ms(phases.transfer()),
9197
"total:", ms(phases.total()),
9298
);
99+
100+
if let Some(s) = server_ms {
101+
output.push_str(&format!("\n{:>22} {}ms", "server processing:", s));
102+
}
103+
if let Some(id) = request_id {
104+
output.push_str(&format!("\n{:>22} {}", "x-request-id:", id));
105+
}
106+
107+
eprintln!("{output}");
93108
}
94109

95110
// ---------------------------------------------------------------------------
@@ -116,10 +131,20 @@ impl Resolve for TimingDnsResolver {
116131
phases.dns_start = Some(Instant::now());
117132
}
118133

134+
let lookup = tokio::net::lookup_host(format!("{}:0", host)).await;
135+
119136
let addrs: Result<Vec<SocketAddr>, Box<dyn std::error::Error + Send + Sync>> =
120-
tokio::net::lookup_host(format!("{}:0", host))
121-
.await
122-
.map(|iter| iter.collect())
137+
lookup
138+
.map(|iter| {
139+
// Sort IPv4 before IPv6 so hyper connects without waiting
140+
// for an IPv6 timeout when IPv6 is unreachable. This matches
141+
// what reqwest's default resolver does on most platforms.
142+
let all: Vec<SocketAddr> = iter.collect();
143+
let mut v4: Vec<SocketAddr> = all.iter().filter(|a| a.is_ipv4()).cloned().collect();
144+
let v6: Vec<SocketAddr> = all.iter().filter(|a| a.is_ipv6()).cloned().collect();
145+
v4.extend(v6);
146+
v4
147+
})
123148
.map_err(|e| Box::new(e) as Box<dyn std::error::Error + Send + Sync>);
124149

125150
if let Ok(mut phases) = handle.lock() {

0 commit comments

Comments
 (0)