diff --git a/tools/server/server-common.cpp b/tools/server/server-common.cpp index 148b7ea6d..5ff7685bb 100644 --- a/tools/server/server-common.cpp +++ b/tools/server/server-common.cpp @@ -60,6 +60,33 @@ json format_error_response(const std::string & message, const enum error_type ty }; } +// +// server_slot_stats +// + +json server_slot_stats::to_json() const { + json base = { + {"cache_n", n_prompt_cached}, + + {"prompt_n", n_prompt_processed}, + {"prompt_ms", t_prompt_ms()}, + {"prompt_per_token_ms", t_prompt_per_token_ms()}, + {"prompt_per_second", n_prompt_tps()}, + + {"predicted_n", n_gen}, + {"predicted_ms", t_gen_ms()}, + {"predicted_per_token_ms", t_gen_per_token_ms()}, + {"predicted_per_second", n_gen_tps()}, + }; + + if (n_draft_tokens > 0) { + base["draft_n"] = n_draft_tokens; + base["draft_n_accepted"] = n_draft_accepted; + } + + return base; +} + // // random string / id // diff --git a/tools/server/server-common.h b/tools/server/server-common.h index 79607e288..7082abdd9 100644 --- a/tools/server/server-common.h +++ b/tools/server/server-common.h @@ -334,6 +334,160 @@ json format_response_rerank( std::vector & texts, int top_n); +// +// stats and metrics +// + +// shared between server_slot and server_task_result_* +struct server_slot_stats { + uint64_t n_prompt_cached = 0; + uint64_t n_prompt_processed = 0; + uint64_t n_gen = 0; + + // speculative decoding stats + // note: the per-position breakdown lives in server_slot, it is not needed in a task result + uint64_t n_draft_tokens = 0; + uint64_t n_draft_accepted = 0; + uint64_t n_draft_verif_steps = 0; + + // these are absolute timestamps (in us) + // note: must be signed - they are subtracted before the later ones are set + int64_t t_start = 0; + int64_t t_prompt_last = 0; + int64_t t_gen_last = 0; + + // can only move one direction: start -> prompt -> gen + void update_prompt_start() { + GGML_ASSERT(t_start == 0); + t_start = ggml_time_us(); + } + void set_prompt_last(int64_t t_us) { + GGML_ASSERT(t_start > 0); + t_prompt_last = t_us; + } + void update_prompt_last() { + set_prompt_last(ggml_time_us()); + } + void update_gen_last() { + GGML_ASSERT(t_prompt_last > 0); + t_gen_last = ggml_time_us(); + } + + // these are time durations + int64_t t_elapsed_us() const { + return ggml_time_us() - t_start; + } + double t_prompt_ms() const { + if (t_prompt_last == 0) { + return 0.0; // the prompt is not processed yet + } + return (t_prompt_last - t_start) / 1000.0; + } + int64_t t_gen_us() const { + if (t_gen_last == 0) { + return 0; // the generation is not started yet + } + // clamp to 1 us, the first token can land in the same us as t_prompt_last + return std::max(1, t_gen_last - t_prompt_last); + } + double t_gen_ms() const { + return t_gen_us() / 1000.0; + } + + // number of decode steps spent on generation + // the first token is free, it comes from the logits of the last prompt batch + uint64_t n_gen_steps() const { + return n_gen > 0 ? n_gen - 1 : 0; + } + + // other derived metrics + // note: all of them return 0.0 if the divisor is not known yet + double t_prompt_per_token_ms() const { + return n_prompt_processed > 0 ? t_prompt_ms() / n_prompt_processed : 0.0; + } + double t_gen_per_token_ms() const { + return n_gen_steps() > 0 ? t_gen_ms() / n_gen_steps() : 0.0; + } + double n_prompt_tps() const { + const double t_ms = t_prompt_ms(); + return t_ms > 0.0 ? 1e3 / t_ms * n_prompt_processed : 0.0; + } + double n_gen_tps() const { + const double t_ms = t_gen_ms(); + return t_ms > 0.0 ? 1e3 / t_ms * n_gen_steps() : 0.0; + } + + // false if the slot never started, i.e. the task result carries no stats + bool is_set() const { + return t_start > 0; + } + + json to_json() const; +}; + +// shared between server_context_impl and server_task_result_* +// unlike server_slot_stats, server_metrics is server-global and cumulative, not tied to a slot +struct server_metrics { + int64_t t_start = 0; + + struct bucket { + uint64_t count = 0; // number of tokens + uint64_t steps = 0; // number of decode steps, + // this excludes first generated token (logits from prompt batch) + uint64_t time = 0; // in microseconds + + // the rate uses the decode steps, so that "free" tokens do not inflate it + double n_per_second() const { + return time > 0 ? (double) steps / (double) time * 1e6 : 0.0; + } + + void add(uint64_t n, uint64_t n_steps, uint64_t t_us) { + count += n; + steps += n_steps; + time += t_us; + } + }; + + // these are reset by reset_bucket(), only the rate is read from them + bucket prompt_bucket; + bucket predict_bucket; + + // metrics below are cumulative since the server started + bucket prompt; // only processed tokens, cached ones are counted separately below + bucket predict; + + // tokens reused from the cache need no decode, so they only have a count + uint64_t n_prompt_cached = 0; + + uint64_t n_tokens_max = 0; + + uint64_t n_decode = 0; + uint64_t n_busy_slots = 0; + + uint64_t n_draft_tokens = 0; // Total draft tokens generated + uint64_t n_draft_accepted = 0; // Draft tokens actually accepted + uint64_t n_draft_verif_steps = 0; // Total draft token verification steps by the target model + std::vector n_accepted_per_pos; // Accepted tokens per draft position + + void init() { + t_start = ggml_time_us(); + } + + void reset_bucket() { + prompt_bucket = {}; + predict_bucket = {}; + } + + void add_prompt(uint64_t n_tokens, uint64_t t_us) { + prompt .add(n_tokens, n_tokens, t_us); + prompt_bucket.add(n_tokens, n_tokens, t_us); + } + + void add_prompt_cached(uint64_t n_tokens) { + n_prompt_cached += n_tokens; + } +}; + // // other utils // diff --git a/tools/server/server-context.cpp b/tools/server/server-context.cpp index 8b2ae72a4..f02a1da68 100644 --- a/tools/server/server-context.cpp +++ b/tools/server/server-context.cpp @@ -74,6 +74,7 @@ struct server_batch { llama_token token; llama_pos pos; bool output; + bool is_prompt; // for stats tracking }; std::vector tokens; int32_t n_tokens_alloc = 0; @@ -109,22 +110,22 @@ struct server_batch { tokens.reserve(n_tokens_alloc); } - bool add(int32_t id_slot, llama_token token, llama_pos pos, bool output) { + bool add(int32_t id_slot, llama_token token, llama_pos pos, bool output, bool is_prompt) { GGML_ASSERT(!has_embd); // cannot mix tokens + embd in same batch GGML_ASSERT(batch.pos != nullptr); if ((int32_t)tokens.size() >= n_tokens_alloc) { return false; } - tokens.push_back({ id_slot, token, pos, output }); + tokens.push_back({ id_slot, token, pos, output, is_prompt }); return true; } - bool add(int32_t id_slot, const std::vector & embd_in, llama_pos pos, bool output) { + bool add(int32_t id_slot, const std::vector & embd_in, llama_pos pos, bool output, bool is_prompt) { GGML_ASSERT(batch.pos != nullptr); if ((int32_t)tokens.size() >= n_tokens_alloc) { return false; } - tokens.push_back({ id_slot, LLAMA_TOKEN_NULL, pos, output }); + tokens.push_back({ id_slot, LLAMA_TOKEN_NULL, pos, output, is_prompt }); has_embd = true; embd.insert(embd.end(), embd_in.begin(), embd_in.end()); return true; @@ -222,20 +223,19 @@ struct server_slot { int64_t t_last_used = -1; // generation props - int32_t n_ctx = 0; // context size per slot - int32_t n_keep = 0; - int32_t n_decoded = 0; - int32_t n_remaining = -1; - int32_t i_batch = -1; + int32_t n_ctx = 0; // context size per slot + int32_t n_keep = 0; + int32_t i_batch = -1; - int32_t n_prompt_tokens_cache = 0; - int32_t n_prompt_tokens_processed = 0; + // effective generation limit for the current task, -1 means unlimited + int32_t n_predict_max = -1; size_t last_nl_pos = 0; std::string generated_text; std::string debug_generated_text; llama_tokens generated_tokens; + size_t n_sent_text = 0; // number of sent text character (i.e. handle partial UTF-8 on streaming) std::vector generated_token_probs; @@ -309,33 +309,24 @@ struct server_slot { // corresponding to one token position (size = n_embd) std::vector inp_embd; - // stats - size_t n_sent_text = 0; // number of sent text character + server_slot_stats stats; - // TODO @ngxson : move all metrics to a sub-struct for clarity - int64_t t_start_process_prompt; - int64_t t_start_generation; + // accepted tokens per draft position + // not in server_slot_stats to avoid copying to every task result + std::vector n_accepted_per_pos; + + std::function callback_on_release; + std::function callback_on_reset; // called before reset() + + // this is for printing timings with slot progress, not part of metrics int64_t t_print_last = 0; - int32_t n_decoded_last = 0; - - double t_prompt_processing = 0.0; // ms - double t_token_generation = 0.0; // ms - - std::function callback_on_release; - - // Speculative decoding stats - int32_t n_draft_total = 0; // Total draft tokens generated - int32_t n_draft_accepted = 0; // Draft tokens actually accepted - int32_t n_draft_verif_steps = 0; // Total draft token verification steps by the target model - std::vector n_accepted_per_pos; // Accepted tokens per draft position + int32_t n_gen_last = 0; void reset() { SLT_DBG(*this, "%s", "\n"); spec_is_replay = false; - n_prompt_tokens_cache = 0; - last_nl_pos = 0; generated_text = ""; has_new_line = false; @@ -353,15 +344,15 @@ struct server_slot { generated_token_probs.clear(); json_schema = json(); - // clear speculative decoding stats - n_draft_total = 0; - n_draft_accepted = 0; - n_draft_verif_steps = 0; - n_accepted_per_pos.clear(); - task_prev = std::move(task); task.reset(); + // note: callback_on_reset() must have run before this, see release() + stats = {}; + n_accepted_per_pos.clear(); + + n_predict_max = -1; + llama_set_sampler(ctx_tgt, id, nullptr); // clear alora start @@ -419,22 +410,13 @@ struct server_slot { && are_lora_equal(lora, other_slot.lora); } - bool has_budget(const common_params & global_params) { - GGML_ASSERT(task); + // returns -1 if the generation is limitless + int32_t n_remaining() const { + return n_predict_max == -1 ? -1 : n_predict_max - (int32_t) stats.n_gen; + } - if (task->params.n_predict == -1 && global_params.n_predict == -1) { - return true; // limitless - } - - n_remaining = -1; - - if (task->params.n_predict != -1) { - n_remaining = task->params.n_predict - n_decoded; - } else if (global_params.n_predict != -1) { - n_remaining = global_params.n_predict - n_decoded; - } - - return n_remaining > 0; // no budget + bool has_budget() const { + return n_predict_max == -1 || n_remaining() > 0; } bool is_processing() const { @@ -466,8 +448,8 @@ struct server_slot { // also, need to leave space for 1 extra token to allow context shifts int n_draft_max = n_ctx - prompt.n_tokens() - 2; - if (n_remaining > 0) { - n_draft_max = std::min(n_draft_max, n_remaining - 1); + if (n_remaining() > 0) { + n_draft_max = std::min(n_draft_max, n_remaining() - 1); } SLT_DBG(*this, "max possible draft: %d\n", n_draft_max); @@ -483,9 +465,9 @@ struct server_slot { i_batch = batch.size(); if (!inp_embd.empty()) { - add_ok &= batch.add(id, inp_embd, prompt.tokens.pos_next(), true); + add_ok &= batch.add(id, inp_embd, prompt.tokens.pos_next(), true, false); } else { - add_ok &= batch.add(id, sampled, prompt.tokens.pos_next(), true); + add_ok &= batch.add(id, sampled, prompt.tokens.pos_next(), true, false); } SLT_DBG(*this, "slot decode token, id=%d, n_ctx = %d, n_tokens = %d, truncated = %d\n", @@ -503,9 +485,9 @@ struct server_slot { auto pos0 = prompt.tokens.pos_next(); - add_ok &= batch.add(id, sampled, pos0++, true); + add_ok &= batch.add(id, sampled, pos0++, true, false); for (auto token : spec_draft) { - add_ok &= batch.add(this->id, token, pos0++, true); + add_ok &= batch.add(this->id, token, pos0++, true, false); } } @@ -521,8 +503,7 @@ struct server_slot { SLT_INF(*this, "stop processing: n_tokens = %d, truncated = %d\n", prompt.n_tokens(), truncated); - t_last_used = ggml_time_us(); - t_token_generation = (ggml_time_us() - t_start_generation) / 1e3; + t_last_used = ggml_time_us(); state = SLOT_STATE_IDLE; @@ -531,35 +512,14 @@ struct server_slot { prompt_clear(); } + callback_on_reset(*this); + reset(); callback_on_release(id); } } - result_timings get_timings() const { - result_timings timings; - timings.cache_n = n_prompt_tokens_cache; - - timings.prompt_n = n_prompt_tokens_processed; - timings.prompt_ms = t_prompt_processing; - timings.prompt_per_token_ms = t_prompt_processing / n_prompt_tokens_processed; - timings.prompt_per_second = 1e3 / t_prompt_processing * n_prompt_tokens_processed; - - timings.predicted_n = n_decoded; - timings.predicted_ms = t_token_generation; - timings.predicted_per_token_ms = t_token_generation / n_decoded; - timings.predicted_per_second = 1e3 / t_token_generation * n_decoded; - - // Add speculative metrics - if (n_draft_total > 0) { - timings.draft_n = n_draft_total; - timings.draft_n_accepted = n_draft_accepted; - } - - return timings; - } - size_t find_stopping_strings(const std::string & text, const size_t last_token_size, bool is_full_stop) { GGML_ASSERT(task); @@ -592,7 +552,7 @@ struct server_slot { } void print_timings_tg() { - if (n_decoded < 100) { + if (stats.n_gen < 100) { return; } @@ -602,50 +562,59 @@ struct server_slot { return; } - const double n_gen_second = 1e3 / (t_token_generation) * (n_decoded); - const double n_gen_second_win = 1e6 / (t_now - t_print_last) * (n_decoded - n_decoded_last); + const double n_gen_second = stats.n_gen_tps(); + const double n_gen_second_win = 1e6 / (t_now - t_print_last) * (stats.n_gen - n_gen_last); t_print_last = t_now; - n_decoded_last = n_decoded; + n_gen_last = stats.n_gen; - SLT_INF(*this, "n_decoded = %6d, tg = %6.2f t/s, tg_3s = %6.2f t/s\n", n_decoded, n_gen_second, n_gen_second_win); + SLT_INF(*this, "n_gen = %6d, tg = %6.2f t/s, tg_3s = %6.2f t/s\n", (int) stats.n_gen, n_gen_second, n_gen_second_win); } void print_timings_pp() const { - const double n_prompt_second = 1e3 / t_prompt_processing * n_prompt_tokens_processed; - const double f_progress = (float) prompt.n_tokens() / task->n_tokens(); + const double t_prompt_total = stats.t_prompt_ms(); - if (t_prompt_processing < 3000.0) { + if (t_prompt_total < 3000.0) { return; } + const double n_prompt_second = stats.n_prompt_tps(); + const double f_progress = task->n_tokens() > 0 ? (double) prompt.n_tokens() / task->n_tokens() : 0.0; + SLT_INF(*this, "prompt processing, n_tokens = %6d, progress = %.2f, t = %6.2f s / %.2f tokens per second\n", - n_prompt_tokens_processed, f_progress, t_prompt_processing / 1e3, n_prompt_second); + (int) stats.n_prompt_processed, f_progress, t_prompt_total / 1e3, n_prompt_second); } void print_timings() const { - const double t_prompt = t_prompt_processing / n_prompt_tokens_processed; - const double n_prompt_second = 1e3 / t_prompt_processing * n_prompt_tokens_processed; + const double t_prompt_total = stats.t_prompt_ms(); + const double t_gen_total = stats.t_gen_ms(); - const double t_gen = t_token_generation / n_decoded; - const double n_gen_second = 1e3 / t_token_generation * n_decoded; + const double t_prompt = stats.t_prompt_per_token_ms(); + const double n_prompt_second = stats.n_prompt_tps(); + + const double t_gen = stats.t_gen_per_token_ms(); + const double n_gen_second = stats.n_gen_tps(); SLT_INF(*this, "prompt eval time = %10.2f ms / %5d tokens (%8.2f ms per token, %8.2f tokens per second)\n", - t_prompt_processing, n_prompt_tokens_processed, t_prompt, n_prompt_second); + t_prompt_total, (int) stats.n_prompt_processed, t_prompt, n_prompt_second); SLT_INF(*this, " eval time = %10.2f ms / %5d tokens (%8.2f ms per token, %8.2f tokens per second)\n", - t_token_generation, n_decoded, t_gen, n_gen_second); + t_gen_total, (int) stats.n_gen, t_gen, n_gen_second); SLT_INF(*this, " total time = %10.2f ms / %5d tokens\n", - t_prompt_processing + t_token_generation, n_prompt_tokens_processed + n_decoded); + t_prompt_total + t_gen_total, (int) (stats.n_prompt_processed + stats.n_gen)); SLT_INF(*this, " graphs reused = %10d\n", llama_perf_context(ctx_tgt).n_reused); + const int32_t n_draft_total = stats.n_draft_tokens; + const int32_t n_draft_accepted = stats.n_draft_accepted; + const int32_t n_draft_verif_steps = stats.n_draft_verif_steps; + if (n_draft_total > 0) { const float draft_ratio = (float) n_draft_accepted / n_draft_total; const double mean_acc_len = n_draft_verif_steps > 0 ? 1.0 + (double) n_draft_accepted / (double) n_draft_verif_steps : 1.0; @@ -685,15 +654,15 @@ struct server_slot { if (ptask) { res["id_task"] = ptask->id; res["n_prompt_tokens"] = (int32_t) prompt.tokens.size(); - res["n_prompt_tokens_processed"] = n_prompt_tokens_processed; - res["n_prompt_tokens_cache"] = n_prompt_tokens_cache; + res["n_prompt_tokens_processed"] = stats.n_prompt_processed; + res["n_prompt_tokens_cache"] = stats.n_prompt_cached; res["params"] = ptask->params.to_json(only_metrics); res["next_token"] = { { {"has_next_token", has_next_token}, {"has_new_line", has_new_line}, - {"n_remain", n_remaining}, - {"n_decoded", n_decoded}, + {"n_remain", n_remaining()}, + {"n_decoded", stats.n_gen}, } }; @@ -712,14 +681,9 @@ struct server_slot { mem.seq_rm(other.id, -1, -1); mem.seq_cp(id, other.id, -1, -1); - other.n_decoded = n_decoded; - other.n_remaining = n_remaining; - other.i_batch = i_batch; + other.i_batch = i_batch; - other.t_start_process_prompt = t_start_process_prompt; - other.t_prompt_processing = t_prompt_processing; - other.n_prompt_tokens_cache = n_prompt_tokens_cache; - other.n_prompt_tokens_processed = n_prompt_tokens_processed; + other.stats = stats; other.prompt = prompt.clone(); other.init_sampler(); @@ -816,84 +780,6 @@ struct server_slot { -// -// server_metrics -// - -struct server_metrics { - int64_t t_start = 0; - - uint64_t n_prompt_tokens_processed_total = 0; - uint64_t t_prompt_processing_total = 0; - uint64_t n_tokens_predicted_total = 0; - uint64_t t_tokens_generation_total = 0; - - uint64_t n_tokens_max = 0; - - uint64_t n_prompt_tokens_processed = 0; - uint64_t t_prompt_processing = 0; - - uint64_t n_tokens_predicted = 0; - uint64_t t_tokens_generation = 0; - - uint64_t n_decode_total = 0; - uint64_t n_busy_slots_total = 0; - - uint64_t n_draft_tokens_total = 0; - uint64_t n_draft_accepted_total = 0; - uint64_t n_draft_verif_steps_total = 0; - std::vector n_accepted_per_pos_total; - - void init() { - t_start = ggml_time_us(); - } - - void on_prompt_eval(const server_slot & slot) { - n_prompt_tokens_processed_total += slot.n_prompt_tokens_processed; - n_prompt_tokens_processed += slot.n_prompt_tokens_processed; - t_prompt_processing += slot.t_prompt_processing; - t_prompt_processing_total += slot.t_prompt_processing; - - n_tokens_max = std::max(n_tokens_max, (uint64_t) slot.prompt.n_tokens()); - } - - void on_prediction(const server_slot & slot) { - n_tokens_predicted_total += slot.n_decoded; - n_tokens_predicted += slot.n_decoded; - t_tokens_generation += slot.t_token_generation; - t_tokens_generation_total += slot.t_token_generation; - - n_draft_tokens_total += slot.n_draft_total; - n_draft_accepted_total += slot.n_draft_accepted; - n_draft_verif_steps_total += slot.n_draft_verif_steps; - - if (n_accepted_per_pos_total.size() < slot.n_accepted_per_pos.size()) { - n_accepted_per_pos_total.resize(slot.n_accepted_per_pos.size(), 0); - } - for (size_t i = 0; i < slot.n_accepted_per_pos.size(); i++) { - n_accepted_per_pos_total[i] += slot.n_accepted_per_pos[i]; - } - } - - void on_decoded(const std::vector & slots) { - n_decode_total++; - for (const auto & slot : slots) { - if (slot.is_processing()) { - n_busy_slots_total++; - } - n_tokens_max = std::max(n_tokens_max, (uint64_t) slot.prompt.n_tokens()); - } - } - - void reset_bucket() { - n_prompt_tokens_processed = 0; - t_prompt_processing = 0; - n_tokens_predicted = 0; - t_tokens_generation = 0; - } -}; - - // // server_context_impl (private implementation) // @@ -972,6 +858,12 @@ private: server_metrics metrics; + // queued prompt stats - llama_decode() is async, so the timing is only valid after a sync + // note: kept out of server_metrics, which is copied as-is into the task result + int64_t t_decode_start = 0; // start of the last submitted decode + int64_t t_prompt_start = 0; // start of the oldest queued prompt decode + uint64_t n_prompt_queued = 0; + json json_ui_settings = json::object(); // Necessary similarity of prompt for slot selection @@ -1369,6 +1261,13 @@ private: queue_tasks.pop_deferred_task(id_slot); }; + slot.callback_on_reset = [this](const server_slot & slot) { + // flush the generated token stats before reset() + if (slot.stats.n_gen > 0) { + metrics_on_prediction(slot); + } + }; + slot.reset(); } @@ -1846,6 +1745,9 @@ private: slot.smpl.reset(); } + // the per-request limit takes priority over the global one + slot.n_predict_max = task.params.n_predict != -1 ? task.params.n_predict : params_base.n_predict; + slot.task = std::make_unique(std::move(task)); slot.state = slot.task->is_child() @@ -1917,16 +1819,16 @@ private: slot.stop = STOP_TYPE_LIMIT; slot.has_next_token = false; - SLT_DBG(slot, "stopped due to running out of context capacity, prompt.n_tokens() = %d, task.n_tokens = %d, n_decoded = %d, n_ctx = %d\n", - slot.prompt.n_tokens(), slot.task->n_tokens(), slot.n_decoded, slot.n_ctx); + SLT_DBG(slot, "stopped due to running out of context capacity, prompt.n_tokens() = %d, task.n_tokens = %d, n_gen = %d, n_ctx = %d\n", + slot.prompt.n_tokens(), slot.task->n_tokens(), (int) slot.stats.n_gen, slot.n_ctx); } // check the limits - if (slot.n_decoded > 0 && slot.has_next_token && !slot.has_budget(params_base)) { + if (slot.stats.n_gen > 0 && slot.has_next_token && !slot.has_budget()) { slot.stop = STOP_TYPE_LIMIT; slot.has_next_token = false; - SLT_DBG(slot, "stopped by limit, n_decoded = %d, n_predict = %d\n", slot.n_decoded, slot.task->params.n_predict); + SLT_DBG(slot, "stopped by limit, n_gen = %d, n_predict = %d\n", (int) slot.stats.n_gen, slot.task->params.n_predict); } if (slot.has_new_line) { @@ -1950,7 +1852,7 @@ private: // cut the last line slot.generated_text.erase(pos, std::string::npos); - SLT_DBG(slot, "stopped by indentation limit, n_decoded = %d, n_indent = %d\n", slot.n_decoded, n_indent); + SLT_DBG(slot, "stopped by indentation limit, n_gen = %d, n_indent = %d\n", (int) slot.stats.n_gen, n_indent); } } @@ -1970,11 +1872,11 @@ private: slot.has_new_line = true; // if we have seen a new line, we stop after a certain time limit, but only upon another new line - if (slot.task->params.t_max_predict_ms > 0 && (ggml_time_us() - slot.t_start_generation > 1000.0f*slot.task->params.t_max_predict_ms)) { + if (slot.task->params.t_max_predict_ms > 0 && slot.stats.t_gen_ms() > slot.task->params.t_max_predict_ms) { slot.stop = STOP_TYPE_LIMIT; slot.has_next_token = false; - SLT_DBG(slot, "stopped by time limit, n_decoded = %d, t_max_predict_ms = %d ms\n", slot.n_decoded, (int) slot.task->params.t_max_predict_ms); + SLT_DBG(slot, "stopped by time limit, n_gen = %d, t_max_predict_ms = %d ms\n", (int) slot.stats.n_gen, (int) slot.task->params.t_max_predict_ms); } } @@ -1985,7 +1887,7 @@ private: SLT_DBG(slot, "%s", "stopped by EOS\n"); } - SLT_DBG(slot, "n_decoded = %d, n_remaining = %d, next token: %5d '%s'\n", slot.n_decoded, slot.n_remaining, result.tok, token_str.c_str()); + SLT_DBG(slot, "n_gen = %d, n_remaining = %d, next token: %5d '%s'\n", (int) slot.stats.n_gen, slot.n_remaining(), result.tok, token_str.c_str()); return slot.has_next_token; // continue } @@ -2081,9 +1983,9 @@ private: if (is_progress) { res->is_progress = true; res->progress.total = slot.task->n_tokens(); - res->progress.cache = slot.n_prompt_tokens_cache; + res->progress.cache = slot.stats.n_prompt_cached; res->progress.processed = slot.prompt.tokens.size(); - res->progress.time_ms = (ggml_time_us() - slot.t_start_process_prompt) / 1000; + res->progress.time_ms = slot.stats.t_elapsed_us() / 1000; } if (is_begin) { res->is_begin = true; @@ -2092,9 +1994,9 @@ private: res->tokens = { tkn.tok }; } - res->n_decoded = slot.n_decoded; + res->n_decoded = slot.stats.n_gen; res->n_prompt_tokens = slot.task->n_tokens(); - res->n_prompt_tokens_cache = slot.n_prompt_tokens_cache; + res->n_prompt_tokens_cache = slot.stats.n_prompt_cached; res->post_sampling_probs = slot.task->params.post_sampling_probs; res->verbose = slot.task->params.verbose; @@ -2109,7 +2011,7 @@ private: // populate timings if this is final response or timings_per_token is enabled if (slot.stop != STOP_TYPE_NONE || slot.task->params.timings_per_token) { - res->timings = slot.get_timings(); + res->stats = slot.stats; } queue_results.send(std::move(res)); @@ -2136,14 +2038,14 @@ private: res->content = std::move(slot.generated_text); res->tokens = std::move(slot.generated_tokens); } - res->timings = slot.get_timings(); + res->stats = slot.stats; res->prompt = slot.task->tokens.detokenize(ctx_tgt, true); res->response_fields = std::move(slot.task->params.response_fields); res->truncated = slot.truncated; - res->n_decoded = slot.n_decoded; + res->n_decoded = slot.stats.n_gen; res->n_prompt_tokens = slot.task->n_tokens(); - res->n_prompt_tokens_cache = slot.n_prompt_tokens_cache; + res->n_prompt_tokens_cache = slot.stats.n_prompt_cached; res->n_tokens_cached = slot.prompt.n_tokens(); res->has_new_line = slot.has_new_line; res->stopping_word = slot.stopping_word; @@ -2530,27 +2432,7 @@ private: res->n_idle_slots = n_idle_slots; res->n_processing_slots = n_processing_slots; res->n_tasks_deferred = queue_tasks.queue_tasks_deferred_size(); - res->t_start = metrics.t_start; - - res->n_prompt_tokens_processed_total = metrics.n_prompt_tokens_processed_total; - res->t_prompt_processing_total = metrics.t_prompt_processing_total; - res->n_tokens_predicted_total = metrics.n_tokens_predicted_total; - res->t_tokens_generation_total = metrics.t_tokens_generation_total; - - res->n_tokens_max = metrics.n_tokens_max; - - res->n_prompt_tokens_processed = metrics.n_prompt_tokens_processed; - res->t_prompt_processing = metrics.t_prompt_processing; - res->n_tokens_predicted = metrics.n_tokens_predicted; - res->t_tokens_generation = metrics.t_tokens_generation; - - res->n_decode_total = metrics.n_decode_total; - res->n_busy_slots_total = metrics.n_busy_slots_total; - - res->n_draft_tokens_total = metrics.n_draft_tokens_total; - res->n_draft_accepted_total = metrics.n_draft_accepted_total; - res->n_draft_verif_steps_total = metrics.n_draft_verif_steps_total; - res->n_accepted_per_pos_total = metrics.n_accepted_per_pos_total; + res->metrics = metrics; if (task.metrics_reset_bucket) { metrics.reset_bucket(); @@ -2830,6 +2712,9 @@ private: if (all_idle) { SRV_TRC("%s", "all slots are idle\n"); + + metrics_flush_idle(); + return; // skip further processing } else { @@ -2848,6 +2733,9 @@ private: } catch (const std::exception & e) { SRV_ERR("pre_decode() failed: %s\n", e.what()); abort_all_slots("pre_decode() failed: " + std::string(e.what())); + + // the batch is half-built and not rendered, skip now to avoid UB + return; } GGML_ASSERT(batch.slot_batched || batch.size() == 0); @@ -3057,7 +2945,7 @@ private: auto & draft = slot.spec_draft; auto & ckpt = slot.spec_ckpt; - slot.n_draft_total += draft.size(); + slot.stats.n_draft_tokens += draft.size(); // TODO: avoid restoring the draft context and re-evaluating the drafted tokens when not needed [TAG_SPEC_AVOID_DRAFT_REEVAL] const bool use_ckpt_dft = ctx_dft_seq_rm_type == COMMON_CONTEXT_SEQ_RM_TYPE_FULL; @@ -3145,8 +3033,7 @@ private: // TODO: maybe move branch to outside of this loop in the future if (slot.state == SLOT_STATE_STARTED) { - slot.t_start_process_prompt = ggml_time_us(); - slot.t_start_generation = 0; + slot.stats.update_prompt_start(); slot.state = SLOT_STATE_PROCESSING_PROMPT; @@ -3412,8 +3299,10 @@ private: SLT_WRN(slot, "n_past was set to %d\n", n_past); } - slot.n_prompt_tokens_cache = n_past; - slot.n_prompt_tokens_processed = 0; + slot.stats.n_prompt_cached = n_past; + slot.stats.n_prompt_processed = 0; + + metrics.add_prompt_cached(n_past); slot.prompt.tokens.keep_first(n_past); @@ -3436,8 +3325,8 @@ private: } } - const int64_t t_now = ggml_time_us(); - slot.t_prompt_processing = (t_now - slot.t_start_process_prompt) / 1e3; + // note: the prompt timing is advanced in post_decode(), so it does not cover + // the tokens added to the batch below slot.print_timings_pp(); // truncate any tokens that are beyond n_past for this slot @@ -3478,7 +3367,7 @@ private: bool has_mtmd = false; - // check if we should process the image + // check if we should process the mtmd chunk while (true) { auto cur_token_idx = slot.prompt.n_tokens(); if ( @@ -3488,19 +3377,25 @@ private: break; } - // process the image + // process the mtmd chunk + // note: it submits its own decode, potentially be async + // so the timing is queued and flushed on the next sync + metrics_pre_decode(); + size_t n_tokens_out = 0; int32_t res = slot.process_mtmd_chunk(cur_token_idx, n_tokens_out); if (res != 0) { - SLT_ERR(slot, "failed to process image, res = %d\n", res); - send_error(slot, "failed to process image", ERROR_TYPE_SERVER); + SLT_ERR(slot, "failed to process mtmd chunk, res = %d\n", res); + send_error(slot, "failed to process mtmd chunk", ERROR_TYPE_SERVER); slot.release(); - continue; + return; // the slot is done, skip it entirely } - slot.n_prompt_tokens_processed += n_tokens_out; + metrics_queue_prompt(n_tokens_out); + slot.stats.n_prompt_processed += n_tokens_out; + slot.stats.update_prompt_last(); - // add the image chunk to cache + // add the mtmd chunk to cache { const auto & chunk = input_tokens.find_chunk(cur_token_idx); slot.prompt.tokens.push_back(chunk.get()); // copy @@ -3533,12 +3428,11 @@ private: // streaming hook can mirror t_h_nextn into ctx_dft. add_ok &= batch.add(slot.id, cur_tok, - slot.prompt.tokens.pos_next(), - slot.need_embd()); + /* pos = */ slot.prompt.tokens.pos_next(), + /* output = */ slot.need_embd(), + /* is_prompt = */ true); slot.prompt.tokens.push_back(cur_tok); - slot.n_prompt_tokens_processed++; - // break at the last user message, or at user messages at least min step past the last checkpoint if (do_checkpoint && spans.is_user_start(slot.prompt.n_tokens())) { const auto pos = slot.prompt.n_tokens(); @@ -3590,8 +3484,8 @@ private: // extract the logits only for the last token batch.set_output(batch.size() - 1, true); - slot.n_decoded = 0; - slot.i_batch = batch.size() - 1; + slot.stats.n_gen = 0; + slot.i_batch = batch.size() - 1; slot.init_sampler(); } else { @@ -3640,6 +3534,8 @@ private: bool decode(int32_t & n_batch, int32_t off, llama_batch & batch_view) { SRV_DBG("n_batch (effective) = %d, off = %d\n", n_batch, off); + metrics_pre_decode(); + if (batch.size() == 0) { SRV_WRN("%s", "no tokens to decode\n"); @@ -3663,8 +3559,6 @@ private: const int ret = llama_decode(ctx_tgt, batch_view); - metrics.on_decoded(slots); - if (ret != 0) { { std::string err; @@ -3713,6 +3607,9 @@ private: SRV_WRN("failed to find free space in the KV cache, retrying with smaller batch size, off = %d, n_batch = %d, ret = %d\n", off, n_batch, ret); return false; // retry with the updated n_batch + } else { + // success, apply batch metrics + metrics_post_decode(off, batch_view.n_tokens); } // TODO: avoid restoring the draft context and re-evaluating the drafted tokens when not needed [TAG_SPEC_AVOID_DRAFT_REEVAL] @@ -3833,17 +3730,15 @@ private: // here we have synchronized the llama_context (due to the sampling above), so we can do time measurement const int64_t t_now = ggml_time_us(); - slot.n_decoded += 1; + slot.stats.n_gen += 1; - if (slot.n_decoded == 1) { - slot.t_start_generation = t_now; + if (slot.stats.n_gen == 1) { + slot.stats.update_prompt_last(); slot.t_print_last = t_now; - slot.n_decoded_last = 0; - slot.t_prompt_processing = (slot.t_start_generation - slot.t_start_process_prompt) / 1e3; - metrics.on_prompt_eval(slot); + slot.n_gen_last = 0; } - slot.t_token_generation = std::max(1, t_now - slot.t_start_generation) / 1e3; + slot.stats.update_gen_last(); completion_token_output result; result.tok = id; @@ -3858,7 +3753,6 @@ private: // release slot because of stop condition slot.print_timings(); send_final_response(slot); - metrics.on_prediction(slot); slot.release(); return; @@ -3934,8 +3828,6 @@ private: slot.spec_draft = std::move(accepted); } - const int64_t t_now = ggml_time_us(); - const auto ids = std::move(slot.spec_draft); size_t n_accepted = ids.size() - 1; @@ -3944,17 +3836,18 @@ private: } slot.spec_is_replay = false; - slot.t_token_generation = std::max(1, t_now - slot.t_start_generation) / 1e3; + slot.stats.update_gen_last(); // update how many tokens out of those tested were accepted - slot.n_draft_accepted += n_accepted; - slot.n_draft_verif_steps += 1; + slot.stats.n_draft_accepted += n_accepted; + slot.stats.n_draft_verif_steps += 1; - if (slot.n_accepted_per_pos.empty()) { - slot.n_accepted_per_pos.resize(common_speculative_n_max(¶ms_base.speculative), 0); + auto & n_accepted_per_pos = slot.n_accepted_per_pos; + if (n_accepted_per_pos.empty()) { + n_accepted_per_pos.resize(common_speculative_n_max(¶ms_base.speculative), 0); } - for (size_t i = 0; i < n_accepted && i < slot.n_accepted_per_pos.size(); ++i) { - slot.n_accepted_per_pos[i]++; + for (size_t i = 0; i < n_accepted && i < n_accepted_per_pos.size(); ++i) { + n_accepted_per_pos[i]++; } // add accepted tokens to the prompt @@ -3975,12 +3868,11 @@ private: // TODO: set result.probs - slot.n_decoded += 1; + slot.stats.n_gen += 1; if (!process_token(result, slot)) { slot.print_timings(); send_final_response(slot); - metrics.on_prediction(slot); slot.release(); return; @@ -4000,6 +3892,121 @@ private: server_response_reader get_response_reader() { return server_response_reader(queue_tasks, queue_results, HTTP_POLLING_SECONDS); } + + // + // metrics helpers + // + + // call before submitting a decode, so that the queued prompt stats can be timed + void metrics_pre_decode() { + t_decode_start = ggml_time_us(); + } + + // the batch is submitted, but its compute may not be done yet + void metrics_queue_prompt(uint64_t n_tokens) { + if (n_tokens == 0) { + return; + } + if (n_prompt_queued == 0) { + t_prompt_start = t_decode_start; + } + n_prompt_queued += n_tokens; + } + + // call only after the context is synchronized, otherwise the time is meaningless + void metrics_flush_prompt() { + if (n_prompt_queued == 0) { + return; + } + metrics.add_prompt(n_prompt_queued, ggml_time_us() - t_prompt_start); + n_prompt_queued = 0; + } + + void metrics_post_decode(int32_t off, int32_t n_tokens) { + metrics.n_decode++; + for (const auto & slot : slots) { + if (slot.is_processing()) { + metrics.n_busy_slots++; + } + metrics.n_tokens_max = std::max(metrics.n_tokens_max, (uint64_t) slot.prompt.n_tokens()); + } + + // apply enqueued prompt tokens stats + // note: a slot can be released before we get here, which clears its stats + // the tokens were still computed, counted in the global metrics, not in slot + uint64_t n_prompt_tokens = 0; + bool has_output = false; + + for (int i = off; i < off + n_tokens; ++i) { + const auto & t = batch.tokens[i]; + + has_output |= t.output; + + if (!t.is_prompt) { + continue; // generated tokens are handled after sampling + } + + n_prompt_tokens++; + + auto & slot = slots[t.id_slot]; + if (slot.stats.is_set()) { + slot.stats.n_prompt_processed++; + } + } + + metrics_queue_prompt(n_prompt_tokens); + + if (has_output) { + // sync if we have at least one output in batch + // so that we can calculate the timings correctly + llama_synchronize(ctx_tgt); + metrics_flush_prompt(); + } + + // advance the prompt timing of the slots that had tokens in this batch + // note: a second pass, it must run after the sync above to reflect the compute + const int64_t t_now = ggml_time_us(); + for (int i = off; i < off + n_tokens; ++i) { + const auto & t = batch.tokens[i]; + auto & slot = slots[t.id_slot]; + if (t.is_prompt && slot.stats.is_set()) { + slot.stats.set_prompt_last(t_now); + } + } + } + + // flush any queued prompt metrics if all slots are now idle + void metrics_flush_idle() { + if (n_prompt_queued == 0) { + return; + } + + llama_synchronize(ctx_tgt); + metrics_flush_prompt(); + } + + void metrics_on_prediction(const server_slot & slot) { + const uint64_t t_us = slot.stats.t_gen_us(); + const uint64_t n = slot.stats.n_gen; + const uint64_t n_steps = slot.stats.n_gen_steps(); + + metrics.predict .add(n, n_steps, t_us); + metrics.predict_bucket.add(n, n_steps, t_us); + + metrics.n_draft_tokens += slot.stats.n_draft_tokens; + metrics.n_draft_accepted += slot.stats.n_draft_accepted; + metrics.n_draft_verif_steps += slot.stats.n_draft_verif_steps; + + auto & dst = metrics.n_accepted_per_pos; + const auto & src = slot.n_accepted_per_pos; + + if (dst.size() < src.size()) { + dst.resize(src.size(), 0); + } + for (size_t i = 0; i < src.size(); i++) { + dst[i] += src[i]; + } + } }; // @@ -4419,6 +4426,8 @@ void server_routes::init_routes() { { server_task task(SERVER_TASK_TYPE_METRICS); task.id = res->rd.get_new_id(); + // the gauges are averaged over the window between two scrapes + task.metrics_reset_bucket = true; res->rd.post_task(std::move(task), true); // high-priority task } @@ -4435,104 +4444,13 @@ void server_routes::init_routes() { return res; } - // TODO: get rid of this dynamic_cast auto res_task = dynamic_cast(result.get()); GGML_ASSERT(res_task != nullptr); - // metrics definition: https://prometheus.io/docs/practices/naming/#metric-names - json all_metrics_def = json { - {"counter", {{ - {"name", "prompt_tokens_total"}, - {"help", "Number of prompt tokens processed."}, - {"value", (uint64_t) res_task->n_prompt_tokens_processed_total} - }, { - {"name", "prompt_seconds_total"}, - {"help", "Prompt process time"}, - {"value", (uint64_t) res_task->t_prompt_processing_total / 1.e3} - }, { - {"name", "tokens_predicted_total"}, - {"help", "Number of generation tokens processed."}, - {"value", (uint64_t) res_task->n_tokens_predicted_total} - }, { - {"name", "tokens_predicted_seconds_total"}, - {"help", "Predict process time"}, - {"value", (uint64_t) res_task->t_tokens_generation_total / 1.e3} - }, { - {"name", "n_decode_total"}, - {"help", "Total number of llama_decode() calls"}, - {"value", res_task->n_decode_total} - }, { - {"name", "n_tokens_max"}, - {"help", "Largest observed n_tokens."}, - {"value", res_task->n_tokens_max} - }, { - {"name", "spec_decode_num_draft_tokens_total"}, - {"help", "Total draft tokens generated"}, - {"value", res_task->n_draft_tokens_total} - }, { - {"name", "spec_decode_num_accepted_tokens_total"}, - {"help", "Total draft tokens accepted by the target model"}, - {"value", res_task->n_draft_accepted_total} - }, { - {"name", "spec_decode_num_drafts_total"}, - {"help", "Total speculative decoding verification steps"}, - {"value", res_task->n_draft_verif_steps_total} - }}}, - {"gauge", {{ - {"name", "prompt_tokens_seconds"}, - {"help", "Average prompt throughput in tokens/s."}, - {"value", res_task->n_prompt_tokens_processed ? 1.e3 / res_task->t_prompt_processing * res_task->n_prompt_tokens_processed : 0.} - },{ - {"name", "predicted_tokens_seconds"}, - {"help", "Average generation throughput in tokens/s."}, - {"value", res_task->n_tokens_predicted ? 1.e3 / res_task->t_tokens_generation * res_task->n_tokens_predicted : 0.} - },{ - {"name", "requests_processing"}, - {"help", "Number of requests processing."}, - {"value", (uint64_t) res_task->n_processing_slots} - },{ - {"name", "requests_deferred"}, - {"help", "Number of requests deferred."}, - {"value", (uint64_t) res_task->n_tasks_deferred} - },{ - {"name", "n_busy_slots_per_decode"}, - {"help", "Average number of busy slots per llama_decode() call"}, - {"value", (float) res_task->n_busy_slots_total / std::max((float) res_task->n_decode_total, 1.f)} - }}} - }; - - std::stringstream prometheus; - - for (const auto & el : all_metrics_def.items()) { - const auto & type = el.key(); - const auto & metrics_def = el.value(); - - for (const auto & metric_def : metrics_def) { - const std::string name = metric_def.at("name"); - const std::string help = metric_def.at("help"); - - auto value = json_value(metric_def, "value", 0.); - prometheus << "# HELP llamacpp:" << name << " " << help << "\n" - << "# TYPE llamacpp:" << name << " " << type << "\n" - << "llamacpp:" << name << " " << value << "\n"; - } - } - - // labeled counter: one time series per draft position - if (!res_task->n_accepted_per_pos_total.empty()) { - prometheus << "# HELP llamacpp:spec_decode_num_accepted_tokens_per_pos_total" - " Accepted tokens per draft position\n" - << "# TYPE llamacpp:spec_decode_num_accepted_tokens_per_pos_total counter\n"; - for (size_t i = 0; i < res_task->n_accepted_per_pos_total.size(); i++) { - prometheus << "llamacpp:spec_decode_num_accepted_tokens_per_pos_total{position=\"" - << i << "\"} " << res_task->n_accepted_per_pos_total[i] << "\n"; - } - } - - res->headers["Process-Start-Time-Unix"] = std::to_string(res_task->t_start); + res->headers["Process-Start-Time-Unix"] = std::to_string(res_task->metrics.t_start); res->content_type = "text/plain; version=0.0.4"; res->status = 200; - res->data = prometheus.str(); + res->data = res_task->to_metrics(); return res; }; @@ -4563,7 +4481,6 @@ void server_routes::init_routes() { return res; } - // TODO: get rid of this dynamic_cast auto * res_task = dynamic_cast(result.get()); GGML_ASSERT(res_task != nullptr); @@ -4575,7 +4492,7 @@ void server_routes::init_routes() { } } - res->ok(res_task->slots_data); + res->ok(res_task->to_json()); return res; }; diff --git a/tools/server/server-task.cpp b/tools/server/server-task.cpp index 1ee677553..64afbc5ed 100644 --- a/tools/server/server-task.cpp +++ b/tools/server/server-task.cpp @@ -10,6 +10,8 @@ #include "speculative.h" #include "server-common.h" +#include + using json = nlohmann::ordered_json; // @@ -236,34 +238,6 @@ common_chat_msg task_result_state::update_chat_msg( return chat_msg; } -// - -// result_timings -// - -json result_timings::to_json() const { - json base = { - {"cache_n", cache_n}, - - {"prompt_n", prompt_n}, - {"prompt_ms", prompt_ms}, - {"prompt_per_token_ms", prompt_per_token_ms}, - {"prompt_per_second", prompt_per_second}, - - {"predicted_n", predicted_n}, - {"predicted_ms", predicted_ms}, - {"predicted_per_token_ms", predicted_per_token_ms}, - {"predicted_per_second", predicted_per_second}, - }; - - if (draft_n > 0) { - base["draft_n"] = draft_n; - base["draft_n_accepted"] = draft_n_accepted; - } - - return base; -} - // // result_prompt_progress // @@ -382,7 +356,7 @@ json server_task_result_cmpl_final::to_json_non_oaicompat() { {"stop_type", stop_type_to_str(stop)}, {"stopping_word", stopping_word}, {"tokens_cached", n_tokens_cached}, - {"timings", timings.to_json()}, + {"timings", stats.to_json()}, }; if (!stream && !probs_output.empty()) { res["completion_probabilities"] = completion_token_output::probs_vector_to_json(probs_output, post_sampling_probs); @@ -432,8 +406,8 @@ json server_task_result_cmpl_final::to_json_oaicompat() { if (verbose) { res["__verbose"] = to_json_non_oaicompat(); } - if (timings.prompt_n >= 0) { - res.push_back({"timings", timings.to_json()}); + if (stats.is_set()) { + res.push_back({"timings", stats.to_json()}); } return res; @@ -480,8 +454,8 @@ json server_task_result_cmpl_final::to_json_oaicompat_chat() { if (verbose) { res["__verbose"] = to_json_non_oaicompat(); } - if (timings.prompt_n >= 0) { - res.push_back({"timings", timings.to_json()}); + if (stats.is_set()) { + res.push_back({"timings", stats.to_json()}); } return res; @@ -541,8 +515,8 @@ json server_task_result_cmpl_final::to_json_oaicompat_chat_stream() { }); } - if (timings.prompt_n >= 0) { - deltas.back().push_back({"timings", timings.to_json()}); + if (stats.is_set()) { + deltas.back().push_back({"timings", stats.to_json()}); } // extra fields for debugging purposes @@ -734,8 +708,8 @@ json server_task_result_cmpl_final::to_json_oaicompat_resp_stream() { }} }); - if (timings.prompt_n >= 0) { - server_sent_events.back().at("data").push_back({"timings", timings.to_json()}); + if (stats.is_set()) { + server_sent_events.back().at("data").push_back({"timings", stats.to_json()}); } return server_sent_events; @@ -1086,8 +1060,8 @@ json server_task_result_cmpl_partial::to_json_non_oaicompat() { {"tokens_evaluated", n_prompt_tokens}, }; // populate the timings object when needed (usually for the last response or with timings_per_token enabled) - if (timings.prompt_n > 0) { - res.push_back({"timings", timings.to_json()}); + if (stats.is_set()) { + res.push_back({"timings", stats.to_json()}); } if (is_progress) { res.push_back({"prompt_progress", progress.to_json()}); @@ -1126,8 +1100,8 @@ json server_task_result_cmpl_partial::to_json_oaicompat() { if (verbose) { res["__verbose"] = to_json_non_oaicompat(); } - if (timings.prompt_n >= 0) { - res.push_back({"timings", timings.to_json()}); + if (stats.is_set()) { + res.push_back({"timings", stats.to_json()}); } if (is_progress) { res.push_back({"prompt_progress", progress.to_json()}); @@ -1180,8 +1154,8 @@ json server_task_result_cmpl_partial::to_json_oaicompat_chat() { }; } - if (timings.prompt_n >= 0) { - last_json.push_back({"timings", timings.to_json()}); + if (stats.is_set()) { + last_json.push_back({"timings", stats.to_json()}); } if (is_progress) { last_json.push_back({"prompt_progress", progress.to_json()}); @@ -1330,8 +1304,8 @@ json server_task_result_cmpl_partial::to_json_oaicompat_resp() { if (!events.empty()) { json & data = events.back().at("data"); - if (timings.prompt_n >= 0) { - data.push_back({"timings", timings.to_json()}); + if (stats.is_set()) { + data.push_back({"timings", stats.to_json()}); } if (is_progress) { data.push_back({"prompt_progress", progress.to_json()}); @@ -1539,34 +1513,104 @@ json server_task_result_error::to_json() { // server_task_result_metrics // json server_task_result_metrics::to_json() { - return json { - { "idle", n_idle_slots }, - { "processing", n_processing_slots }, - { "deferred", n_tasks_deferred }, - { "t_start", t_start }, + return slots_data; +} - { "n_prompt_tokens_processed_total", n_prompt_tokens_processed_total }, - { "t_tokens_generation_total", t_tokens_generation_total }, - { "n_tokens_predicted_total", n_tokens_predicted_total }, - { "t_prompt_processing_total", t_prompt_processing_total }, - - { "n_tokens_max", n_tokens_max }, - - { "n_prompt_tokens_processed", n_prompt_tokens_processed }, - { "t_prompt_processing", t_prompt_processing }, - { "n_tokens_predicted", n_tokens_predicted }, - { "t_tokens_generation", t_tokens_generation }, - - { "n_decode_total", n_decode_total }, - { "n_busy_slots_total", n_busy_slots_total }, - - { "n_draft_tokens_total", n_draft_tokens_total }, - { "n_draft_accepted_total", n_draft_accepted_total }, - { "n_draft_verif_steps_total", n_draft_verif_steps_total }, - { "n_accepted_per_pos_total", n_accepted_per_pos_total }, - - { "slots", slots_data }, +// metrics definition: https://prometheus.io/docs/practices/naming/#metric-names +std::string server_task_result_metrics::to_metrics() { + const std::vector counters = { + { + "prompt_tokens_total", + "Number of prompt tokens processed, excluding cached tokens", + (double) metrics.prompt.count + }, { + "prompt_tokens_cached_total", + "Number of prompt tokens reused from the cache", + (double) metrics.n_prompt_cached + }, { + "prompt_seconds_total", + "Total time spent processing prompts", + metrics.prompt.time / 1.e6 + }, { + "tokens_predicted_total", + "Number of generation tokens processed", + (double) metrics.predict.count + }, { + "tokens_predicted_seconds_total", + "Total time spent generating tokens", + metrics.predict.time / 1.e6 + }, { + "n_decode_total", + "Total number of llama_decode() calls, excluding speculative decoding and multimodal decoding", + (double) metrics.n_decode + }, { + "n_tokens_max", + "Largest observed sequence length (prompt + generation)", + (double) metrics.n_tokens_max + }, { + "spec_decode_num_draft_tokens_total", + "Speculative: Total draft tokens generated", + (double) metrics.n_draft_tokens + }, { + "spec_decode_num_accepted_tokens_total", + "Speculative: Total draft tokens accepted by the target model", + (double) metrics.n_draft_accepted + }, { + "spec_decode_num_drafts_total", + "Speculative: Total speculative decoding verification steps", + (double) metrics.n_draft_verif_steps + }, }; + + const std::vector gauges = { + { + "prompt_tokens_seconds", + "Average prompt throughput in tokens/s", + metrics.prompt_bucket.n_per_second() + }, { + "predicted_tokens_seconds", + "Average generation throughput in tokens/s", + metrics.predict_bucket.n_per_second() + }, { + "requests_processing", + "Number of requests processing", + (double) n_processing_slots + }, { + "requests_deferred", + "Number of requests deferred", + (double) n_tasks_deferred + }, { + "n_busy_slots_per_decode", + "Average number of busy slots per llama_decode() call", + (double) metrics.n_busy_slots / std::max((double) metrics.n_decode, 1.0) + }, + }; + + std::stringstream prometheus; + + auto add_items = [&prometheus](const char * type, const std::vector & items) { + for (const auto & item : items) { + prometheus << "# HELP llamacpp:" << item.name << " " << item.description << "\n" + << "# TYPE llamacpp:" << item.name << " " << type << "\n" + << "llamacpp:" << item.name << " " << item.value << "\n"; + } + }; + + add_items("counter", counters); + add_items("gauge", gauges); + + // labeled counter: one time series per draft position + if (!metrics.n_accepted_per_pos.empty()) { + prometheus << "# HELP llamacpp:spec_decode_num_accepted_tokens_per_pos_total" + " Accepted tokens per draft position\n" + << "# TYPE llamacpp:spec_decode_num_accepted_tokens_per_pos_total counter\n"; + for (size_t i = 0; i < metrics.n_accepted_per_pos.size(); i++) { + prometheus << "llamacpp:spec_decode_num_accepted_tokens_per_pos_total{position=\"" + << i << "\"} " << metrics.n_accepted_per_pos[i] << "\n"; + } + } + + return prometheus.str(); } // diff --git a/tools/server/server-task.h b/tools/server/server-task.h index 6275ec760..b6da4d4bd 100644 --- a/tools/server/server-task.h +++ b/tools/server/server-task.h @@ -259,26 +259,6 @@ struct server_task { } }; -struct result_timings { - int32_t cache_n = -1; - - int32_t prompt_n = -1; - double prompt_ms = 0.0; - double prompt_per_token_ms = 0.0; - double prompt_per_second = 0.0; - - int32_t predicted_n = -1; - double predicted_ms = 0.0; - double predicted_per_token_ms = 0.0; - double predicted_per_second = 0.0; - - // Optional speculative metrics - only included when > 0 - int32_t draft_n = 0; - int32_t draft_n_accepted = 0; - - json to_json() const; -}; - struct result_prompt_progress { int32_t total = 0; int32_t cache = 0; @@ -343,7 +323,7 @@ struct server_task_result_cmpl_final : server_task_result { bool stream; bool include_usage; - result_timings timings; + server_slot_stats stats; std::string prompt; bool truncated; @@ -425,7 +405,7 @@ struct server_task_result_cmpl_partial : server_task_result { bool is_begin = false; // whether to send 200 status to HTTP client (begin of SSE stream) // ref: https://github.com/ggml-org/llama.cpp/pull/23884 completion_token_output prob_output; - result_timings timings; + server_slot_stats stats; result_prompt_progress progress; // response formatting @@ -510,38 +490,27 @@ struct server_task_result_error : server_task_result { }; struct server_task_result_metrics : server_task_result { + // these are immediate stats, not accumulated (server_metrics is cumulative) int n_idle_slots; int n_processing_slots; int n_tasks_deferred; - int64_t t_start; - // TODO: somehow reuse server_metrics in the future, instead of duplicating the fields - uint64_t n_prompt_tokens_processed_total = 0; - uint64_t t_prompt_processing_total = 0; - uint64_t n_tokens_predicted_total = 0; - uint64_t t_tokens_generation_total = 0; - - uint64_t n_tokens_max = 0; - - uint64_t n_prompt_tokens_processed = 0; - uint64_t t_prompt_processing = 0; - - uint64_t n_tokens_predicted = 0; - uint64_t t_tokens_generation = 0; - - uint64_t n_decode_total = 0; - uint64_t n_busy_slots_total = 0; - - uint64_t n_draft_tokens_total = 0; - uint64_t n_draft_accepted_total = 0; - uint64_t n_draft_verif_steps_total = 0; - std::vector n_accepted_per_pos_total; + server_metrics metrics; // while we can also use std::vector this requires copying the slot object which can be quite messy // therefore, we use json to temporarily store the slot.to_json() result json slots_data = json::array(); + // used by /slots API virtual json to_json() override; + + // used by /metrics API + struct metric_item { + std::string name; + std::string description; + double value; // prometheus values are always float64 + }; + std::string to_metrics(); }; struct server_task_result_slot_save_load : server_task_result { diff --git a/tools/server/tests/unit/test_metrics.py b/tools/server/tests/unit/test_metrics.py new file mode 100644 index 000000000..10cfc424b --- /dev/null +++ b/tools/server/tests/unit/test_metrics.py @@ -0,0 +1,227 @@ +import pytest +from utils import * + +server = ServerPreset.tinyllama2() + + +@pytest.fixture(autouse=True) +def create_server(): + global server + server = ServerPreset.tinyllama2() + server.server_metrics = True + + +def fetch_metrics(server: ServerProcess) -> str: + """get /metrics as raw prometheus text""" + res = server.make_request("GET", "/metrics") + assert res.status_code == 200 + assert "Process-Start-Time-Unix" in res.headers + assert isinstance(res.body, str) + return res.body + + +def parse_metrics(text: str) -> dict: + """parse the prometheus text format into {name: (type, value)}""" + out = {} + types = {} + for line in text.splitlines(): + if line.startswith("# TYPE "): + _, _, name, kind = line.split(" ", 3) + types[name] = kind + elif line.startswith("llamacpp:") and "{" not in line: + name, value = line.split(" ", 1) + assert name in types, f"{name} has no # TYPE line" + out[name] = (types[name], float(value)) + return out + + +def test_metrics_disabled(): + global server + server.server_metrics = False + server.start() + res = server.make_request("GET", "/metrics") + assert res.status_code == 501 # ERROR_TYPE_NOT_SUPPORTED + + +def test_metrics_prometheus_format(): + global server + server.start() + server.make_request("POST", "/completion", data={"prompt": "I believe", "n_predict": 8}) + + text = fetch_metrics(server) + metrics = parse_metrics(text) + + expected_counters = [ + "llamacpp:prompt_tokens_total", + "llamacpp:prompt_tokens_cached_total", + "llamacpp:prompt_seconds_total", + "llamacpp:tokens_predicted_total", + "llamacpp:tokens_predicted_seconds_total", + "llamacpp:n_decode_total", + "llamacpp:n_tokens_max", + "llamacpp:spec_decode_num_draft_tokens_total", + "llamacpp:spec_decode_num_accepted_tokens_total", + "llamacpp:spec_decode_num_drafts_total", + ] + expected_gauges = [ + "llamacpp:prompt_tokens_seconds", + "llamacpp:predicted_tokens_seconds", + "llamacpp:requests_processing", + "llamacpp:requests_deferred", + "llamacpp:n_busy_slots_per_decode", + ] + + for name in expected_counters: + assert metrics[name][0] == "counter" + for name in expected_gauges: + assert metrics[name][0] == "gauge" + + # every metric must carry a help line + for name in expected_counters + expected_gauges: + assert f"# HELP {name} " in text + + assert metrics["llamacpp:n_decode_total"][1] > 0 + assert metrics["llamacpp:requests_processing"][1] == 0 + + +def test_metrics_prompt_processed_and_cached(): + global server + server.n_slots = 1 # keep the prompt cache on a single slot + server.start() + + prompt = "the quick brown fox jumps over the lazy dog" + + n_processed = 0 + n_cached = 0 + for _ in range(2): + res = server.make_request("POST", "/completion", data={"prompt": prompt, "n_predict": 4}) + assert res.status_code == 200 + n_processed += res.body["timings"]["prompt_n"] + n_cached += res.body["timings"]["cache_n"] + + # the second request must reuse the prompt of the first one + assert n_cached > 0 + + metrics = parse_metrics(fetch_metrics(server)) + + # cached tokens are counted apart, they cost no decode + assert metrics["llamacpp:prompt_tokens_total"][1] == n_processed + assert metrics["llamacpp:prompt_tokens_cached_total"][1] == n_cached + + +def test_metrics_predicted_total_matches_requests(): + global server + server.start() + + n_predicted = 0 + for n_predict in [1, 4, 16]: + res = server.make_request("POST", "/completion", data={"prompt": "I believe", "n_predict": n_predict}) + assert res.status_code == 200 + n_predicted += res.body["timings"]["predicted_n"] + + metrics = parse_metrics(fetch_metrics(server)) + assert metrics["llamacpp:tokens_predicted_total"][1] == n_predicted + + +def test_metrics_generation_rate_excludes_first_token(): + global server + server.start() + + # the first token comes from the logits of the last prompt batch, so it costs no decode step + res = server.make_request("POST", "/completion", data={"prompt": "I believe", "n_predict": 1}) + timings = res.body["timings"] + assert timings["predicted_n"] == 1 + assert timings["predicted_per_second"] == 0.0 + assert timings["predicted_per_token_ms"] == 0.0 + + res = server.make_request("POST", "/completion", data={"prompt": "I believe", "n_predict": 16}) + timings = res.body["timings"] + assert timings["predicted_n"] == 16 + # the rate is over 15 decode steps, not 16 tokens + expected = 1e3 / timings["predicted_ms"] * 15 + assert abs(timings["predicted_per_second"] - expected) < 1e-6 + + +@pytest.mark.parametrize("n_predict", [1, 8]) +def test_metrics_timings_are_finite(n_predict: int): + global server + server.start() + res = server.make_request("POST", "/completion", data={"prompt": "I believe", "n_predict": n_predict}) + timings = res.body["timings"] + + # a null here means the server produced inf or nan + for key, value in timings.items(): + assert value is not None, f"{key} is null" + assert value >= 0, f"{key} is negative" + + assert timings["prompt_ms"] > 0 + assert timings["prompt_per_token_ms"] > 0 + + +def test_metrics_timings_on_prompt_progress(): + global server + server.start() + + # a long prompt so that it is split over several batches (n_batch = 32) + prompt = "the quick brown fox jumps over the lazy dog " * 8 + chunks = list(server.make_stream_request("POST", "/completion", data={ + "prompt": prompt, + "n_predict": 4, + "stream": True, + "timings_per_token": True, + "return_progress": True, + })) + + progress = [c for c in chunks if "prompt_progress" in c] + assert len(progress) > 1 # the prompt did not fit in a single batch + + # the very first update is sent before any prompt token is decoded + first = progress[0]["timings"] + assert first["prompt_n"] == 0 + assert first["prompt_ms"] == 0.0 + assert first["predicted_n"] == 0 + assert first["predicted_ms"] == 0.0 + + # timings must never go backwards, nor report bogus values + prompt_ms = 0.0 + for chunk in progress: + timings = chunk["timings"] + for key, value in timings.items(): + assert value is not None, f"{key} is null" + assert value >= 0, f"{key} is negative" + assert timings["prompt_ms"] >= prompt_ms + prompt_ms = timings["prompt_ms"] + + assert prompt_ms > 0 + + +def test_metrics_slots_idle_after_completion(): + global server + server.server_slots = True + server.start() + server.make_request("POST", "/completion", data={"prompt": "I believe", "n_predict": 8}) + + res = server.make_request("GET", "/slots") + assert res.status_code == 200 + for slot in res.body: + assert slot["is_processing"] is False + if "next_token" in slot: + # the budget of the finished task must not leak into the idle slot + assert slot["next_token"][0]["n_remain"] == -1 + assert slot["next_token"][0]["n_decoded"] == 0 + + +def test_metrics_embedding_prompt_is_counted(): + global server + server = ServerPreset.bert_bge_small() + server.server_metrics = True + server.start() + + res = server.make_request("POST", "/v1/embeddings", data={"input": ["hello world", "goodbye world"]}) + assert res.status_code == 200 + + # embedding tasks never sample a token, but their prompt still costs a decode + metrics = parse_metrics(fetch_metrics(server)) + assert metrics["llamacpp:prompt_tokens_total"][1] > 0 + assert metrics["llamacpp:n_decode_total"][1] > 0 + assert metrics["llamacpp:tokens_predicted_total"][1] == 0