gavindiaz/sol-trade-sdk
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Improve SDK and SWQOS logging: alignment, errors, duration format

Browse Source 
- Rename wait_transaction_confirmed to wait_tx_confirmed (params, lib, docs, examples)
- SDK timing: use [SDK][provider] style with fixed-width labels; add newline before block
- Move print_sdk_timing_block to common::sdk_log; unify SWQOS_LABEL_WIDTH
- SWQOS submitted/failed: aligned [Provider] labels via log_swqos_submitted/submission_failed
- Extract short error message from JSON (message/data) or quoted string; prefix with 'error: '
- Format elapsed as 'X.XXXX ms' or 'X.XXXX µs' (4 decimals, space before unit); use comma before error
- Add SwqosType::as_str() for zero-allocation log labels; only parse JSON when input starts with '{'

Made-with: Cursor
This commit is contained in:
Wood
2026-03-17 13:11:33 +08:00
parent 7d2ecd57e9
commit 624b1843a2
21 changed files with 387 additions and 169 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/trading/core/executor.rs
+60 -69
View File
@@ -118,32 +118,45 @@ impl TradeExecutor for GenericTradeExecutor {
if crate::common::sdk_log::sdk_log_enabled() {
let dir = if is_buy { "Buy" } else { "Sell" };
println!();
if let (Some(start_us), Some(end_us)) = (timing_start_us, build_end_us) {
println!(
" [SDK] {} build_instructions: {:.4} ms",
" [SDK][{:width$}] {} build_instructions: {:.4} ms",
"-",
dir,
(end_us - start_us) as f64 / 1000.0
(end_us - start_us) as f64 / 1000.0,
width = crate::common::sdk_log::SWQOS_LABEL_WIDTH
);
}
if let (Some(start_us), Some(end_us)) = (timing_start_us, before_submit_us) {
println!(
" [SDK] {} before_submit: {:.4} ms",
" [SDK][{:width$}] {} before_submit: {:.4} ms",
"-",
dir,
(end_us - start_us) as f64 / 1000.0
(end_us - start_us) as f64 / 1000.0,
width = crate::common::sdk_log::SWQOS_LABEL_WIDTH
);
}
println!(
" [SDK] {} simulate (dry-run): {:.4} ms",
" [SDK][{:width$}] {} simulate (dry-run): {:.4} ms",
"-",
dir,
send_elapsed.as_secs_f64() * 1000.0
send_elapsed.as_secs_f64() * 1000.0,
width = crate::common::sdk_log::SWQOS_LABEL_WIDTH
);
println!(
" [SDK][{:width$}] {} total: {:.4} ms",
"-",
dir,
total_elapsed.as_secs_f64() * 1000.0,
width = crate::common::sdk_log::SWQOS_LABEL_WIDTH
);
println!(" [SDK] {} total: {:.4} ms", dir, total_elapsed.as_secs_f64() * 1000.0);
}
return result;
}
let need_confirm = params.wait_transaction_confirmed;
let need_confirm = params.wait_tx_confirmed;
let sender_config = params.sender_concurrency_config();
let result = execute_parallel(
params.swqos_clients.as_slice(),
@@ -185,32 +198,14 @@ impl TradeExecutor for GenericTradeExecutor {
let confirm_done_us = log_enabled.then(crate::common::clock::now_micros);
if log_enabled {
let dir = if is_buy { "Buy" } else { "Sell" };
if let Some(start_us) = timing_start_us {
if let Some(end_us) = build_end_us {
println!(
" [SDK] {} build_instructions: {:.4} ms",
dir,
(end_us - start_us) as f64 / 1000.0
);
}
if let Some(end_us) = before_submit_us {
println!(
" [SDK] {} before_submit: {:.4} ms",
dir,
(end_us - start_us) as f64 / 1000.0
);
}
if let Some(confirm_us) = confirm_done_us {
let total_ms = (confirm_us - start_us) as f64 / 1000.0;
for (swqos_type, submit_done_us) in submit_timings_ref {
let submit_ms =
(*submit_done_us - start_us).max(0) as f64 / 1000.0;
let confirmed_ms =
(confirm_us - *submit_done_us).max(0) as f64 / 1000.0;
println!(" [SDK] {} {:?} submit: {:.4} ms, confirmed: {:.4} ms, total: {:.4} ms", dir, swqos_type, submit_ms, confirmed_ms, total_ms);
}
}
}
crate::common::sdk_log::print_sdk_timing_block(
dir,
timing_start_us,
build_end_us,
before_submit_us,
submit_timings_ref,
confirm_done_us,
);
}
match poll_res {
Ok(_) => (true, signatures, None),
@@ -222,31 +217,17 @@ impl TradeExecutor for GenericTradeExecutor {
};
Ok(confirm_result)
} else {
// Not waiting for confirmation: confirmed is not measured (-); total is per-channel submit time only.
if log_enabled {
let dir = if is_buy { "Buy" } else { "Sell" };
if let Some(start_us) = timing_start_us {
if let Some(end_us) = build_end_us {
println!(
" [SDK] {} build_instructions: {:.4} ms",
dir,
(end_us - start_us) as f64 / 1000.0
);
}
if let Some(end_us) = before_submit_us {
println!(
" [SDK] {} before_submit: {:.4} ms",
dir,
(end_us - start_us) as f64 / 1000.0
);
}
for (swqos_type, submit_done_us) in submit_timings_ref {
let submit_ms = (*submit_done_us - start_us).max(0) as f64 / 1000.0;
println!(
" [SDK] {} {:?} submit: {:.4} ms, confirmed: -, total: {:.4} ms",
dir, swqos_type, submit_ms, submit_ms
);
}
}
crate::common::sdk_log::print_sdk_timing_block(
dir,
timing_start_us,
build_end_us,
before_submit_us,
submit_timings_ref,
None,
);
}
Ok((ok, signatures, err))
};
@@ -377,37 +358,47 @@ mod tests {
let dir = "Buy";
let build_ms = 12.34;
let before_submit_ms = 15.67;
let w = 12usize; // same as crate::common::sdk_log::SWQOS_LABEL_WIDTH
println!("\n--- 1. 构建指令耗时 / 提交前耗时（各打印一次，统一 ms，保留 4 位小数）---\n");
println!(" [SDK] {} build_instructions: {:.4} ms", dir, build_ms);
println!(" [SDK] {} before_submit: {:.4} ms", dir, before_submit_ms);
println!(" [SDK][{:width$}] {} build_instructions: {:.4} ms", "-", dir, build_ms, width = w);
println!(" [SDK][{:width$}] {} before_submit: {:.4} ms", "-", dir, before_submit_ms, width = w);
println!("\n--- 2. 每个 SWQOS 独立耗时：submit=起点→该通道返回, confirmed=该通道提交→链上确认, total=起点→链上确认 ---\n");
println!("\n--- 2. 每个 SWQOS 独立耗时：submit_done=起点→该通道提交完成, confirmed=该通道提交→链上确认, total=起点→链上确认 ---\n");
for (swqos_type, submit_ms, confirmed_ms, total_ms) in [
(SwqosType::Jito, 45.12, 83.38, 128.50),
(SwqosType::Helius, 52.30, 76.20, 128.50),
(SwqosType::ZeroSlot, 48.90, 79.60, 128.50),
] {
println!(
" [SDK] {} {:?} submit: {:.4} ms, confirmed: {:.4} ms, total: {:.4} ms",
dir, swqos_type, submit_ms, confirmed_ms, total_ms
" [SDK][{:width$}] {} submit_done: {:.4} ms, confirmed: {:.4} ms, total: {:.4} ms",
swqos_type.as_str(),
dir,
submit_ms,
confirmed_ms,
total_ms,
width = w
);
}
println!("\n--- 3. 不等待链上确认时：每行 total = 该通道 submit 耗时（独立）---\n");
println!("\n--- 3. 不等待链上确认时：每行 total = 该通道 submit_done（提交完成总耗时）---\n");
for (swqos_type, submit_ms, total_ms) in
[(SwqosType::Jito, 44.20, 44.20), (SwqosType::Helius, 51.80, 51.80)]
{
println!(
" [SDK] {} {:?} submit: {:.4} ms, confirmed: -, total: {:.4} ms",
dir, swqos_type, submit_ms, total_ms
" [SDK][{:width$}] {} submit_done: {:.4} ms, confirmed: -, total: {:.4} ms",
swqos_type.as_str(),
dir,
submit_ms,
total_ms,
width = w
);
}
println!("\n--- 4. Simulate 模式（build/before_submit 仍从 grpc_recv_us 起算）---\n");
println!(" [SDK] {} build_instructions: {:.4} ms", dir, build_ms);
println!(" [SDK] {} before_submit: {:.4} ms", dir, before_submit_ms);
println!(" [SDK] {} simulate (dry-run): {:.4} ms", dir, 8.50);
println!(" [SDK] {} total: {:.4} ms", dir, 36.51);
println!(" [SDK][{:width$}] {} build_instructions: {:.4} ms", "-", dir, build_ms, width = w);
println!(" [SDK][{:width$}] {} before_submit: {:.4} ms", "-", dir, before_submit_ms, width = w);
println!(" [SDK][{:width$}] {} simulate (dry-run): {:.4} ms", "-", dir, 8.50, width = w);
println!(" [SDK][{:width$}] {} total: {:.4} ms", "-", dir, 36.51, width = w);
println!();
}
}