diff --git a/src/cli.rs b/src/cli.rs index e07a2cc..2493931 100644 --- a/src/cli.rs +++ b/src/cli.rs @@ -5,15 +5,17 @@ use crate::metrics::{LatencySummary, Metrics, MetricsSummary}; use crate::report::{ BenchmarkParamsReport, BenchmarkReport, BenchmarkSummaryReport, CorrectCaseReport, DatasetReport, LatencyReport, LimiterInferenceKind, LimiterInferenceReport, PhaseSummaryReport, - ProbeSecondReport, RpmModeDetailReport, RpmParamsReport, RpmReport, RpmRunReport, - RpmSummaryReport, RunReport, SentRequestParamsReport, ThinkingParamsReport, + ProbeSecondReport, RequestDebugReport, RpmModeDetailReport, RpmParamsReport, RpmReport, + RpmRunReport, RpmSummaryReport, RunReport, SentRequestParamsReport, ThinkingParamsReport, WindowBoundaryReport, WrongCaseReport, write_benchmark_report, write_rpm_report, }; use crate::rpm_modes::{ ProbePhase, RpmMode, ScheduledProbe, burst_schedule, sliding_window_schedule, sustained_schedule, token_bucket_schedule, window_boundary_plan, }; -use crate::runner::{ModelRequest, RawDebugConfig, ThinkingConfig, run_model_request}; +use crate::runner::{ + ModelRequest, ModelResponse, RawDebugConfig, ThinkingConfig, run_model_request, +}; use anyhow::{Context, Result, bail}; use chrono::Utc; use clap::{Parser, Subcommand}; @@ -449,10 +451,21 @@ async fn run_aime_benchmark(options: BenchmarkCommandOptions) -> Result<()> { let mut metrics = Metrics::new(); let mut wrong_cases = Vec::new(); let mut correct_samples = Vec::new(); + let mut debug_requests = Vec::new(); while let Some((case, result)) = results.next().await { pb.inc(1); match result { Ok(response) => { + let prompt = case.prompt(); + if let Some(debug) = + response_debug_report(Some(case.id.clone()), None, None, prompt, &response) + { + debug_requests.push(debug); + } + if response_has_no_content(&response) { + metrics.record_failure("request_error"); + continue; + } metrics.record_success( response.status, response.elapsed_ms as u64, @@ -503,6 +516,7 @@ async fn run_aime_benchmark(options: BenchmarkCommandOptions) -> Result<()> { summary, correct_samples, wrong_cases, + debug_requests, }); let report_path = write_benchmark_report(Path::new("."), &report)?; print_benchmark_report(&report, &report_path); @@ -559,10 +573,21 @@ async fn run_gpqa_benchmark(options: BenchmarkCommandOptions) -> Result<()> { let mut metrics = Metrics::new(); let mut wrong_cases = Vec::new(); let mut correct_samples = Vec::new(); + let mut debug_requests = Vec::new(); while let Some((case, result)) = results.next().await { pb.inc(1); match result { Ok(response) => { + let prompt = case.prompt(); + if let Some(debug) = + response_debug_report(Some(case.id.clone()), None, None, prompt, &response) + { + debug_requests.push(debug); + } + if response_has_no_content(&response) { + metrics.record_failure("request_error"); + continue; + } metrics.record_success( response.status, response.elapsed_ms as u64, @@ -615,6 +640,7 @@ async fn run_gpqa_benchmark(options: BenchmarkCommandOptions) -> Result<()> { summary, correct_samples, wrong_cases, + debug_requests, }); let report_path = write_benchmark_report(Path::new("."), &report)?; print_benchmark_report(&report, &report_path); @@ -683,6 +709,8 @@ async fn run_rpm(config_path: PathBuf, options: RpmCommandOptions) -> Result<()> let started = Instant::now(); let mut metrics = Metrics::new(); let mut mode_summary = RpmModeSummaryBuilder::default(); + let mut debug_requests = Vec::new(); + let prompt_for_debug = request.prompt.clone(); let results = run_scheduled_requests( provider_config.protocol, @@ -693,14 +721,32 @@ async fn run_rpm(config_path: PathBuf, options: RpmCommandOptions) -> Result<()> .await; for result in results { - let success = result.result.is_ok(); + let success = result + .result + .as_ref() + .is_ok_and(|response| !response_has_no_content(response)); mode_summary.record(result.phase, result.second, success); match result.result { - Ok(response) => metrics.record_success( - response.status, - response.elapsed_ms as u64, - response.first_token_ms.map(|ms| ms as u64), - ), + Ok(response) => { + if let Some(debug) = response_debug_report( + None, + Some(phase_name(result.phase).to_string()), + result.second, + prompt_for_debug.clone(), + &response, + ) { + debug_requests.push(debug); + } + if response_has_no_content(&response) { + metrics.record_failure("request_error"); + continue; + } + metrics.record_success( + response.status, + response.elapsed_ms as u64, + response.first_token_ms.map(|ms| ms as u64), + ); + } Err(error) => metrics.record_failure(error_code(&error)), } } @@ -738,6 +784,7 @@ async fn run_rpm(config_path: PathBuf, options: RpmCommandOptions) -> Result<()> mode: mode_plan.mode_name.to_string(), mode_detail: mode_summary.into_report(options.mode), errors: summary.errors, + debug_requests, }; let report_path = write_rpm_report(Path::new("."), &report)?; print_rpm_report(&report, &report_path); @@ -1250,6 +1297,7 @@ struct BenchmarkReportInput { summary: MetricsSummary, correct_samples: Vec, wrong_cases: Vec, + debug_requests: Vec, } fn benchmark_report(input: BenchmarkReportInput) -> BenchmarkReport { @@ -1284,6 +1332,71 @@ fn benchmark_report(input: BenchmarkReportInput) -> BenchmarkReport { errors: input.summary.errors, correct_samples: input.correct_samples, wrong_cases: input.wrong_cases, + debug_requests: input.debug_requests, + } +} + +const NEAR_TTFT_LATENCY_THRESHOLD_MS: u128 = 1_000; + +fn response_debug_report( + id: Option, + phase: Option, + second: Option, + prompt: String, + response: &ModelResponse, +) -> Option { + let ttft_latency_delta_ms = response + .first_token_ms + .map(|ttft_ms| response.elapsed_ms.abs_diff(ttft_ms)); + let near_ttft_latency = + ttft_latency_delta_ms.is_some_and(|delta_ms| delta_ms < NEAR_TTFT_LATENCY_THRESHOLD_MS); + let has_think_tags = contains_think_tags(&response.text); + let no_content = response_has_no_content(response); + + let mut reasons = Vec::new(); + if no_content { + reasons.push("no_content"); + } + if near_ttft_latency { + reasons.push("near_ttft_latency"); + } + if has_think_tags { + reasons.push("contains_think_tags"); + } + if reasons.is_empty() { + return None; + } + + Some(RequestDebugReport { + reason: reasons.join(","), + id, + phase, + second, + prompt, + output: response.text.clone(), + latency_ms: response.elapsed_ms, + ttft_ms: response.first_token_ms, + ttft_latency_delta_ms, + has_think_tags, + }) +} + +fn response_has_no_content(response: &ModelResponse) -> bool { + response.text.trim().is_empty() +} + +fn contains_think_tags(text: &str) -> bool { + let lower = text.to_ascii_lowercase(); + lower.contains("") && lower.contains("") +} + +fn phase_name(phase: ProbePhase) -> &'static str { + match phase { + ProbePhase::Burst => "burst", + ProbePhase::RefillProbe => "refill_probe", + ProbePhase::SlidingProbe => "sliding_probe", + ProbePhase::BeforeBoundary => "before_boundary", + ProbePhase::AfterBoundary => "after_boundary", } } @@ -1893,6 +2006,75 @@ mod tests { ); } + #[test] + fn response_debug_report_records_near_ttft_latency_with_full_prompt_and_output() { + let response = ModelResponse { + text: "final answer".to_string(), + status: 200, + elapsed_ms: 1_500, + first_token_ms: Some(750), + }; + + let debug = response_debug_report( + Some("case-1".to_string()), + None, + None, + "full prompt".to_string(), + &response, + ) + .expect("near ttft/latency should be debugged"); + + assert_eq!(debug.reason, "near_ttft_latency"); + assert_eq!(debug.id.as_deref(), Some("case-1")); + assert_eq!(debug.prompt, "full prompt"); + assert_eq!(debug.output, "final answer"); + assert_eq!(debug.latency_ms, 1_500); + assert_eq!(debug.ttft_ms, Some(750)); + assert_eq!(debug.ttft_latency_delta_ms, Some(750)); + assert!(!debug.has_think_tags); + } + + #[test] + fn response_debug_report_marks_think_tags() { + let response = ModelResponse { + text: "hidden\nanswer".to_string(), + status: 200, + elapsed_ms: 5_000, + first_token_ms: Some(100), + }; + + let debug = response_debug_report(None, None, None, "prompt".to_string(), &response) + .expect("think tags should be debugged"); + + assert_eq!(debug.reason, "contains_think_tags"); + assert!(debug.has_think_tags); + assert_eq!(debug.ttft_latency_delta_ms, Some(4_900)); + } + + #[test] + fn response_debug_report_records_empty_content_as_request_debug() { + let response = ModelResponse { + text: " ".to_string(), + status: 200, + elapsed_ms: 2_000, + first_token_ms: None, + }; + + let debug = response_debug_report( + None, + Some("burst".to_string()), + Some(0), + "prompt".to_string(), + &response, + ) + .expect("empty content should be debugged"); + + assert_eq!(debug.reason, "no_content"); + assert_eq!(debug.phase.as_deref(), Some("burst")); + assert_eq!(debug.second, Some(0)); + assert!(response_has_no_content(&response)); + } + #[test] fn rpm_command_parses_window_boundary_offset() { let cli = Cli::try_parse_from([ diff --git a/src/report.rs b/src/report.rs index 1371575..33a2eba 100644 --- a/src/report.rs +++ b/src/report.rs @@ -71,6 +71,7 @@ pub struct BenchmarkReport { pub errors: Vec, pub correct_samples: Vec, pub wrong_cases: Vec, + pub debug_requests: Vec, } #[derive(Debug, Clone, Serialize)] @@ -140,6 +141,21 @@ pub struct RpmReport { pub summary: RpmSummaryReport, pub mode_detail: Option, pub errors: Vec, + pub debug_requests: Vec, +} + +#[derive(Debug, Clone, Serialize)] +pub struct RequestDebugReport { + pub reason: String, + pub id: Option, + pub phase: Option, + pub second: Option, + pub prompt: String, + pub output: String, + pub latency_ms: u128, + pub ttft_ms: Option, + pub ttft_latency_delta_ms: Option, + pub has_think_tags: bool, } #[derive(Debug, Clone, Serialize)] @@ -330,6 +346,7 @@ mod tests { errors: vec![], correct_samples: vec![], wrong_cases: vec![], + debug_requests: vec![], }; let path = write_benchmark_report(temp_dir.path(), &report).expect("write report"); @@ -380,6 +397,18 @@ mod tests { mode: "sustained".to_string(), mode_detail: None, errors: vec![], + debug_requests: vec![RequestDebugReport { + reason: "near_ttft_latency".to_string(), + id: None, + phase: Some("refill_probe".to_string()), + second: Some(1), + prompt: "Hi".to_string(), + output: "xdone".to_string(), + latency_ms: 1000, + ttft_ms: Some(1000), + ttft_latency_delta_ms: Some(0), + has_think_tags: true, + }], }; let json = serde_json::to_string(&report).expect("serialize report"); @@ -387,6 +416,9 @@ mod tests { assert!(json.contains("\"prompt\":\"Hi\"")); assert!(json.contains("\"stream\":false")); assert!(json.contains("\"duration\":\"60s\"")); + assert!(json.contains("\"debug_requests\"")); + assert!(json.contains("\"reason\":\"near_ttft_latency\"")); + assert!(json.contains("\"has_think_tags\":true")); } #[test] @@ -458,6 +490,7 @@ mod tests { }), }), errors: vec![], + debug_requests: vec![], }; let json = serde_json::to_string(&report).expect("serialize report");