@tduncan / Nvidia-Optimization-Stack-VLLM / commits / 8688a06d67

[Rust][Benchmark] Use `tracing` for logs (#48937)

Signed-off-by: Bugen Zhao <i@bugenzhao.com>

Bugen Zhao committed Jul 21, 2026 at 13:18 UTC 8688a06d676bda6e9e3ec3a87233dce91c40bb4f
24 files changed +498 -249
rust/Cargo.lock
+3
@@ -5498,10 +5498,13 @@ dependencies = [
5498 "serde",
5499 "serde_json",
5500 "thiserror 2.0.18",
5501 + "thiserror-ext",
5502 "tiktoken-rs 0.9.1",
5503 "tokenizers",
5504 "tokio",
5505 "tokio-stream",
5506 + "tracing",
5507 + "tracing-subscriber",
5508 "url",
5509 "uuid",
5510 ]
rust/src/bench/Cargo.toml
+3
@@ -26,10 +26,13 @@ rustc-hash.workspace = true
26 serde = { workspace = true, features = ["rc"] }
27 serde_json = { workspace = true, features = ["raw_value"] }
28 thiserror.workspace = true
29 +thiserror-ext.workspace = true
30 tiktoken-rs.workspace = true
31 tokenizers.workspace = true
32 tokio.workspace = true
33 tokio-stream.workspace = true
34 +tracing.workspace = true
35 +tracing-subscriber.workspace = true
36 url.workspace = true
37 uuid.workspace = true
38
rust/src/bench/src/backends/pooling.rs
+8 -7
@@ -158,9 +158,10 @@ impl PoolingBackend {
158 // (mirrors Python async_request_vllm_rerank).
159 if let Some(ref list) = input.prompt_list {
160 if list.len() < 2 {
161 - eprintln!(
162 - "WARNING: vllm-rerank request has no documents \
163 - (prompt_list needs [query, doc, ...])"
161 + tracing::warn!(
162 + backend = "vllm-rerank",
163 + inputs = list.len(),
164 + "rerank request has no documents"
165 );
166 }
167 let query = list.first().map(|s| s.as_ref()).unwrap_or("");
@@ -175,10 +176,10 @@ impl PoolingBackend {
176 // Legacy path: text prompt as query, documents via --extra-body.
177 let query = input.prompt.as_ref();
178 if query.is_empty() && input.prompt_token_ids.is_some() {
178 - eprintln!(
179 - "WARNING: vllm-rerank received empty query (random dataset uses \
180 - token IDs only). Use --dataset-name random-rerank for meaningful \
181 - rerank benchmarks."
179 + tracing::warn!(
180 + backend = "vllm-rerank",
181 + dataset = "random",
182 + "rerank request has an empty query; use the random-rerank dataset"
183 );
184 }
185 serde_json::json!({
rust/src/bench/src/benchmark.rs
+107 -80
@@ -6,6 +6,7 @@ use std::sync::Arc;
6 use std::time::Instant;
7
8 use indicatif::{ProgressBar, ProgressStyle};
9 +use thiserror_ext::AsReport as _;
10 use tokio::sync::Semaphore;
11
12 use crate::backends::{RequestFuncInput, RequestFuncOutput, get_backend};
@@ -72,12 +73,12 @@ pub fn pre_resolve_dns(
73 v4.extend(v6);
74 if !v4.is_empty() {
75 let ips: Vec<_> = v4.iter().map(|a| a.ip()).collect();
75 - println!("Pre-resolved {host} -> {ips:?}");
76 + tracing::info!(host, addresses = ?ips, "pre-resolved benchmark endpoint DNS");
77 builder = builder.resolve_to_addrs(host, &v4);
78 }
79 }
80 Err(e) => {
80 - eprintln!("Warning: DNS pre-resolution for '{host}' failed: {e}");
81 + tracing::warn!(host, error = %e.as_report(), "failed to pre-resolve benchmark endpoint DNS");
82 }
83 }
84
@@ -346,10 +347,14 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
347 let (model_id, model_name) = if let Some(ref m) = config.model {
348 (m.clone(), config.model_name.clone())
349 } else {
349 - println!("Model not specified, fetching first model from server...");
350 + tracing::info!(base_url = %config.base_url, "fetching first model from server");
351 let (name, id) =
352 get_first_model_from_server(&config.base_url, &client, &config.extra_headers).await?;
352 - println!("First model name: {name}, first model id: {id}");
353 + tracing::info!(
354 + model_name = name,
355 + model_id = id,
356 + "selected first model from server"
357 + );
358 (id, Some(name))
359 };
360
@@ -358,10 +363,9 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
363 None
364 } else {
365 let tid = config.tokenizer_id.as_deref().unwrap_or(&model_id);
361 - println!("Loading tokenizer: {tid}");
366 + tracing::info!(tokenizer = tid, "loading tokenizer");
367 let server_info = Some((config.base_url.as_str(), model_id.as_str()));
368 let t = crate::tokenizer::load_tokenizer(tid, config.trust_remote_code, server_info)?;
364 - println!("Tokenizer loaded successfully.");
369 Some(t)
370 };
371 let has_tokenizer = tokenizer.is_some();
@@ -421,7 +425,12 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
425 config.num_prompts, config.random_batch_size, config.is_reranker,
426 ),
427 };
424 - println!("Generating {dataset_label}...");
428 + tracing::info!(
429 + dataset = ?config.dataset_name,
430 + prompts = config.num_prompts,
431 + description = %dataset_label,
432 + "generating benchmark dataset"
433 + );
434 let gen_start = Instant::now();
435
436 let mut input_requests = match config.dataset_name {
@@ -608,18 +617,19 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
617 };
618
619 let gen_elapsed = gen_start.elapsed();
611 - println!(
612 - "Generated {} prompts in {:.2}s",
613 - input_requests.len(),
614 - gen_elapsed.as_secs_f64()
620 + tracing::info!(
621 + prompts = input_requests.len(),
622 + elapsed_seconds = gen_elapsed.as_secs_f64(),
623 + "generated benchmark dataset"
624 );
625
626 let filtered_count =
627 filter_requests_by_max_model_len(&mut input_requests, config.max_model_len);
628 if filtered_count > 0 {
620 - println!(
621 - "Filtered {filtered_count} prompt(s) above --max-model-len {}.",
622 - config.max_model_len.unwrap()
629 + tracing::info!(
630 + filtered_prompts = filtered_count,
631 + max_model_len = config.max_model_len.unwrap(),
632 + "filtered prompts above maximum model length"
633 );
634 }
635 if input_requests.is_empty() {
@@ -670,7 +680,7 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
680
681 // Ready check
682 if config.ready_check_timeout_sec > 0 {
673 - println!("Starting initial single prompt test run...");
683 + tracing::info!("starting initial single-prompt test run");
684 let test_output = wait_for_endpoint(
685 config.backend,
686 &client,
@@ -685,7 +695,7 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
695 test_output.error
696 )));
697 }
688 - println!("Initial test run completed.");
698 + tracing::info!("initial single-prompt test run completed");
699 }
700
701 // Verify and fix prompt token lengths against the server's /tokenize endpoint.
@@ -703,12 +713,15 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
713 DatasetName::Random | DatasetName::PrefixRepetition
714 );
715 if verifiable_dataset && has_token_ids && !config.backend.is_pooling() {
706 - println!("Using prompt_token_ids, skipping server-side tokenizer verification.");
716 + tracing::info!(
717 + reason = "prompt_token_ids",
718 + "skipping server tokenizer verification"
719 + );
720 }
721 if verifiable_dataset && !has_token_ids && !config.backend.is_pooling() {
722 let cache_key = tokenizer_verify_cache_key(&config.base_url, &model_id);
723 if is_tokenizer_verified(&cache_key) {
711 - println!("Tokenizer verified in previous run (cached), skipping verification.");
724 + tracing::info!(reason = "cached", "skipping server tokenizer verification");
725 } else {
726 let num_special =
727 tokenizer.as_ref().map(|t| t.num_special_tokens_to_add()).unwrap_or(0);
@@ -723,14 +736,17 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
736 .await?
737 {
738 SampleVerifyOutcome::Passed => {
726 - println!("Sample verification passed, skipping full verification.");
739 + tracing::info!("tokenizer sample verification passed");
740 mark_tokenizer_verified(&cache_key);
741 }
742 SampleVerifyOutcome::Skipped(reason) => {
730 - println!("Server /tokenize unavailable ({reason}), skipping verification.");
743 + tracing::warn!(
744 + reason = %reason,
745 + "server tokenizer unavailable; skipping prompt verification"
746 + );
747 }
748 SampleVerifyOutcome::Mismatch => {
733 - println!("Sample verification found mismatch, running full verify+fix...");
749 + tracing::warn!("tokenizer sample mismatch; verifying and fixing all prompts");
750 match verify_and_fix_prompt_lengths(
751 &client,
752 &config.base_url,
@@ -742,16 +758,16 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
758 .await
759 {
760 Ok(()) => {
745 - println!(
746 - "All {} prompts verified: exact token length match.",
747 - input_requests.len()
761 + tracing::info!(
762 + prompts = input_requests.len(),
763 + "verified exact prompt token lengths"
764 );
765 mark_tokenizer_verified(&cache_key);
766 }
767 Err(BenchError::TokenizeUnavailable(reason)) => {
752 - println!(
753 - "Server /tokenize became unavailable during verification \
754 - ({reason}); proceeding with client-side token counts."
768 + tracing::warn!(
769 + reason = %reason,
770 + "server tokenizer became unavailable; using client token counts"
771 );
772 }
773 Err(e) => return Err(e),
@@ -763,7 +779,7 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
779
780 // Warmup
781 if config.num_warmups > 0 {
766 - println!("Warming up with {} requests...", config.num_warmups);
782 + tracing::info!(requests = config.num_warmups, "starting benchmark warmup");
783 run_warmup(
784 config.backend,
785 &client,
@@ -776,7 +792,7 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
792 config.disable_tqdm,
793 )
794 .await;
779 - println!("Warmup run completed.");
795 + tracing::info!(requests = config.num_warmups, "benchmark warmup completed");
796 }
797
798 // Start profiler if requested (immediate mode — no batch threshold)
@@ -814,28 +830,22 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
830 let spec_decode_before =
831 fetch_spec_decode_metrics(&config.base_url, &client, &config.extra_headers).await;
832 if spec_decode_before.is_some() {
817 - println!("Speculative decoding detected, will collect metrics.");
833 + tracing::info!("detected speculative decoding; collecting metrics");
834 }
835
836 // Main benchmark
821 - println!("Starting main benchmark run...");
837 let distribution = if config.burstiness == 1.0 {
838 "Poisson process"
839 } else {
840 "Gamma distribution"
841 };
827 - println!(
828 - "Traffic request rate: {}",
829 - if config.request_rate.is_infinite() {
830 - "inf".to_string()
831 - } else {
832 - format!("{}", config.request_rate)
833 - }
834 - );
835 - println!("Burstiness factor: {} ({distribution})", config.burstiness);
836 - println!(
837 - "Maximum request concurrency: {}",
838 - config.max_concurrency.unwrap_or(config.num_prompts)
842 + tracing::info!(
843 + request_rate = config.request_rate,
844 + burstiness = config.burstiness,
845 + distribution,
846 + max_concurrency = config.max_concurrency.unwrap_or(config.num_prompts),
847 + prompts = config.num_prompts,
848 + "starting main benchmark run"
849 );
850
851 // Pre-assign LoRA adapters to each request (None when --lora-modules not set).
@@ -847,11 +857,11 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
857 );
858 if let (Some(modules), Some(_)) = (config.lora_modules.as_ref(), lora_assignments.as_ref()) {
859 let names: Vec<&str> = modules.iter().map(|s| s.as_ref()).collect();
850 - println!(
851 - "LoRA adapters ({}): {:?} [assignment={:?}]",
852 - modules.len(),
853 - names,
854 - config.lora_assignment
860 + tracing::info!(
861 + adapters = modules.len(),
862 + names = ?names,
863 + assignment = ?config.lora_assignment,
864 + "assigned LoRA adapters"
865 );
866 }
867
@@ -1125,7 +1135,7 @@ pub async fn run_benchmark(config: &BenchConfig) -> Result<serde_json::Value> {
1135 if let Some((cancel_tx, task)) = profile_task {
1136 let _ = cancel_tx.send(());
1137 if let Err(e) = task.await {
1128 - eprintln!("WARNING: Profile background task failed: {e}");
1138 + tracing::error!(error = %e.as_report(), "profiler background task failed");
1139 }
1140 }
1141
@@ -1289,12 +1299,14 @@ pub(crate) async fn start_profiler_immediate(
1299 base_url: &str,
1300 extra_headers: &Option<std::collections::HashMap<String, String>>,
1301 ) {
1292 - println!("Starting profiler...");
1302 let profile_url = format!("{base_url}/start_profile");
1303 + tracing::info!(url = %profile_url, "starting profiler");
1304 match send_profile_request(client, &profile_url, extra_headers).await {
1295 - Ok(true) => println!("Profiler started"),
1296 - Ok(false) => eprintln!("WARNING: Profiler start request returned non-success"),
1297 - Err(e) => eprintln!("WARNING: Failed to start profiler: {e}"),
1305 + Ok(true) => tracing::info!(url = %profile_url, "profiler started"),
1306 + Ok(false) => tracing::warn!(url = %profile_url, "profiler start request was unsuccessful"),
1307 + Err(e) => {
1308 + tracing::warn!(url = %profile_url, error = %e.as_report(), "failed to start profiler")
1309 + }
1310 }
1311 }
1312
@@ -1304,12 +1316,14 @@ pub(crate) async fn stop_profiler_immediate(
1316 base_url: &str,
1317 extra_headers: &Option<std::collections::HashMap<String, String>>,
1318 ) {
1307 - println!("Stopping profiler...");
1319 let profile_url = format!("{base_url}/stop_profile");
1320 + tracing::info!(url = %profile_url, "stopping profiler");
1321 match send_profile_request(client, &profile_url, extra_headers).await {
1310 - Ok(true) => println!("Profiler stopped"),
1311 - Ok(false) => eprintln!("WARNING: Profiler stop request returned non-success"),
1312 - Err(e) => eprintln!("WARNING: Failed to stop profiler: {e}"),
1322 + Ok(true) => tracing::info!(url = %profile_url, "profiler stopped"),
1323 + Ok(false) => tracing::warn!(url = %profile_url, "profiler stop request was unsuccessful"),
1324 + Err(e) => {
1325 + tracing::warn!(url = %profile_url, error = %e.as_report(), "failed to stop profiler")
1326 + }
1327 }
1328 }
1329
@@ -1371,25 +1385,30 @@ pub(crate) async fn profile_on_batch_threshold(
1385 duration_secs: f64,
1386 mut cancel_rx: tokio::sync::oneshot::Receiver<()>,
1387 ) {
1374 - println!(
1375 - "Waiting for batch size >= {threshold} before starting profiler \
1376 - (will capture {duration_secs}s)..."
1388 + tracing::info!(
1389 + threshold,
1390 + duration_seconds = duration_secs,
1391 + "waiting for profiler batch threshold"
1392 );
1393
1394 loop {
1395 if let Some(running) = fetch_num_requests_running(client, base_url).await
1396 && running >= threshold
1397 {
1383 - println!("Batch size {running} >= {threshold}, starting profiler...");
1398 + tracing::info!(
1399 + running_requests = running,
1400 + threshold,
1401 + "profiler batch threshold reached"
1402 + );
1403 break;
1404 }
1405 // Wait 500ms or until the benchmark signals cancellation
1406 tokio::select! {
1407 _ = tokio::time::sleep(std::time::Duration::from_millis(500)) => {}
1408 _ = &mut cancel_rx => {
1390 - eprintln!(
1391 - "NOTE: Benchmark finished before batch threshold {threshold} was reached; \
1392 - profiling skipped."
1409 + tracing::warn!(
1410 + threshold,
1411 + "benchmark finished before profiler batch threshold; skipping profiling"
1412 );
1413 return;
1414 }
@@ -1398,13 +1417,13 @@ pub(crate) async fn profile_on_batch_threshold(
1417
1418 let start_url = format!("{base_url}/start_profile");
1419 match send_profile_request(client, &start_url, extra_headers).await {
1401 - Ok(true) => println!("Profiler started"),
1420 + Ok(true) => tracing::info!(url = %start_url, "profiler started"),
1421 Ok(false) => {
1403 - eprintln!("WARNING: Profiler start request returned non-success");
1422 + tracing::warn!(url = %start_url, "profiler start request was unsuccessful");
1423 return;
1424 }
1425 Err(e) => {
1407 - eprintln!("WARNING: Failed to start profiler: {e}");
1426 + tracing::warn!(url = %start_url, error = %e.as_report(), "failed to start profiler");
1427 return;
1428 }
1429 }
@@ -1413,15 +1432,17 @@ pub(crate) async fn profile_on_batch_threshold(
1432 tokio::select! {
1433 _ = tokio::time::sleep(std::time::Duration::from_secs_f64(duration_secs)) => {}
1434 _ = &mut cancel_rx => {
1416 - println!("Benchmark finished, stopping profiler early...");
1435 + tracing::info!("benchmark finished; stopping profiler early");
1436 }
1437 }
1438
1439 let stop_url = format!("{base_url}/stop_profile");
1440 match send_profile_request(client, &stop_url, extra_headers).await {
1422 - Ok(true) => println!("Profiler stopped after capturing"),
1423 - Ok(false) => eprintln!("WARNING: Profiler stop request returned non-success"),
1424 - Err(e) => eprintln!("WARNING: Failed to stop profiler: {e}"),
1441 + Ok(true) => tracing::info!(url = %stop_url, "profiler stopped after capture"),
1442 + Ok(false) => tracing::warn!(url = %stop_url, "profiler stop request was unsuccessful"),
1443 + Err(e) => {
1444 + tracing::warn!(url = %stop_url, error = %e.as_report(), "failed to stop profiler")
1445 + }
1446 }
1447 }
1448
@@ -1502,10 +1523,11 @@ async fn verify_and_fix_prompt_lengths(
1523 let excess = tokens.len().saturating_sub(expected_input_len);
1524 let compensate = if excess > 0 && last_excess == Some(excess) {
1525 if _iter == 1 {
1505 - eprintln!(
1506 - "Prompt {i}: server consistently adds {excess} extra token(s) \
1507 - (likely BOS), compensating target to {}.",
1508 - expected_input_len.saturating_sub(excess),
1526 + tracing::warn!(
1527 + prompt_index = i,
1528 + extra_tokens = excess,
1529 + adjusted_target = expected_input_len.saturating_sub(excess),
1530 + "server consistently adds prompt tokens; compensating verification target"
1531 );
1532 }
1533 excess
@@ -1563,7 +1585,10 @@ async fn verify_and_fix_prompt_lengths(
1585
1586 let fc = fixed_count.load(std::sync::atomic::Ordering::Relaxed);
1587 if fc > 0 {
1566 - println!("Fixed {fc} prompt(s) via server tokenize/detokenize convergence.");
1588 + tracing::info!(
1589 + fixed_prompts = fc,
1590 + "fixed prompt lengths using server tokenizer"
1591 + );
1592 }
1593
1594 Ok(())
@@ -1818,7 +1843,7 @@ async fn sample_verify_prompts(
1843 let tokenize_url = format!("{base_url}/tokenize");
1844 let api_key = std::env::var("OPENAI_API_KEY").ok();
1845
1821 - println!("Sampling {sample_size} prompts for verification...");
1846 + tracing::info!(sample_size, "sampling prompts for tokenizer verification");
1847
1848 for (i, request) in requests.iter().enumerate().take(sample_size) {
1849 let tokens = match server_tokenize(
@@ -1841,9 +1866,11 @@ async fn sample_verify_prompts(
1866
1867 let expected = request.prompt_len + num_special;
1868 if tokens.len() != expected {
1844 - println!(
1845 - "Prompt {i}: expected {expected} tokens, server returned {}",
1846 - tokens.len()
1869 + tracing::warn!(
1870 + prompt_index = i,
1871 + expected_tokens = expected,
1872 + actual_tokens = tokens.len(),
1873 + "tokenizer verification sample mismatch"
1874 );
1875 return Ok(SampleVerifyOutcome::Mismatch);
1876 }
rust/src/bench/src/config.rs
+18 -9
@@ -288,10 +288,18 @@ impl BenchConfig {
288 }
289 Some(other) => {
290 // extra_body was not an object — just use sampling params
291 - eprintln!(
292 - "Warning: --extra-body is not a JSON object, sampling params may be lost"
291 + let value_type = match &other {
292 + serde_json::Value::Null => "null",
293 + serde_json::Value::Bool(_) => "boolean",
294 + serde_json::Value::Number(_) => "number",
295 + serde_json::Value::String(_) => "string",
296 + serde_json::Value::Array(_) => "array",
297 + serde_json::Value::Object(_) => unreachable!(),
298 + };
299 + tracing::warn!(
300 + value_type,
301 + "sampling parameters may be lost because --extra-body is not a JSON object"
302 );
294 - let _ = other;
303 sampling_params
304 }
305 None => sampling_params,
@@ -489,9 +497,9 @@ impl BenchConfig {
497 _ => {}
498 }
499 if !args.skip_chat_template {
492 - eprintln!(
493 - "NOTE: client-side chat template rendering is not supported; custom \
494 - dataset prompts are sent raw (equivalent to --skip-chat-template)."
500 + tracing::warn!(
501 + dataset = "custom",
502 + "client-side chat template rendering is unsupported; sending prompts raw"
503 );
504 }
505 }
@@ -570,9 +578,10 @@ impl BenchConfig {
578 }
579
580 if ignore_eos {
573 - eprintln!(
574 - "WARNING: --ignore-eos is set with --multi-turn. The server may not \
575 - respect output length limits, causing unbounded context growth."
581 + tracing::warn!(
582 + ignore_eos,
583 + multi_turn = true,
584 + "output length limits may be ignored, causing unbounded context growth"
585 );
586 }
587
rust/src/bench/src/datasets/hf_dataset.rs
+59 -26
@@ -8,6 +8,7 @@ use rand::seq::SliceRandom;
8 use rand::{Rng, SeedableRng};
9
10 use super::SampleRequest;
11 +use super::progress::RowDownloadReporter;
12 use crate::error::{BenchError, Result};
13 use crate::tokenizer::TokenizerKind;
14
@@ -201,7 +202,12 @@ pub fn download_hf_dataset(
202 (resolved_config, resolved_split)
203 };
204
204 - println!("HF dataset: {dataset} (config={resolved_config}, split={resolved_split})");
205 + tracing::info!(
206 + dataset,
207 + config = resolved_config,
208 + split = resolved_split,
209 + "resolved Hugging Face dataset"
210 + );
211
212 // Check cache
213 let dir = cache_dir();
@@ -215,11 +221,16 @@ pub fn download_hf_dataset(
221
222 if cache_path.exists() {
223 let path_str = cache_path.to_string_lossy().to_string();
218 - println!("HF dataset cached: {path_str}");
224 + tracing::info!(dataset, path = %path_str, "using cached Hugging Face dataset");
225 return Ok((path_str, resolved_config, resolved_split));
226 }
227
222 - println!("Downloading HF dataset '{dataset}' from datasets-server...");
228 + tracing::info!(
229 + dataset,
230 + config = resolved_config,
231 + split = resolved_split,
232 + "downloading Hugging Face dataset"
233 + );
234
235 let encoded_config: String =
236 url::form_urlencoded::byte_serialize(resolved_config.as_bytes()).collect();
@@ -229,6 +240,7 @@ pub fn download_hf_dataset(
240 let mut all_rows: Vec<serde_json::Value> = Vec::new();
241 let mut offset = 0usize;
242 let page_size = 100usize;
243 + let mut progress = RowDownloadReporter::new();
244
245 loop {
246 let url = format!(
@@ -260,14 +272,14 @@ pub fn download_hf_dataset(
272 offset += fetched;
273
274 let total = data["num_rows_total"].as_u64().unwrap_or(0);
263 - eprint!("\r Fetched {offset}/{total} rows...");
275 + progress.update(offset, total);
276
277 // Stop if we have enough rows or reached end of dataset
278 if all_rows.len() >= num_rows_needed || fetched < page_size {
279 break;
280 }
281 }
270 - eprintln!(); // newline after progress
282 + progress.finish();
283
284 if all_rows.is_empty() {
285 return Err(BenchError::Config(format!(
@@ -280,7 +292,12 @@ pub fn download_hf_dataset(
292 std::fs::write(&cache_path, &json_str)?;
293
294 let path_str = cache_path.to_string_lossy().to_string();
283 - println!("HF dataset: {} rows saved to {path_str}", all_rows.len());
295 + tracing::info!(
296 + dataset,
297 + rows = all_rows.len(),
298 + path = %path_str,
299 + "saved Hugging Face dataset"
300 + );
301 Ok((path_str, resolved_config, resolved_split))
302 }
303
@@ -483,21 +500,31 @@ pub fn load_hf_dataset(
500 // Detect column format from first row
501 let format = detect_column_format(&entries[0], text_column_override)?;
502
486 - // Print detected format
503 match &format {
488 - ColumnFormat::Chat(col) => println!("HF dataset: detected chat column '{col}'"),
504 + ColumnFormat::Chat(col) => {
505 + tracing::info!(
506 + format = "chat",
507 + column = col,
508 + "detected Hugging Face dataset format"
509 + );
510 + }
511 ColumnFormat::Text {
512 prompt_col,
513 output_col,
514 } => {
493 - let out_msg = output_col.as_deref().unwrap_or("none");
494 - println!("HF dataset: detected text column '{prompt_col}', output column: {out_msg}");
515 + tracing::info!(
516 + format = "text",
517 + prompt_column = prompt_col,
518 + output_column = output_col.as_deref().unwrap_or("none"),
519 + "detected Hugging Face dataset format"
520 + );
521 }
522 ColumnFormat::Combined { cols, output_col } => {
497 - let out_msg = output_col.as_deref().unwrap_or("none");
498 - println!(
499 - "HF dataset: detected combined columns {:?}, output column: {out_msg}",
500 - cols
523 + tracing::info!(
524 + format = "combined",
525 + prompt_columns = ?cols,
526 + output_column = output_col.as_deref().unwrap_or("none"),
527 + "detected Hugging Face dataset format"
528 );
529 }
530 }
@@ -608,9 +635,10 @@ pub fn load_hf_dataset(
635 if len == 0 { 128 } else { len }
636 } else {
637 if !warned_no_output {
611 - eprintln!(
612 - "WARNING: No output column detected and --hf-output-len not set. \
613 - Using default output length of 128 tokens."
638 + tracing::warn!(
639 + path = dataset_path,
640 + default_output_tokens = 128,
641 + "no dataset output column or --hf-output-len; using default output length"
642 );
643 warned_no_output = true;
644 }
@@ -618,9 +646,10 @@ pub fn load_hf_dataset(
646 }
647 } else {
648 if !warned_no_output {
621 - eprintln!(
622 - "WARNING: No output column detected and --hf-output-len not set. \
623 - Using default output length of 128 tokens."
649 + tracing::warn!(
650 + path = dataset_path,
651 + default_output_tokens = 128,
652 + "no dataset output column or --hf-output-len; using default output length"
653 );
654 warned_no_output = true;
655 }
@@ -640,9 +669,11 @@ pub fn load_hf_dataset(
669 // Oversample if needed
670 if samples.len() < num_requests {
671 if no_oversample {
643 - println!(
644 - "Skipping oversampling. Total samples: {} (requested: {num_requests})",
645 - samples.len()
672 + tracing::info!(
673 + dataset = "hf",
674 + samples = samples.len(),
675 + requested = num_requests,
676 + "skipping dataset oversampling"
677 );
678 } else if !samples.is_empty() {
679 let original_len = samples.len();
@@ -652,9 +683,11 @@ pub fn load_hf_dataset(
683 req.request_id = Some(format!("{request_id_prefix}{}", original_len + i));
684 samples.push(req);
685 }
655 - println!(
656 - "Oversampled HF dataset from {original_len} to {} total samples.",
657 - samples.len()
686 + tracing::info!(
687 + dataset = "hf",
688 + original_samples = original_len,
689 + samples = samples.len(),
690 + "oversampled dataset"
691 );
692 }
693 }
rust/src/bench/src/datasets/mod.rs
+9 -6
@@ -5,6 +5,7 @@ pub mod custom;
5 pub mod hf_dataset;
6 pub mod multi_turn;
7 pub mod prefix_repetition;
8 +mod progress;
9 pub mod random;
10 pub mod random_mm;
11 pub mod random_rerank;
@@ -90,9 +91,10 @@ pub fn oversample_requests(
91 return;
92 }
93 if no_oversample {
93 - println!(
94 - "Skipping oversampling. Total samples: {} (requested: {num_requests})",
95 - requests.len()
94 + tracing::info!(
95 + samples = requests.len(),
96 + requested = num_requests,
97 + "skipping dataset oversampling"
98 );
99 return;
100 }
@@ -103,9 +105,10 @@ pub fn oversample_requests(
105 req.request_id = Some(format!("{request_id_prefix}{}", original_len + i));
106 requests.push(req);
107 }
106 - println!(
107 - "Oversampled requests from {original_len} to {} total samples.",
108 - requests.len()
108 + tracing::info!(
109 + original_samples = original_len,
110 + samples = requests.len(),
111 + "oversampled dataset"
112 );
113 }
114
rust/src/bench/src/datasets/multi_turn.rs
+4 -3
@@ -445,9 +445,10 @@ pub fn load_sharegpt_multi_turn(
445 conv.conversation_id = format!("{request_id_prefix}conv-{}", original_len + i);
446 conversations.push(conv);
447 }
448 - println!(
449 - "Oversampled multi-turn conversations from {original_len} to {} total.",
450 - conversations.len()
448 + tracing::info!(
449 + original_conversations = original_len,
450 + conversations = conversations.len(),
451 + "oversampled multi-turn conversations"
452 );
453 }
454
rust/src/bench/src/datasets/prefix_repetition.rs
+7 -5
@@ -41,11 +41,13 @@ pub fn generate_prefix_repetition_dataset(
41 }
42 let total = prompts_per_prefix * num_prefixes;
43 if total != num_requests {
44 - println!(
45 - "prefix_repetition: generating {total} requests \
46 - ({num_prefixes} prefixes x {prompts_per_prefix} prompts each; \
47 - {} dropped to divide evenly)",
48 - num_requests - total
44 + tracing::info!(
45 + requested = num_requests,
46 + generated = total,
47 + prefixes = num_prefixes,
48 + prompts_per_prefix,
49 + dropped = num_requests - total,
50 + "adjusted prefix-repetition request count"
51 );
52 }
53
rust/src/bench/src/datasets/progress.rs new
+77
@@ -0,0 +1,77 @@
1 +// SPDX-License-Identifier: Apache-2.0
2 +// SPDX-FileCopyrightText: Copyright contributors to the vLLM project
3 +
4 +use std::time::{Duration, Instant};
5 +
6 +use indicatif::{ProgressBar, ProgressStyle};
7 +
8 +const REPORT_INTERVAL: Duration = Duration::from_secs(10);
9 +
10 +/// Reports row download progress to an interactive progress bar, or through
11 +/// periodic tracing events when the progress bar is hidden on a non-TTY.
12 +pub(super) struct RowDownloadReporter {
13 + progress: ProgressBar,
14 + next_report: Instant,
15 +}
16 +
17 +impl RowDownloadReporter {
18 + /// Creates a reporter that emits non-TTY updates every 10 seconds.
19 + pub fn new() -> Self {
20 + let progress = ProgressBar::new(0);
21 + progress.set_style(
22 + ProgressStyle::with_template(
23 + "{spinner:.green} Fetching rows [{bar:30.cyan/blue}] {pos}/{len}",
24 + )
25 + .unwrap()
26 + .progress_chars("#>-"),
27 + );
28 + Self {
29 + progress,
30 + next_report: Instant::now() + REPORT_INTERVAL,
31 + }
32 + }
33 +
34 + /// Updates the current row count and reports progress when due.
35 + pub fn update(&mut self, rows: usize, total: u64) {
36 + let rows = rows as u64;
37 + let total = total.max(rows);
38 + self.progress.set_length(total);
39 + self.progress.set_position(rows);
40 +
41 + if self.should_report(Instant::now()) {
42 + tracing::info!(rows, total, "fetching dataset rows");
43 + }
44 + }
45 +
46 + /// Clears the interactive progress bar after the download completes.
47 + pub fn finish(self) {
48 + self.progress.finish_and_clear();
49 + }
50 +
51 + fn should_report(&mut self, now: Instant) -> bool {
52 + if !self.progress.is_hidden() || now < self.next_report {
53 + return false;
54 + }
55 + self.next_report = now + REPORT_INTERVAL;
56 + true
57 + }
58 +}
59 +
60 +#[cfg(test)]
61 +mod tests {
62 + use super::*;
63 +
64 + #[test]
65 + fn hidden_reporter_uses_ten_second_deadline() {
66 + let start = Instant::now();
67 + let mut reporter = RowDownloadReporter {
68 + progress: ProgressBar::hidden(),
69 + next_report: start + REPORT_INTERVAL,
70 + };
71 +
72 + assert!(!reporter.should_report(start + Duration::from_secs(9)));
73 + assert!(reporter.should_report(start + Duration::from_secs(10)));
74 + assert!(!reporter.should_report(start + Duration::from_secs(19)));
75 + assert!(reporter.should_report(start + Duration::from_secs(20)));
76 + }
77 +}
rust/src/bench/src/datasets/random.rs
+6 -3
@@ -49,9 +49,12 @@ pub fn generate_random_dataset(
49 let (input_low, input_high) = range_ratio.input_bounds(real_input_len);
50 let (output_low, output_high) = range_ratio.output_bounds(output_len);
51 if !range_ratio.is_fixed() {
52 - println!(
53 - "Sampling input_len from [{input_low}, {input_high}] and \
54 - output_len from [{output_low}, {output_high}]"
52 + tracing::info!(
53 + input_low,
54 + input_high,
55 + output_low,
56 + output_high,
57 + "sampling random request lengths"
58 );
59 }
60
rust/src/bench/src/datasets/sharegpt.rs
+15 -9
@@ -23,8 +23,10 @@ const DEFAULT_SHAREGPT_FILE: &str = "ShareGPT_V3_unfiltered_cleaned_split.json";
23 /// Download the default ShareGPT dataset from HuggingFace Hub.
24 /// Uses hf-hub's built-in cache — subsequent calls return the cached path instantly.
25 pub fn download_sharegpt_dataset() -> Result<String> {
26 - println!(
27 - "Downloading ShareGPT dataset from {DEFAULT_SHAREGPT_REPO}/{DEFAULT_SHAREGPT_FILE} ..."
26 + tracing::info!(
27 + repository = DEFAULT_SHAREGPT_REPO,
28 + file = DEFAULT_SHAREGPT_FILE,
29 + "downloading ShareGPT dataset"
30 );
31 let repo = crate::hub::HubRepo::dataset(DEFAULT_SHAREGPT_REPO.to_string());
32 let path = repo.get(DEFAULT_SHAREGPT_FILE).map_err(|e| {
@@ -33,7 +35,7 @@ pub fn download_sharegpt_dataset() -> Result<String> {
35 ))
36 })?;
37 let path_str = path.to_string_lossy().to_string();
36 - println!("ShareGPT dataset ready: {path_str}");
38 + tracing::info!(dataset = "sharegpt", path = %path_str, "dataset is ready");
39 Ok(path_str)
40 }
41
@@ -135,9 +137,11 @@ pub fn load_sharegpt_dataset(
137 // Oversample if dataset is smaller than requested
138 if samples.len() < num_requests {
139 if no_oversample {
138 - println!(
139 - "Skipping oversampling. Total samples: {} (requested: {num_requests})",
140 - samples.len()
140 + tracing::info!(
141 + dataset = "sharegpt",
142 + samples = samples.len(),
143 + requested = num_requests,
144 + "skipping dataset oversampling"
145 );
146 } else if !samples.is_empty() {
147 let needed = num_requests - samples.len();
@@ -147,9 +151,11 @@ pub fn load_sharegpt_dataset(
151 req.request_id = Some(format!("{request_id_prefix}{}", original_len + i));
152 samples.push(req);
153 }
150 - println!(
151 - "Oversampled requests from {original_len} to {} total samples.",
152 - samples.len()
154 + tracing::info!(
155 + dataset = "sharegpt",
156 + original_samples = original_len,
157 + samples = samples.len(),
158 + "oversampled dataset"
159 );
160 }
161 }
rust/src/bench/src/datasets/speed_bench.rs
+22 -16
@@ -8,6 +8,7 @@ use rand::seq::SliceRandom;
8 use rand::{Rng, SeedableRng};
9
10 use super::SampleRequest;
11 +use super::progress::RowDownloadReporter;
12 use crate::cli::SpeedBenchConfig;
13 use crate::error::{BenchError, Result};
14 use crate::tokenizer::TokenizerKind;
@@ -35,11 +36,11 @@ pub fn download_speed_bench(config: SpeedBenchConfig) -> Result<String> {
36 // Return cached file if it exists
37 if cache_path.exists() {
38 let path_str = cache_path.to_string_lossy().to_string();
38 - println!("SPEED-Bench ({config_name}) cached: {path_str}");
39 + tracing::info!(config = config_name, path = %path_str, "using cached SPEED-Bench dataset");
40 return Ok(path_str);
41 }
42
42 - println!("Downloading SPEED-Bench ({config_name}) from HuggingFace datasets-server...");
43 + tracing::info!(config = config_name, "downloading SPEED-Bench dataset");
44
45 let client = reqwest::blocking::Client::builder()
46 .timeout(std::time::Duration::from_secs(120))
@@ -49,6 +50,7 @@ pub fn download_speed_bench(config: SpeedBenchConfig) -> Result<String> {
50 let mut all_rows: Vec<serde_json::Value> = Vec::new();
51 let mut offset = 0usize;
52 let page_size = 100usize;
53 + let mut progress = RowDownloadReporter::new();
54
55 loop {
56 let url = format!(
@@ -116,15 +118,14 @@ pub fn download_speed_bench(config: SpeedBenchConfig) -> Result<String> {
118 let fetched = rows.len();
119 offset += fetched;
120
119 - // Print progress
121 let total = data["num_rows_total"].as_u64().unwrap_or(0);
121 - eprint!("\r Fetched {offset}/{total} rows...");
122 + progress.update(offset, total);
123
124 if fetched < page_size {
125 break;
126 }
127 }
127 - eprintln!(); // newline after progress
128 + progress.finish();
129
130 if all_rows.is_empty() {
131 return Err(BenchError::Config(
@@ -137,9 +138,11 @@ pub fn download_speed_bench(config: SpeedBenchConfig) -> Result<String> {
138 std::fs::write(&cache_path, &json_str)?;
139
140 let path_str = cache_path.to_string_lossy().to_string();
140 - println!(
141 - "SPEED-Bench ({config_name}): {} rows saved to {path_str}",
142 - all_rows.len()
141 + tracing::info!(
142 + config = config_name,
143 + rows = all_rows.len(),
144 + path = %path_str,
145 + "saved SPEED-Bench dataset"
146 );
147 Ok(path_str)
148 }
@@ -263,9 +266,11 @@ pub fn load_speed_bench_dataset(
266 // Oversample if needed
267 if samples.len() < num_requests {
268 if no_oversample {
266 - println!(
267 - "Skipping oversampling. Total samples: {} (requested: {num_requests})",
268 - samples.len()
269 + tracing::info!(
270 + dataset = "speed-bench",
271 + samples = samples.len(),
272 + requested = num_requests,
273 + "skipping dataset oversampling"
274 );
275 } else if !samples.is_empty() {
276 let original_len = samples.len();
@@ -275,9 +280,11 @@ pub fn load_speed_bench_dataset(
280 req.request_id = Some(format!("{request_id_prefix}{}", original_len + i));
281 samples.push(req);
282 }
278 - println!(
279 - "Oversampled SPEED-Bench from {original_len} to {} total samples.",
280 - samples.len()
283 + tracing::info!(
284 + dataset = "speed-bench",
285 + original_samples = original_len,
286 + samples = samples.len(),
287 + "oversampled dataset"
288 );
289 }
290 }
@@ -288,7 +295,6 @@ pub fn load_speed_bench_dataset(
295 ));
296 }
297
291 - // Print category distribution
298 let mut cat_counts: std::collections::HashMap<&str, usize> = std::collections::HashMap::new();
299 for entry in &filtered[..filtered.len().min(samples.len())] {
300 let cat = entry.get("category").and_then(|c| c.as_str()).unwrap_or("unknown");
@@ -297,7 +303,7 @@ pub fn load_speed_bench_dataset(
303 let mut cats: Vec<_> = cat_counts.into_iter().collect();
304 cats.sort_by_key(|b| std::cmp::Reverse(b.1));
305 let cat_str: Vec<String> = cats.iter().map(|(k, v)| format!("{k}:{v}")).collect();
300 - println!("SPEED-Bench categories: {}", cat_str.join(", "));
306 + tracing::info!(categories = %cat_str.join(", "), "computed SPEED-Bench category distribution");
307
308 Ok(samples)
309 }
rust/src/bench/src/lib.rs
+1 -1
@@ -33,7 +33,7 @@ pub fn prepare_process() {
33 if let Ok(new) = rlimit::increase_nofile_limit(u64::MAX)
34 && new > 1024
35 {
36 - eprintln!("Open-file limit: {new}");
36 + tracing::info!(soft_limit = new, "raised open-file limit");
37 }
38 }
39
rust/src/bench/src/main.rs
+12
@@ -19,7 +19,19 @@ struct Cli {
19 args: vllm_bench::BenchServeArgs,
20 }
21
22 +// TODO: unify the tracing subscriber used by different binaries.
23 +fn init_tracing() {
24 + let filter = tracing_subscriber::EnvFilter::try_from_default_env()
25 + .unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info"));
26 + let _ = tracing_subscriber::fmt()
27 + .with_env_filter(filter)
28 + .with_writer(std::io::stderr)
29 + .try_init();
30 +}
31 +
32 fn main() -> anyhow::Result<()> {
33 + init_tracing();
34 +
35 let cli = Cli::parse();
36 vllm_bench::prepare_process();
37
rust/src/bench/src/metrics/calculator.rs
+18 -16
@@ -7,6 +7,22 @@ use crate::datasets::SampleRequest;
7 use crate::metrics::{BenchmarkMetrics, MultiTurnMetrics};
8 use crate::multi_turn::ConversationOutput;
9
10 +fn log_failed_requests(outputs: &[RequestFuncOutput]) {
11 + let failed_outputs: Vec<_> = outputs.iter().filter(|output| !output.success).collect();
12 + if failed_outputs.is_empty() {
13 + return;
14 + }
15 +
16 + tracing::warn!(
17 + failed_requests = failed_outputs.len(),
18 + displayed_errors = failed_outputs.len().min(10),
19 + "benchmark requests failed"
20 + );
21 + for (index, output) in failed_outputs.into_iter().take(10).enumerate() {
22 + tracing::warn!(index, error = %output.error, "benchmark request failed");
23 + }
24 +}
25 +
26 /// Calculate benchmark metrics from request outputs.
27 ///
28 /// Mirrors Python's `calculate_metrics()` from serve.py:392-599.
@@ -63,14 +79,7 @@ pub fn calculate_metrics(
79
80 let failed = outputs.len() - completed;
81
66 - // Print failed request errors (capped to 10)
67 - let failed_outputs: Vec<&RequestFuncOutput> = outputs.iter().filter(|o| !o.success).collect();
68 - if !failed_outputs.is_empty() {
69 - eprintln!("Failed requests during benchmark run detected (capping to 10):");
70 - for (i, err) in failed_outputs.iter().take(10).enumerate() {
71 - eprintln!("Error {i}: {}", err.error);
72 - }
73 - }
82 + log_failed_requests(outputs);
83
84 // Calculate max output tokens per second and max concurrent requests
85 let mut max_output_tokens_per_s = 0.0_f64;
@@ -295,14 +304,7 @@ pub fn calculate_embedding_metrics(
304
305 let failed = outputs.len() - completed;
306
298 - // Print failed request errors (capped to 10)
299 - let failed_outputs: Vec<&RequestFuncOutput> = outputs.iter().filter(|o| !o.success).collect();
300 - if !failed_outputs.is_empty() {
301 - eprintln!("Failed requests during benchmark run detected (capping to 10):");
302 - for (i, err) in failed_outputs.iter().take(10).enumerate() {
303 - eprintln!("Error {i}: {}", err.error);
304 - }
305 - }
307 + log_failed_requests(outputs);
308
309 // Compute peak concurrent requests from start_time + latency windows
310 let successful_outputs: Vec<&RequestFuncOutput> =
rust/src/bench/src/multi_turn.rs
+50 -37
@@ -6,6 +6,7 @@ use std::sync::Arc;
6 use std::time::Instant;
7
8 use indicatif::{ProgressBar, ProgressStyle};
9 +use thiserror_ext::AsReport as _;
10 use tokio::sync::Semaphore;
11
12 use crate::backends::{Backend, RequestFuncInput, RequestFuncOutput, get_backend};
@@ -72,9 +73,13 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
73 let (model_id, model_name) = if let Some(ref m) = config.model {
74 (m.clone(), config.model_name.clone())
75 } else {
75 - println!("Model not specified, fetching first model from server...");
76 + tracing::info!(base_url = %config.base_url, "fetching first model from server");
77 let (name, id) = get_first_model(&config.base_url, &client, &config.extra_headers).await?;
77 - println!("First model name: {name}, first model id: {id}");
78 + tracing::info!(
79 + model_name = name,
80 + model_id = id,
81 + "selected first model from server"
82 + );
83 (id, Some(name))
84 };
85
@@ -83,15 +88,18 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
88 None
89 } else {
90 let tid = config.tokenizer_id.as_deref().unwrap_or(&model_id);
86 - println!("Loading tokenizer: {tid}");
91 + tracing::info!(tokenizer = tid, "loading tokenizer");
92 let server_info = Some((config.base_url.as_str(), model_id.as_str()));
93 let t = crate::tokenizer::load_tokenizer(tid, config.trust_remote_code, server_info)?;
89 - println!("Tokenizer loaded successfully.");
94 Some(t)
95 };
96
97 // Generate/load conversations
94 - println!("Generating multi-turn conversations...");
98 + tracing::info!(
99 + dataset = ?config.dataset_name,
100 + conversations = config.num_prompts,
101 + "generating multi-turn conversations"
102 + );
103 let gen_start = Instant::now();
104
105 let mut conversations = match config.dataset_name {
@@ -179,8 +187,11 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
187 let (filtered_conversations, filtered_turns) =
188 filter_turns_by_max_model_len(&mut conversations, max_model_len, no_history);
189 if filtered_turns > 0 || filtered_conversations > 0 {
182 - println!(
183 - "Filtered {filtered_turns} turn(s) and {filtered_conversations} conversation(s) above --max-model-len {max_model_len}."
190 + tracing::info!(
191 + filtered_turns,
192 + filtered_conversations,
193 + max_model_len,
194 + "filtered conversations above maximum model length"
195 );
196 }
197 if conversations.is_empty() {
@@ -192,11 +203,11 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
203
204 let gen_elapsed = gen_start.elapsed();
205 let total_turns: usize = conversations.iter().map(|c| c.turns.len()).sum();
195 - println!(
196 - "Generated {} conversations ({} total turns) in {:.2}s",
197 - conversations.len(),
206 + tracing::info!(
207 + conversations = conversations.len(),
208 total_turns,
199 - gen_elapsed.as_secs_f64()
209 + elapsed_seconds = gen_elapsed.as_secs_f64(),
210 + "generated multi-turn conversations"
211 );
212
213 // Log prefix sharing info
@@ -208,18 +219,15 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
219 let conv_tokens =
220 (real_input_len as f64 * config.multi_turn_prefix_conversation_ratio).floor() as usize;
221 let unique_tokens = real_input_len.saturating_sub(global_tokens + conv_tokens);
211 - println!(
212 - "User message prefix sharing: {:.0}% global ({} tokens), {:.0}% per-conversation ({} tokens), {:.0}% unique ({} tokens)",
213 - config.multi_turn_prefix_global_ratio * 100.0,
222 + tracing::info!(
223 + global_ratio = config.multi_turn_prefix_global_ratio,
224 global_tokens,
215 - config.multi_turn_prefix_conversation_ratio * 100.0,
216 - conv_tokens,
217 - (1.0 - config.multi_turn_prefix_global_ratio
218 - - config.multi_turn_prefix_conversation_ratio)
219 - * 100.0,
225 + conversation_ratio = config.multi_turn_prefix_conversation_ratio,
226 + conversation_tokens = conv_tokens,
227 unique_tokens,
228 + history_accumulation = false,
229 + "configured multi-turn prefix sharing"
230 );
222 - println!("No history accumulation: each turn sends fixed-length prompt only.");
231 }
232
233 if config.dry_run {
@@ -253,7 +261,7 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
261 ..Default::default()
262 };
263
256 - println!("Starting initial single prompt test run...");
264 + tracing::info!("starting initial single-prompt test run");
265 let test_output = crate::ready_checker::wait_for_endpoint(
266 config.backend,
267 &client,
@@ -268,7 +276,7 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
276 test_output.error
277 )));
278 }
271 - println!("Initial test run completed.");
279 + tracing::info!("initial single-prompt test run completed");
280 }
281
282 // For random datasets in multi-turn mode, auto-set min_tokens to enforce
@@ -283,9 +291,10 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
291 "min_tokens".to_string(),
292 serde_json::json!(config.random_output_len),
293 );
286 - println!(
287 - "Auto-setting min_tokens={} for multi-turn random dataset (use --extra-body to override)",
288 - config.random_output_len
294 + tracing::info!(
295 + min_tokens = config.random_output_len,
296 + dataset = "random",
297 + "set minimum output tokens for multi-turn dataset"
298 );
299 }
300 Some(body)
@@ -297,7 +306,7 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
306 let spec_decode_before =
307 fetch_spec_decode_metrics(&config.base_url, &client, &config.extra_headers).await;
308 if spec_decode_before.is_some() {
300 - println!("Speculative decoding detected, will collect metrics.");
309 + tracing::info!("detected speculative decoding; collecting metrics");
310 }
311
312 // Start profiler if requested (immediate mode — no batch threshold)
@@ -330,10 +339,13 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
339 };
340
341 // Main benchmark
333 - println!("Starting multi-turn benchmark...");
334 - println!("Conversations: {}", conversations.len());
335 - println!("Concurrency: {concurrency}");
336 - println!("Inter-turn delay: {} ms", config.multi_turn_delay_ms);
342 + tracing::info!(
343 + conversations = conversations.len(),
344 + total_turns,
345 + concurrency,
346 + inter_turn_delay_ms = config.multi_turn_delay_ms,
347 + "starting multi-turn benchmark"
348 + );
349
350 let max_turn_count = conversations.iter().map(|c| c.turns.len()).max().unwrap_or(0);
351
@@ -364,11 +376,12 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
376 );
377 if let Some(modules) = config.lora_modules.as_ref() {
378 let names: Vec<&str> = modules.iter().map(|s| s.as_ref()).collect();
367 - println!(
368 - "LoRA adapters ({}): {:?} [assignment={:?}, scope=conversation]",
369 - modules.len(),
370 - names,
371 - config.lora_assignment
379 + tracing::info!(
380 + adapters = modules.len(),
381 + names = ?names,
382 + assignment = ?config.lora_assignment,
383 + scope = "conversation",
384 + "assigned LoRA adapters"
385 );
386 }
387
@@ -433,7 +446,7 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
446 match handle.await {
447 Ok(output) => all_outputs.push(output),
448 Err(e) => {
436 - eprintln!("Conversation task panicked: {e}");
449 + tracing::error!(error = %e.as_report(), "conversation task panicked");
450 }
451 }
452 }
@@ -453,7 +466,7 @@ pub async fn run_multi_turn_benchmark(config: &BenchConfig) -> Result<serde_json
466 if let Some((cancel_tx, task)) = profile_task {
467 let _ = cancel_tx.send(());
468 if let Err(e) = task.await {
456 - eprintln!("WARNING: Profile background task failed: {e}");
469 + tracing::error!(error = %e.as_report(), "profiler background task failed");
470 }
471 }
472
rust/src/bench/src/output/json.rs
+2 -2
@@ -603,7 +603,7 @@ fn add_metric_stats(
603 pub fn save_result(json: &Value, file_path: &str) -> Result<()> {
604 let content = serde_json::to_string(json)?;
605 std::fs::write(file_path, content)?;
606 - println!("Results saved to {file_path}");
606 + tracing::info!(path = file_path, "saved benchmark results");
607 Ok(())
608 }
609
@@ -618,7 +618,7 @@ pub fn append_result(json: &Value, file_path: &str) -> Result<()> {
618 file.write_all(b"\n")?;
619 }
620 file.write_all(content.as_bytes())?;
621 - println!("Results appended to {file_path}");
621 + tracing::info!(path = file_path, "appended benchmark results");
622 Ok(())
623 }
624
rust/src/bench/src/ready_checker.rs
+8 -2
@@ -23,7 +23,11 @@ pub async fn wait_for_endpoint(
23 let backend = get_backend(backend)?;
24 let deadline = Instant::now() + std::time::Duration::from_secs(timeout_seconds);
25
26 - println!("Waiting for endpoint to become up in {timeout_seconds}s");
26 + tracing::info!(
27 + timeout_seconds,
28 + retry_interval,
29 + "waiting for endpoint readiness"
30 + );
31
32 let pb = ProgressBar::new(timeout_seconds);
33 pb.set_style(
@@ -53,7 +57,9 @@ pub async fn wait_for_endpoint(
57 Ok(output) => {
58 let err = output.error.clone();
59 let err_last_line = err.lines().last().unwrap_or(&err);
56 - eprintln!("Endpoint is not ready. Error='{err_last_line}'");
60 + pb.suspend(|| {
61 + tracing::warn!(error = err_last_line, "endpoint is not ready");
62 + });
63 last_error = err;
64 }
65 Err(e) => {
rust/src/bench/src/sweep.rs
+1 -1
@@ -16,7 +16,7 @@ async fn reset_prefix_cache(base_url: &str) -> Result<()> {
16 .await
17 .map_err(|e| BenchError::Backend(format!("Failed to reset prefix cache: {e}")))?;
18 if resp.status().is_success() {
19 - println!("Prefix cache reset successfully.");
19 + tracing::info!(url = %url, "reset prefix cache");
20 } else {
21 let status = resp.status();
22 let body = resp.text().await.unwrap_or_default();
rust/src/bench/src/tiktoken.rs
+15 -9
@@ -199,7 +199,12 @@ pub fn load_builtin_tiktoken(encoding: &str) -> Result<TiktokenTokenizer> {
199 }
200 };
201 let bpe = bpe.map_err(|e| BenchError::Tokenizer(format!("Failed to load {encoding}: {e}")))?;
202 - println!("Tokenizer: Built-in tiktoken {encoding} (vocab_size={vocab_size})");
202 + tracing::info!(
203 + encoding,
204 + kind = "built-in-tiktoken",
205 + vocab_size,
206 + "loaded tokenizer"
207 + );
208 Ok(TiktokenTokenizer::from_builtin_bpe(bpe, vocab_size))
209 }
210
@@ -309,15 +314,16 @@ fn build_tiktoken(
314 }
315 }
316
312 - println!(
313 - "Loading tiktoken model for '{model_id}' (base={}, special={}, pat={})...",
314 - num_base_tokens,
315 - all_special_tokens.len(),
316 - if pattern.is_some() {
317 + tracing::info!(
318 + model = model_id,
319 + base_tokens = num_base_tokens,
320 + special_tokens = all_special_tokens.len(),
321 + pattern = if pattern.is_some() {
322 "custom"
323 } else {
324 "default"
325 },
326 + "loading tiktoken model"
327 );
328
329 TiktokenTokenizer::from_file(
@@ -438,9 +444,9 @@ fn extract_pat_str_from_source(source: &str) -> Option<String> {
444
445 if !fragments.is_empty() {
446 let pattern = fragments.join("|");
441 - println!(
442 - "Extracted pat_str from Python source: {} fragments",
443 - fragments.len()
447 + tracing::debug!(
448 + fragments = fragments.len(),
449 + "extracted tiktoken pattern from Python source"
450 );
451 return Some(pattern);
452 }
rust/src/bench/src/tokenizer.rs
+27 -9
@@ -4,6 +4,7 @@
4 use std::collections::HashSet;
5 use std::path::Path;
6
7 +use thiserror_ext::AsReport as _;
8 use tokenizers::Tokenizer;
9
10 use crate::error::{BenchError, Result};
@@ -214,29 +215,46 @@ pub fn load_tokenizer(
215 // 1. Try local HuggingFace tokenizer (tokenizer.json)
216 match try_load_local(model_id) {
217 Ok(tok) => {
217 - println!("Tokenizer: Local (vocab_size={})", tok.get_vocab_size(true));
218 + tracing::info!(
219 + model = model_id,
220 + kind = "local",
221 + vocab_size = tok.get_vocab_size(true),
222 + "loaded tokenizer"
223 + );
224 Ok(TokenizerKind::Local(Box::new(tok)))
225 }
226 Err(local_err) => {
227 // 2. Try tiktoken format
222 - println!("No tokenizer.json for '{model_id}', trying tiktoken format...");
228 + tracing::info!(
229 + model = model_id,
230 + error = %local_err.as_report(),
231 + "local tokenizer unavailable; trying tiktoken"
232 + );
233 match crate::tiktoken::try_load_tiktoken(model_id) {
234 Ok(tok) => {
225 - println!("Tokenizer: Tiktoken (vocab_size={})", tok.vocab_size());
235 + tracing::info!(
236 + model = model_id,
237 + kind = "tiktoken",
238 + vocab_size = tok.vocab_size(),
239 + "loaded tokenizer"
240 + );
241 Ok(TokenizerKind::Tiktoken(tok))
242 }
243 Err(tiktoken_err) => {
244 // 3. Try server-side fallback
245 if let Some((base_url, model)) = server_info {
231 - println!(
232 - "Tiktoken also not available ({tiktoken_err}), \
233 - trying server-side tokenization..."
246 + tracing::info!(
247 + model = model_id,
248 + error = %tiktoken_err.as_report(),
249 + "tiktoken unavailable; trying server-side tokenization"
250 );
251 match ServerTokenizer::new(base_url, model) {
252 Ok(srv) => {
237 - println!(
238 - "Tokenizer: Server (vocab_size≈{})",
239 - srv.cached_vocab_size
253 + tracing::info!(
254 + model = model_id,
255 + kind = "server",
256 + vocab_size = srv.cached_vocab_size,
257 + "loaded tokenizer"
258 );
259 return Ok(TokenizerKind::Server(srv));
260 }
rust/src/cmd/src/logging.rs
+17 -7
@@ -26,18 +26,21 @@ const RESET: &str = "\x1b[0m";
26 const VLLM_TIME_FORMAT: &[time::format_description::FormatItem<'static>] =
27 format_description!("[month]-[day] [hour]:[minute]:[second]");
28
29 -const PROCESS_LABEL: &str = "RustFrontend";
30 -
29 /// Install the process-wide vLLM-style tracing subscriber for the CLI binary.
32 -pub(crate) fn init_tracing() {
30 +pub(crate) fn init_tracing(process_label: &str) {
31 let filter = build_targets_filter(
32 env::var("VLLM_LOGGING_LEVEL").ok().as_deref(),
33 env::var("RUST_LOG").ok().as_deref(),
34 );
37 - let formatter = VllmEventFormatter::new();
35 + let formatter = VllmEventFormatter::new(process_label);
36
37 let _ = tracing_subscriber::registry()
40 - .with(tracing_subscriber::fmt::layer().event_format(formatter).with_filter(filter))
38 + .with(
39 + tracing_subscriber::fmt::layer()
40 + .event_format(formatter)
41 + .with_writer(std::io::stderr)
42 + .with_filter(filter),
43 + )
44 .try_init();
45 }
46
@@ -94,9 +97,9 @@ struct VllmEventFormatter {
97 }
98
99 impl VllmEventFormatter {
97 - fn new() -> Self {
100 + fn new(process_label: &str) -> Self {
101 Self {
99 - prefix: format!("({} pid={})", PROCESS_LABEL, process::id()),
102 + prefix: format!("({process_label} pid={})", process::id()),
103 timer: VllmLocalTimer::default(),
104 }
105 }
@@ -291,6 +294,13 @@ fn map_python_log_level(level: &str) -> LevelFilter {
294 mod tests {
295 use super::*;
296
297 + #[test]
298 + fn formatter_prefix_uses_process_label() {
299 + let formatter = VllmEventFormatter::new("Bench");
300 +
301 + assert_eq!(formatter.prefix, format!("(Bench pid={})", process::id()));
302 + }
303 +
304 #[test]
305 fn rust_log_target_overrides_are_merged_with_vllm_default_level() {
306 let filter = build_targets_filter(Some("DEBUG"), Some("hyper=warn,tower=error"));
rust/src/cmd/src/main.rs
+9 -1
@@ -5,6 +5,7 @@ mod cli;
5 mod logging;
6
7 use std::env;
8 +use std::ffi::OsStr;
9 use std::process::ExitStatus;
10
11 use anyhow::{Context, Result, anyhow, bail};
@@ -82,7 +83,14 @@ fn shutdown_signal() -> CancellationToken {
83 }
84
85 fn main() -> Result<()> {
85 - logging::init_tracing();
86 + let process_label =
87 + match env::args_os().nth(1).as_deref().and_then(OsStr::to_str).unwrap_or_default() {
88 + "bench" => "Bench",
89 + "serve" | "frontend" => "RustFrontend",
90 + _ => "Rust",
91 + };
92 + logging::init_tracing(process_label);
93 +
94 let cli = Cli::parse();
95
96 let mut runtime = tokio::runtime::Builder::new_multi_thread();