ForgeLM/experiments/worklog.md

Autoresearch Worklog: latency-p95-chat-completions

Session Summary

• Objective: reduce end-to-end p95 latency for local POST /v1/chat/completions
• Primary metric: p95_ms (lower is better)
• Secondary metrics: p50_ms, mean_ms, completion_tps_mean, success_count
• Benchmark harness: ./autoresearch.sh

Key Insights

• The first stable end-to-end benchmark is around 0.94 s p95 for a short non-streaming coding request on the local 4B GGUF model.
• The benchmark harness must use the canonical model id derived from the GGUF filename; the current server build does not actually honor the intended local-model alias path yet.
• Prompt prefill is only about 25 ms for this workload, so almost all latency sits in token generation rather than request parsing or prompt construction.
• A micro-optimization in per-token detokenization made both latency and throughput worse, which suggests the dominant cost is deeper in the generation/runtime path rather than heap allocation in Rust glue code.
• Shrinking the Turbo4B context and batch sizes also hurt throughput, so the current 4B profile appears closer to the local optimum for this hardware/workload than expected.
• Disabling internal llama.cpp perf counters produced the first real p95 improvement over baseline, which suggests a small but measurable amount of hot-path CPU overhead was coming from instrumentation rather than model math.
• Better stop behavior improved average and median latency, but it still failed to beat baseline p95, so the worst outliers are not explained solely by turn-boundary overruns.
• Switching to a Qwen-style chat template produced a severe p95 tail regression while median latency stayed near baseline, which strongly suggests worse stop behavior or occasional runaway generations rather than uniformly slower decoding.

Next Ideas

• Measure baseline first, then inspect the hottest latency contributors in prompt preparation, request handling, and session creation.
• Investigate why ModelCatalog rejects local-model despite intending to expose aliases.

Run 1: baseline - p95_ms=941.252 (KEEP)

• Timestamp: 2026-03-26 17:32
• What changed: Established the autoresearch harness, built the release server, started it against the local Qwen GGUF, and measured a fixed non-streaming coding request workload.
• Result: p95_ms=941.252, p50_ms=908.457, mean_ms=917.123, completion_tps_mean=52.427, success_count=7.
• Insight: The baseline is stable enough to compare future server/runtime changes, and the benchmark immediately exposed a compatibility bug in alias resolution that should be kept separate from true latency experiments.
• Next: fix low-risk benchmark-adjacent correctness issues only if they distort measurement; otherwise inspect hot latency contributors in the request/session path.

Run 2: stack buffer detokenization - p95_ms=1032.315 (DISCARD)

• Timestamp: 2026-03-26 17:38
• What changed: Replaced the per-token heap allocation in decode_token_piece_with() with a 256-byte stack buffer and heap fallback in crates/inference-core/src/session.rs.
• Result: p95_ms=1032.315, p50_ms=1020.402, mean_ms=1011.466, completion_tps_mean=47.671, success_count=7.
• Insight: This path is not the practical bottleneck for end-to-end latency here; generation got slower overall despite the reduced allocation churn.
• Next: discard this branch state and focus on runtime/profile-level experiments that can improve generation throughput directly.

Run 3: slim turbo4b runtime profile - p95_ms=1004.435 (DISCARD)

• Timestamp: 2026-03-26 17:40
• What changed: Reduced Turbo4B defaults in crates/inference-core/src/profile.rs from n_ctx=4096, n_batch=512, n_ubatch=128 to n_ctx=2048, n_batch=256, n_ubatch=64.
• Result: p95_ms=1004.435, p50_ms=998.919, mean_ms=990.771, completion_tps_mean=48.528, success_count=7.
• Insight: The leaner profile still reduced effective generation speed on this RTX 3070 + Q6_K workload, so the current batch/context sizing is likely not the source of the baseline latency.
• Next: revert to the best-known commit and target generation semantics or model-facing prompt/template strategy rather than detokenization or profile shrinkage.

Run 6: disable llama perf counters in hot path - p95_ms=925.587 (KEEP)

• Timestamp: 2026-03-26 17:57
• What changed: Set llama_context_params.no_perf = true in crates/inference-core/src/engine.rs and sampler_chain_default_params.no_perf = true in crates/inference-core/src/session.rs.
• Result: p95_ms=925.587, p50_ms=893.913, mean_ms=899.895, completion_tps_mean=53.618, success_count=7.
• Insight: Disabling internal perf bookkeeping shaved about 1.7% off baseline p95 with slightly better overall throughput, making this the first experiment worth keeping.
• Next: continue from this commit and look for adjacent hot-path flags or runtime settings that reduce generation overhead without changing model behavior.

Run 5: default turn-boundary stops - p95_ms=965.663 (DISCARD)

• Timestamp: 2026-03-26 17:54
• What changed: Added rolling multi-token stop detection in crates/inference-core/src/session.rs and injected default turn-boundary stop sequences in crates/inference-server/src/compat.rs when the request did not specify stop.
• Result: p95_ms=965.663, p50_ms=877.030, mean_ms=897.251, completion_tps_mean=53.686, success_count=7.
• Insight: This reduced median and mean latency and slightly improved throughput, but the p95 still stayed above baseline, so tail latency likely comes from a smaller number of deeper generation stalls rather than just missed stop boundaries.
• Next: inspect per-sample latency spread and target the remaining long-tail outliers directly, likely in warmup/first-request behavior or occasional decode stalls.

Run 4: qwen-style chat template - p95_ms=3027.145 (DISCARD)

• Timestamp: 2026-03-26 17:50
• What changed: Replaced the plain System/User/Assistant: prompt format in crates/inference-server/src/compat.rs with a Qwen-style <|im_start|>...<|im_end|> chat template.
• Result: p95_ms=3027.145, p50_ms=974.937, mean_ms=1467.026, completion_tps_mean=41.360, success_count=7.
• Insight: The template did not make typical requests much faster and introduced severe tail latency, likely because some generations stopped much later or followed a worse decoding path for this server/model combination.
• Next: revert this template change and focus on experiments that directly bound generation length or improve stop behavior without overhauling the prompt format.

Segment 1: Dynamic Chat Templates

• New objective: add dynamic prompt templates by model family with built-in coverage for Qwen, Gemma, Llama, Kimi, and a generic fallback.
• Benchmark driver: ./autoresearch.sh now runs ignored template-specific tests and reports template_score, passed_cases, failed_cases, and total_cases.
• Keep/discard rule for this segment is test-driven: higher template_score wins, while the regular non-ignored test suite must remain green.

Run 7: baseline - template_score=20.0 (KEEP)

• Timestamp: 2026-03-26 18:14
• What changed: Re-initialized autoresearch to a new segment focused on dynamic chat templates, added a dedicated ignored test suite for Qwen, Gemma, Llama, Kimi, and generic fallback behavior, and switched the benchmark harness to score that suite.
• Result: template_score=20.0, passed_cases=1, failed_cases=4, total_cases=5.
• Insight: Only the generic fallback works today; all named family-template expectations fail because prompt rendering is still generic and model-agnostic.
• Next: add a minimal model-family detector and template registry in crates/inference-server/src/compat.rs, then route prepare_prompt() through it.