From f8732a036c9cbc395385698fd58b6caae7515201 Mon Sep 17 00:00:00 2001 From: tawei-amd Date: Fri, 30 Oct 2026 15:36:35 -0700 Subject: [PATCH 1/2] feat(server): log a 'Request done:' timing summary for every request, streamed or not (#841) One stable-prefix line per finished request: prompt tokens (and cached), prefill time and tok/s, generated tokens, decode time and tok/s, kv use, finish reason. Covers OpenAI chat/completions and Ollama chat/generate, streamed or not, regardless of stream_options.include_usage. Co-Authored-By: Claude Sonnet 5.5 --- src/server/rest_handler.cpp | 27 +++++++++++++++++++++++++++ 1 file changed, 27 insertions(+) diff --git a/src/server/rest_handler.cpp b/src/server/rest_handler.cpp index 3109b7ade..5849b9bb7 100644 --- a/src/server/rest_handler.cpp +++ b/src/server/rest_handler.cpp @@ -36,6 +36,26 @@ json ExceptionResponse(const std::exception& error) { return {{"error", error.what()}}; } +/// \brief One line per finished request in the server log, streamed or not, whatever the client asked for +/// \note The prefix "Request done:" is stable so tools can grep it +void log_request_summary(const chat_meta_info_t& m, size_t kv_used, size_t kv_max) { + const double prefill_s = static_cast(m.prefill_duration) / 1e9; + const double decode_s = static_cast(m.decoding_duration) / 1e9; + const auto new_prompt = m.prompt_tokens > m.cached_prompt_tokens ? m.prompt_tokens - m.cached_prompt_tokens : 0; + std::ostringstream os; + os << std::fixed << std::setprecision(3) + << "Request done: prompt " << m.prompt_tokens << " tokens"; + if (m.cached_prompt_tokens > 0) os << " (" << m.cached_prompt_tokens << " cached)"; + os << " (prefill " << prefill_s << " s" << std::setprecision(2); + if (prefill_s > 0) os << ", " << new_prompt / prefill_s << " tok/s"; + os << "), generated " << m.generated_tokens << " tokens (decode " + << std::setprecision(3) << decode_s << " s" << std::setprecision(2); + if (decode_s > 0) os << ", " << m.generated_tokens / decode_s << " tok/s"; + os << "), kv " << kv_used << "/" << kv_max + << ", finish " << stop_reason_to_string(m.stop_reason); + header_print("FLM", os.str()); +} + /// \brief Whether a request sets a field /// \note Some clients send null for every option they leave unset, so null /// counts as not set; json::value() and conversions throw on it instead. @@ -1011,6 +1031,7 @@ void RestHandler::handle_generate(const json& request, // std::cout << "history: " << history.first << std::endl; meta_info.total_duration = (uint64_t)time_utils::duration_ns(total_start_time, total_end_time).first; ostream.finalize_generate(meta_info, history.second); + log_request_summary(meta_info, this->auto_chat_engine->get_current_context_length(), this->auto_chat_engine->get_max_length()); } else { // Non-streaming response std::stringstream ss; @@ -1055,6 +1076,7 @@ void RestHandler::handle_generate(const json& request, {"done_reason", stop_reason_to_string(meta_info.stop_reason)} }; // std::cout << "history: " << history.first << std::endl; + log_request_summary(meta_info, this->auto_chat_engine->get_current_context_length(), this->auto_chat_engine->get_max_length()); send_response(response); } } catch (const std::exception& e) { @@ -1133,6 +1155,7 @@ void RestHandler::handle_chat(const json& request, meta_info.total_duration = (uint64_t)time_utils::duration_ns(total_start_time, total_end_time).first; ostream.finalize_chat(meta_info); + log_request_summary(meta_info, this->auto_chat_engine->get_current_context_length(), this->auto_chat_engine->get_max_length()); // auto history = this->chat_engine->get_history(); // std::cout << "history: " << history.first << std::endl; this->auto_chat_engine->clear_context(); @@ -1656,6 +1679,7 @@ void RestHandler::handle_openai_chat_completion(const json& request, header_print("ERROR", std::string("Finishing the stream failed: ") + e.what()); send_stream_error(ExceptionResponse(e)); } + log_request_summary(meta_info, this->auto_chat_engine->get_current_context_length(), this->auto_chat_engine->get_max_length()); } else { nullstream nstream; @@ -1739,6 +1763,7 @@ void RestHandler::handle_openai_chat_completion(const json& request, header_print("❌ ", "Generation Cancelled!"); this->prompt_cache.reset(); } + log_request_summary(meta_info, this->auto_chat_engine->get_current_context_length(), this->auto_chat_engine->get_max_length()); send_response(response); } @@ -1987,6 +2012,7 @@ void RestHandler::handle_openai_completion(const json& request, header_print("ERROR", std::string("Finishing the stream failed: ") + e.what()); send_stream_error(ExceptionResponse(e)); } + log_request_summary(meta_info, this->auto_chat_engine->get_current_context_length(), this->auto_chat_engine->get_max_length()); this->auto_chat_engine->clear_context(); } @@ -2041,6 +2067,7 @@ void RestHandler::handle_openai_completion(const json& request, }} }; if (meta_info.prefix_cache.valid) response["usage"]["flm_prefix_cache"] = prefix_cache_usage_json(meta_info.prefix_cache); + log_request_summary(meta_info, this->auto_chat_engine->get_current_context_length(), this->auto_chat_engine->get_max_length()); send_response(response); } } From ca907ec85c1d4b3bc4008f73d7811b2c21f80a34 Mon Sep 17 00:00:00 2001 From: tawei-amd Date: Fri, 30 Oct 2026 15:43:14 -0700 Subject: [PATCH 2/2] fix(server): also log the summary for non-streamed Ollama chat (#841) Co-Authored-By: Claude Sonnet 5.5 --- src/server/rest_handler.cpp | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/server/rest_handler.cpp b/src/server/rest_handler.cpp index 5849b9bb7..5332abcd2 100644 --- a/src/server/rest_handler.cpp +++ b/src/server/rest_handler.cpp @@ -1198,8 +1198,9 @@ void RestHandler::handle_chat(const json& request, {"eval_duration", meta_info.decoding_duration}, {"done_reason", stop_reason_to_string(meta_info.stop_reason)} }; + log_request_summary(meta_info, this->auto_chat_engine->get_current_context_length(), this->auto_chat_engine->get_max_length()); send_response(response); - + // auto history = this->chat_engine->get_history(); // std::cout << "history: " << history.first << std::endl; this->auto_chat_engine->clear_context();