Skip to content

feat(server): log a 'Request done:' timing summary for every request (#841) #898

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
tawei-amd merged 2 commits into from
Oct 30, 2026
Merged

feat(server): log a 'Request done:' timing summary for every request (#841) #898

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
f8732a0
feat(server): log a 'Request done:' timing summary for every request,…
Oct 30, 2026
ca907ec
fix(server): also log the summary for non-streamed Ollama chat (#841)
Oct 30, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
30 changes: 29 additions & 1 deletion src/server/rest_handler.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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<double>(m.prefill_duration) / 1e9;
const double decode_s = static_cast<double>(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.
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -1175,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();
Expand Down Expand Up @@ -1656,6 +1680,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;
Expand Down Expand Up @@ -1739,6 +1764,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);
}

Expand Down Expand Up @@ -1987,6 +2013,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();
}
Expand Down Expand Up @@ -2041,6 +2068,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);
}
}
Expand Down
Loading