Просмотр исходного кода

feat: record response debug cases in reports

codex/lq-token-test-init
orangels 1 месяц назад
Родитель
Сommit
70ced01112
2 измененных файлов: 224 добавлений и 9 удалений
  1. +191
    -9
      src/cli.rs
  2. +33
    -0
      src/report.rs

+ 191
- 9
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<CorrectCaseReport>,
wrong_cases: Vec<WrongCaseReport>,
debug_requests: Vec<RequestDebugReport>,
}

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<String>,
phase: Option<String>,
second: Option<u64>,
prompt: String,
response: &ModelResponse,
) -> Option<RequestDebugReport> {
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("<think>") && lower.contains("</think>")
}

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: "<think>hidden</think>\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([


+ 33
- 0
src/report.rs Просмотреть файл

@@ -71,6 +71,7 @@ pub struct BenchmarkReport {
pub errors: Vec<ErrorCount>,
pub correct_samples: Vec<CorrectCaseReport>,
pub wrong_cases: Vec<WrongCaseReport>,
pub debug_requests: Vec<RequestDebugReport>,
}

#[derive(Debug, Clone, Serialize)]
@@ -140,6 +141,21 @@ pub struct RpmReport {
pub summary: RpmSummaryReport,
pub mode_detail: Option<RpmModeDetailReport>,
pub errors: Vec<ErrorCount>,
pub debug_requests: Vec<RequestDebugReport>,
}

#[derive(Debug, Clone, Serialize)]
pub struct RequestDebugReport {
pub reason: String,
pub id: Option<String>,
pub phase: Option<String>,
pub second: Option<u64>,
pub prompt: String,
pub output: String,
pub latency_ms: u128,
pub ttft_ms: Option<u128>,
pub ttft_latency_delta_ms: Option<u128>,
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: "<think>x</think>done".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");


Загрузка…
Отмена
Сохранить