From 27c8bb4f63ad9f20bf5901067810a4be5ffe20c4 Mon Sep 17 00:00:00 2001 From: Georgi Gerganov Date: Sun, 28 Jun 2026 08:52:15 +0300 Subject: [PATCH] logs : reduce v2 (#25078) * server : reduce logs * cont : common * cont : spec * cont : CMN_ -> COM_ --- common/common.cpp | 94 +++++++++++----------- common/common.h | 7 ++ common/fit.cpp | 2 +- common/reasoning-budget.cpp | 20 ++--- common/speculative.cpp | 133 +++++++++++++++++--------------- src/llama-context.cpp | 2 +- tools/server/server-context.cpp | 86 +++++++++++---------- tools/server/server-http.cpp | 16 ++-- tools/server/server-schema.cpp | 2 +- tools/server/server-stream.cpp | 11 ++- tools/server/server-task.cpp | 12 +-- tools/server/server.cpp | 12 +-- 12 files changed, 203 insertions(+), 194 deletions(-) diff --git a/common/common.cpp b/common/common.cpp index a14e7bbed9..0dd9ede5eb 100644 --- a/common/common.cpp +++ b/common/common.cpp @@ -225,7 +225,7 @@ bool set_process_priority(enum ggml_sched_priority prio) { } if (!SetPriorityClass(GetCurrentProcess(), p)) { - LOG_WRN("failed to set process priority class %d : (%d)\n", prio, (int) GetLastError()); + COM_WRN("failed to set process priority class %d : (%d)\n", prio, (int) GetLastError()); return false; } @@ -251,7 +251,7 @@ bool set_process_priority(enum ggml_sched_priority prio) { } if (setpriority(PRIO_PROCESS, 0, p) != 0) { - LOG_WRN("failed to set process priority %d : %s (%d)\n", prio, strerror(errno), errno); + COM_WRN("failed to set process priority %d : %s (%d)\n", prio, strerror(errno), errno); return false; } return true; @@ -284,14 +284,14 @@ void postprocess_cpu_params(common_cpu_params & cpuparams, const common_cpu_para if (n_set && n_set < cpuparams.n_threads) { // Not enough set bits, may experience performance issues. - LOG_WRN("Not enough set bits in CPU mask (%d) to satisfy requested thread count: %d\n", n_set, cpuparams.n_threads); + COM_WRN("Not enough set bits in CPU mask (%d) to satisfy requested thread count: %d\n", n_set, cpuparams.n_threads); } } bool parse_cpu_range(const std::string & range, bool (&boolmask)[GGML_MAX_N_THREADS]) { size_t dash_loc = range.find('-'); if (dash_loc == std::string::npos) { - LOG_ERR("Format of CPU range is invalid! Expected []-[].\n"); + COM_ERR("%s", "Format of CPU range is invalid! Expected []-[].\n"); return false; } @@ -303,7 +303,7 @@ bool parse_cpu_range(const std::string & range, bool (&boolmask)[GGML_MAX_N_THRE } else { start_i = std::stoull(range.substr(0, dash_loc)); if (start_i >= GGML_MAX_N_THREADS) { - LOG_ERR("Start index out of bounds!\n"); + COM_ERR("%s", "Start index out of bounds!\n"); return false; } } @@ -313,7 +313,7 @@ bool parse_cpu_range(const std::string & range, bool (&boolmask)[GGML_MAX_N_THRE } else { end_i = std::stoull(range.substr(dash_loc + 1)); if (end_i >= GGML_MAX_N_THREADS) { - LOG_ERR("End index out of bounds!\n"); + COM_ERR("%s", "End index out of bounds!\n"); return false; } } @@ -333,7 +333,7 @@ bool parse_cpu_mask(const std::string & mask, bool (&boolmask)[GGML_MAX_N_THREAD } size_t num_digits = mask.length() - start_i; - if (num_digits > 128) num_digits = 128; + num_digits = std::min(num_digits, 128); size_t end_i = num_digits + start_i; @@ -348,7 +348,7 @@ bool parse_cpu_mask(const std::string & mask, bool (&boolmask)[GGML_MAX_N_THREAD } else if (c >= 'A' && c <= 'F') { id -= 'A' - 10; } else { - LOG_ERR("Invalid hex character '%c' at position %d\n", c, int32_t(i)); + COM_ERR("Invalid hex character '%c' at position %d\n", c, int32_t(i)); return false; } @@ -379,21 +379,21 @@ void common_params_print_info(const common_params & params, bool print_devices) #else const char * build_type = " (debug)"; #endif - LOG_TRC("%s: build %d (%s) with %s for %s%s\n", __func__, llama_build_number(), llama_commit(), llama_compiler(), llama_build_target(), build_type); + COM_TRC("%s: build %d (%s) with %s for %s%s\n", __func__, llama_build_number(), llama_commit(), llama_compiler(), llama_build_target(), build_type); - LOG_INF("log_info: verbosity = %d (adjust with the `-lv N` CLI arg)\n", common_log_get_verbosity_thold()); + COM_INF("%s: verbosity = %d (adjust with the `-lv N` CLI arg)\n", __func__, common_log_get_verbosity_thold()); // device enumeration creates a primary context on CUDA backends, skip it when the caller does not own any device if (print_devices) { - LOG_INF("device_info:\n"); + COM_TRC("%s", "device_info:\n"); for (size_t i = 0; i < ggml_backend_dev_count(); ++i) { auto * dev = ggml_backend_dev_get(i); size_t free, total; ggml_backend_dev_memory(dev, &free, &total); - LOG_INF(" - %-8s: %s (%zu MiB, %zu MiB free)\n", ggml_backend_dev_name(dev), ggml_backend_dev_description(dev), total / 1024 / 1024, free / 1024 / 1024); + COM_TRC(" - %-8s: %s (%zu MiB, %zu MiB free)\n", ggml_backend_dev_name(dev), ggml_backend_dev_description(dev), total / 1024 / 1024, free / 1024 / 1024); } } - LOG_INF("%s\n", common_params_get_system_info(params).c_str()); + COM_TRC("%s\n", common_params_get_system_info(params).c_str()); } std::string common_params_get_system_info(const common_params & params) { @@ -660,7 +660,7 @@ void string_process_escapes(std::string & input) { bool string_parse_kv_override(const char * data, std::vector & overrides) { const char * sep = strchr(data, '='); if (sep == nullptr || sep - data >= 128) { - LOG_ERR("%s: malformed KV override '%s'\n", __func__, data); + COM_ERR("%s: malformed KV override '%s'\n", __func__, data); return false; } llama_model_kv_override kvo; @@ -683,20 +683,20 @@ bool string_parse_kv_override(const char * data, std::vector 127) { - LOG_ERR("%s: malformed KV override '%s', value cannot exceed 127 chars\n", __func__, data); + COM_ERR("%s: malformed KV override '%s', value cannot exceed 127 chars\n", __func__, data); return false; } strncpy(kvo.val_str, sep, 127); kvo.val_str[127] = '\0'; } else { - LOG_ERR("%s: invalid type for KV override '%s'\n", __func__, data); + COM_ERR("%s: invalid type for KV override '%s'\n", __func__, data); return false; } overrides.emplace_back(std::move(kvo)); @@ -1199,8 +1199,8 @@ common_init_result::common_init_result(common_params & params, bool model_only) auto cparams = common_context_params_to_llama(params); if (params.fit_params) { - LOG_INF("%s: fitting params to device memory ...\n", __func__); - LOG_INF("%s: (for bugs during this step try to reproduce them with -fit off, or provide --verbose logs if the bug only occurs with -fit on)\n", __func__); + COM_TRC("%s", "fitting params to device memory ...\n"); + COM_TRC("%s", "(for bugs during this step try to reproduce them with -fit off, or provide --verbose logs if the bug only occurs with -fit on)\n"); common_fit_params(params.model.path.c_str(), &mparams, &cparams, params.tensor_split, params.tensor_buft_overrides.data(), @@ -1227,7 +1227,7 @@ common_init_result::common_init_result(common_params & params, bool model_only) llama_adapter_lora_ptr lora; lora.reset(llama_adapter_lora_init(model, la.path.c_str())); if (lora == nullptr) { - LOG_ERR("%s: failed to load lora adapter '%s'\n", __func__, la.path.c_str()); + COM_ERR("failed to load lora adapter '%s'\n", la.path.c_str()); pimpl->model.reset(model); return; } @@ -1246,14 +1246,14 @@ common_init_result::common_init_result(common_params & params, bool model_only) common_init_sampler_from_model(model, params.sampling); if (params.sampling.ignore_eos && llama_vocab_eos(vocab) == LLAMA_TOKEN_NULL) { - LOG_WRN("%s: warning: vocab does not have an EOS token, ignoring --ignore-eos\n", __func__); + COM_WRN("%s", "vocab does not have an EOS token, ignoring --ignore-eos\n"); params.sampling.ignore_eos = false; } // initialize once for (llama_token i = 0; i < llama_vocab_n_tokens(vocab); i++) { if (llama_vocab_is_eog(vocab, i)) { - LOG_TRC("%s: added %s logit bias = %f\n", __func__, common_token_to_piece(vocab, i).c_str(), -INFINITY); + COM_TRC("added %s logit bias = %f\n", common_token_to_piece(vocab, i).c_str(), -INFINITY); params.sampling.logit_bias_eog.push_back({i, -INFINITY}); } } @@ -1291,7 +1291,7 @@ common_init_result::common_init_result(common_params & params, bool model_only) llama_context * lctx = llama_init_from_model(model, cparams); if (lctx == NULL) { - LOG_ERR("%s: failed to create context with model '%s'\n", __func__, params.model.path.c_str()); + COM_ERR("failed to create context with model '%s'\n", params.model.path.c_str()); return; } @@ -1328,7 +1328,7 @@ common_init_result_ptr common_init_from_params(common_params & params, bool mode llama_model * model = res->model(); if (model == NULL) { - LOG_ERR("%s: failed to load model '%s'\n", __func__, params.model.path.c_str()); + COM_ERR("failed to load model '%s'\n", params.model.path.c_str()); return res; } @@ -1338,14 +1338,14 @@ common_init_result_ptr common_init_from_params(common_params & params, bool mode llama_context * lctx = res->context(); if (lctx == NULL) { - LOG_ERR("%s: failed to create context with model '%s'\n", __func__, params.model.path.c_str()); + COM_ERR("failed to create context with model '%s'\n", params.model.path.c_str()); return res; } const llama_vocab * vocab = llama_model_get_vocab(model); if (params.ctx_shift && !llama_memory_can_shift(llama_get_memory(lctx))) { - LOG_WRN("%s: KV cache shifting is not supported for this context, disabling KV cache shifting\n", __func__); + COM_WRN("%s", "KV cache shifting is not supported for this context, disabling KV cache shifting\n"); params.ctx_shift = false; } @@ -1374,7 +1374,7 @@ common_init_result_ptr common_init_from_params(common_params & params, bool mode bool ok = true; if (llama_vocab_bos(vocab) == LLAMA_TOKEN_NULL) { - LOG_WRN("%s: warning: vocab does not have a BOS token, reranking will not work\n", __func__); + COM_WRN("%s", "vocab does not have a BOS token, reranking will not work\n"); ok = false; } @@ -1383,10 +1383,10 @@ common_init_result_ptr common_init_from_params(common_params & params, bool mode bool has_rerank_prompt = llama_model_chat_template(model, "rerank") != NULL; if (!has_eos && !has_sep && !has_rerank_prompt) { - LOG_WRN("%s: warning: vocab does not have an EOS token, SEP token, or rerank prompt. Reranking will not work\n", __func__); + COM_WRN("%s", "vocab does not have an EOS token, SEP token, or rerank prompt. Reranking will not work\n"); ok = false; } else if (!has_eos) { - LOG_WRN("%s: warning: vocab does not have an EOS token, using SEP token as fallback\n", __func__); + COM_WRN("%s", "vocab does not have an EOS token, using SEP token as fallback\n"); } if (!ok) { @@ -1399,7 +1399,7 @@ common_init_result_ptr common_init_from_params(common_params & params, bool mode } if (params.warmup) { - LOG_INF("%s: warming up the model with an empty run - please wait ... (--no-warmup to disable)\n", __func__); + COM_TRC("%s", "warming up the model with an empty run - please wait ... (--no-warmup to disable)\n"); std::vector tmp; llama_token bos = llama_vocab_bos(vocab); @@ -1473,20 +1473,20 @@ common_context_seq_rm_type common_context_can_seq_rm(llama_context * ctx) { int ret = llama_decode(ctx, llama_batch_get_one(tmp.data(), tmp.size())); if (ret != 0) { - LOG_ERR("%s: llama_decode() failed: %d\n", __func__, ret); + COM_ERR("llama_decode() failed: %d\n", ret); res = COMMON_CONTEXT_SEQ_RM_TYPE_NO; goto done; } if (llama_n_rs_seq(ctx) > 0) { - LOG_INF("%s: the context supports bounded partial sequence removal\n", __func__); + COM_TRC("%s", "the context supports bounded partial sequence removal\n"); res = COMMON_CONTEXT_SEQ_RM_TYPE_RS; goto done; } // try to remove the last tokens if (!llama_memory_seq_rm(mem, 0, 1, -1)) { - LOG_TRC("%s: the context does not support partial sequence removal\n", __func__); + COM_TRC("%s", "the context does not support partial sequence removal\n"); res = COMMON_CONTEXT_SEQ_RM_TYPE_FULL; goto done; } @@ -1803,13 +1803,13 @@ static common_control_vector_data common_control_vector_load_one(const common_co }; struct gguf_context * ctx_gguf = gguf_init_from_file(load_info.fname.c_str(), meta_gguf_params); if (!ctx_gguf) { - LOG_ERR("%s: failed to load control vector file from %s\n", __func__, load_info.fname.c_str()); + COM_ERR("failed to load control vector file from %s\n", load_info.fname.c_str()); return result; } int32_t n_tensors = gguf_get_n_tensors(ctx_gguf); if (n_tensors == 0) { - LOG_WRN("%s: no direction tensors found in %s\n", __func__, load_info.fname.c_str()); + COM_WRN("no direction tensors found in %s\n", load_info.fname.c_str()); } for (int i = 0; i < n_tensors; i++) { @@ -1827,23 +1827,23 @@ static common_control_vector_data common_control_vector_load_one(const common_co } } if (layer_idx < 0) { - LOG_ERR("%s: invalid/unparsable direction tensor layer index in %s\n", __func__, load_info.fname.c_str()); + COM_ERR("invalid/unparsable direction tensor layer index in %s\n", load_info.fname.c_str()); result.n_embd = -1; break; } else if (layer_idx == 0) { - LOG_ERR("%s: invalid (zero) direction tensor layer index in %s\n", __func__, load_info.fname.c_str()); + COM_ERR("invalid (zero) direction tensor layer index in %s\n", load_info.fname.c_str()); result.n_embd = -1; break; } struct ggml_tensor * tensor = ggml_get_tensor(ctx, name.c_str()); if (tensor->type != GGML_TYPE_F32) { - LOG_ERR("%s: invalid (non-F32) direction tensor type in %s\n", __func__, load_info.fname.c_str()); + COM_ERR("invalid (non-F32) direction tensor type in %s\n", load_info.fname.c_str()); result.n_embd = -1; break; } if (ggml_n_dims(tensor) != 1) { - LOG_ERR("%s: invalid (non-1D) direction tensor shape in %s\n", __func__, load_info.fname.c_str()); + COM_ERR("invalid (non-1D) direction tensor shape in %s\n", load_info.fname.c_str()); result.n_embd = -1; break; } @@ -1851,7 +1851,7 @@ static common_control_vector_data common_control_vector_load_one(const common_co if (result.n_embd == -1) { result.n_embd = ggml_nelements(tensor); } else if (ggml_nelements(tensor) != result.n_embd) { - LOG_ERR("%s: direction tensor in %s does not match previous dimensions\n", __func__, load_info.fname.c_str()); + COM_ERR("direction tensor in %s does not match previous dimensions\n", load_info.fname.c_str()); result.n_embd = -1; break; } @@ -1868,7 +1868,7 @@ static common_control_vector_data common_control_vector_load_one(const common_co } if (result.n_embd == -1) { - LOG_WRN("%s: skipping %s due to invalid direction tensors\n", __func__, load_info.fname.c_str()); + COM_WRN("skipping %s due to invalid direction tensors\n", load_info.fname.c_str()); result.data.clear(); } @@ -1889,7 +1889,7 @@ common_control_vector_data common_control_vector_load(const std::vector(all_tokens.data() + offset), n_tokens_before_last))) { - LOG_ERR("%s : failed to eval\n", __func__); + COM_ERR("%s", "failed to eval\n"); return false; } n_past += n_tokens_before_last; llama_state_save_file(ctx, state_path.data(), all_tokens.data(), all_tokens.size()); - LOG_INF("saved session before last token to %s, n_new = %zu\n", state_path.data(), all_tokens.size()); + COM_INF("saved session before last token to %s, n_new = %zu\n", state_path.data(), all_tokens.size()); llama_token last_token = all_tokens.back(); llama_batch batch = llama_batch_get_one(&last_token, 1); @@ -2030,13 +2030,13 @@ bool common_prompt_batch_decode( batch.pos = &pos; if (llama_decode(ctx, batch)) { - LOG_ERR("%s : failed to eval last token\n", __func__); + COM_ERR("%s", "failed to eval last token\n"); return false; } n_past++; } else { if (llama_decode(ctx, llama_batch_get_one(const_cast(all_tokens.data() + offset), n_new))) { - LOG_ERR("%s : failed to eval\n", __func__); + COM_ERR("%s", "failed to eval\n"); return false; } n_past += n_new; diff --git a/common/common.h b/common/common.h index 94147d5d8c..d56f6064b1 100644 --- a/common/common.h +++ b/common/common.h @@ -25,6 +25,13 @@ #define DIRECTORY_SEPARATOR '/' #endif // _WIN32 +#define COM_DBG(fmt, ...) LOG_DBG("cmn %12.*s: " fmt, 12, __func__, __VA_ARGS__) +#define COM_TRC(fmt, ...) LOG_TRC("cmn %12.*s: " fmt, 12, __func__, __VA_ARGS__) +#define COM_INF(fmt, ...) LOG_INF("cmn %12.*s: " fmt, 12, __func__, __VA_ARGS__) +#define COM_WRN(fmt, ...) LOG_WRN("cmn %12.*s: " fmt, 12, __func__, __VA_ARGS__) +#define COM_ERR(fmt, ...) LOG_ERR("cmn %12.*s: " fmt, 12, __func__, __VA_ARGS__) +#define COM_CNT(fmt, ...) LOG_CNT("" fmt, __VA_ARGS__) + #define die(msg) do { fputs("error: " msg "\n", stderr); exit(1); } while (0) #define die_fmt(fmt, ...) do { fprintf(stderr, "error: " fmt "\n", __VA_ARGS__); exit(1); } while (0) diff --git a/common/fit.cpp b/common/fit.cpp index a8565bfc91..afbf0b10f3 100644 --- a/common/fit.cpp +++ b/common/fit.cpp @@ -233,7 +233,7 @@ static void common_params_fit_impl( sum_projected_used = dmds_full.back().mb.total(); sum_free = dmds_full.back().total; sum_projected_free = sum_free - sum_projected_used; - LOG_INF("%s: projected to use %" PRId64 " MiB of host memory vs. %" PRId64 " MiB of total host memory\n", + LOG_TRC("%s: projected to use %" PRId64 " MiB of host memory vs. %" PRId64 " MiB of total host memory\n", __func__, sum_projected_used/MiB, sum_free/MiB); if (sum_projected_free >= margins[0]) { LOG_TRC("%s: will leave %" PRId64 " >= %" PRId64 " MiB of system memory, no changes needed\n", diff --git a/common/reasoning-budget.cpp b/common/reasoning-budget.cpp index ce41d029b0..7da0bb1c57 100644 --- a/common/reasoning-budget.cpp +++ b/common/reasoning-budget.cpp @@ -65,12 +65,12 @@ static void common_reasoning_budget_accept(struct llama_sampler * smpl, llama_to if (ctx->start_matcher.advance(token)) { ctx->state = REASONING_BUDGET_COUNTING; ctx->remaining = ctx->budget; - LOG_INF("reasoning-budget: activated, budget=%d tokens\n", ctx->budget); + COM_TRC("activated, budget=%d tokens\n", ctx->budget); if (ctx->remaining <= 0) { ctx->state = REASONING_BUDGET_FORCING; ctx->force_pos = 0; - LOG_INF("reasoning-budget: budget=0, forcing immediately\n"); + COM_TRC("%s", "budget=0, forcing immediately\n"); } } break; @@ -80,7 +80,7 @@ static void common_reasoning_budget_accept(struct llama_sampler * smpl, llama_to { if (ctx->end_matcher.advance(token)) { ctx->state = REASONING_BUDGET_DONE; - LOG_INF("reasoning-budget: deactivated (natural end)\n"); + COM_TRC("%s", "deactivated (natural end)\n"); break; } @@ -95,7 +95,7 @@ static void common_reasoning_budget_accept(struct llama_sampler * smpl, llama_to ctx->state = REASONING_BUDGET_FORCING; ctx->force_pos = 0; ctx->end_matcher.reset(); - LOG_INF("reasoning-budget: UTF-8 complete, now forcing end sequence\n"); + COM_TRC("%s", "UTF-8 complete, now forcing end sequence\n"); } } else if (ctx->state == REASONING_BUDGET_COUNTING) { ctx->remaining--; @@ -104,11 +104,11 @@ static void common_reasoning_budget_accept(struct llama_sampler * smpl, llama_to ctx->state = REASONING_BUDGET_FORCING; ctx->force_pos = 0; ctx->end_matcher.reset(); - LOG_INF("reasoning-budget: budget exhausted, forcing end sequence\n"); + COM_TRC("%s", "budget exhausted, forcing end sequence\n"); } else { ctx->state = REASONING_BUDGET_WAITING_UTF8; ctx->end_matcher.reset(); - LOG_INF("reasoning-budget: budget exhausted, waiting for UTF-8 completion\n"); + COM_TRC("%s", "budget exhausted, waiting for UTF-8 completion\n"); } } } @@ -118,7 +118,7 @@ static void common_reasoning_budget_accept(struct llama_sampler * smpl, llama_to ctx->force_pos++; if (ctx->force_pos >= ctx->forced_tokens.size()) { ctx->state = REASONING_BUDGET_DONE; - LOG_INF("reasoning-budget: forced sequence complete, done\n"); + COM_TRC("%s", "forced sequence complete, done\n"); } break; case REASONING_BUDGET_DONE: @@ -128,12 +128,12 @@ static void common_reasoning_budget_accept(struct llama_sampler * smpl, llama_to ctx->state = REASONING_BUDGET_COUNTING; ctx->remaining = ctx->budget; ctx->end_matcher.reset(); - LOG_INF("reasoning-budget: re-activated on new start tag, budget=%d tokens\n", ctx->budget); + COM_TRC("re-activated on new start tag, budget=%d tokens\n", ctx->budget); if (ctx->remaining <= 0) { ctx->state = REASONING_BUDGET_FORCING; ctx->force_pos = 0; - LOG_INF("reasoning-budget: budget=0, forcing immediately\n"); + COM_TRC("%s", "budget=0, forcing immediately\n"); } } break; @@ -264,7 +264,7 @@ bool common_reasoning_budget_force(struct llama_sampler * smpl) { ctx->state = REASONING_BUDGET_FORCING; ctx->force_pos = 0; ctx->end_matcher.reset(); - LOG_INF("reasoning-budget: forced into forcing state (manual transition)\n"); + COM_TRC("%s", "forced into forcing state (manual transition)\n"); return true; } diff --git a/common/speculative.cpp b/common/speculative.cpp index c922a3f592..a3495c3a11 100644 --- a/common/speculative.cpp +++ b/common/speculative.cpp @@ -18,6 +18,13 @@ #include #include +#define SPC_DBG(fmt, ...) LOG_DBG("spec %12.*s: " fmt, 12, __func__, __VA_ARGS__) +#define SPC_TRC(fmt, ...) LOG_TRC("spec %12.*s: " fmt, 12, __func__, __VA_ARGS__) +#define SPC_INF(fmt, ...) LOG_INF("spec %12.*s: " fmt, 12, __func__, __VA_ARGS__) +#define SPC_WRN(fmt, ...) LOG_WRN("spec %12.*s: " fmt, 12, __func__, __VA_ARGS__) +#define SPC_ERR(fmt, ...) LOG_ERR("spec %12.*s: " fmt, 12, __func__, __VA_ARGS__) +#define SPC_CNT(fmt, ...) LOG_CNT("" fmt, __VA_ARGS__) + #define SPEC_VOCAB_MAX_SIZE_DIFFERENCE 128 #define SPEC_VOCAB_CHECK_START_TOKEN_ID 5 @@ -60,21 +67,20 @@ static bool common_speculative_are_compatible( const llama_vocab * vocab_dft = llama_model_get_vocab(model_dft); const auto vocab_type_tgt = llama_vocab_type(vocab_tgt); - LOG_DBG("%s: vocab_type tgt: %d\n", __func__, vocab_type_tgt); + SPC_DBG("vocab_type tgt: %d\n", vocab_type_tgt); const auto vocab_type_dft = llama_vocab_type(vocab_dft); - LOG_DBG("%s: vocab_type dft: %d\n", __func__, vocab_type_dft); + SPC_DBG("vocab_type dft: %d\n", vocab_type_dft); if (vocab_type_tgt != vocab_type_dft) { - LOG_WRN("%s: draft model vocab type must match target model to use speculation but " - "vocab_type_dft = %d while vocab_type_tgt = %d\n", __func__, vocab_type_dft, vocab_type_tgt); + SPC_WRN("draft model vocab type must match target model to use speculation but " + "vocab_type_dft = %d while vocab_type_tgt = %d\n", vocab_type_dft, vocab_type_tgt); return false; } if (llama_vocab_get_add_bos(vocab_tgt) != llama_vocab_get_add_bos(vocab_dft) || (llama_vocab_get_add_bos(vocab_tgt) && llama_vocab_bos(vocab_tgt) != llama_vocab_bos(vocab_dft))) { - LOG_WRN("%s: draft model bos tokens must match target model to use speculation. add: %d - %d, id: %d - %d)\n", - __func__, + SPC_WRN("draft model bos tokens must match target model to use speculation. add: %d - %d, id: %d - %d)\n", llama_vocab_get_add_bos(vocab_tgt), llama_vocab_get_add_bos(vocab_dft), llama_vocab_bos(vocab_tgt), llama_vocab_bos(vocab_dft)); return false; @@ -82,8 +88,7 @@ static bool common_speculative_are_compatible( if (llama_vocab_get_add_eos(vocab_tgt) != llama_vocab_get_add_eos(vocab_dft) || (llama_vocab_get_add_eos(vocab_tgt) && llama_vocab_eos(vocab_tgt) != llama_vocab_eos(vocab_dft))) { - LOG_WRN("%s: draft model eos tokens must match target model to use speculation. add: %d - %d, id: %d - %d)\n", - __func__, + SPC_WRN("draft model eos tokens must match target model to use speculation. add: %d - %d, id: %d - %d)\n", llama_vocab_get_add_eos(vocab_tgt), llama_vocab_get_add_eos(vocab_dft), llama_vocab_eos(vocab_tgt), llama_vocab_eos(vocab_dft)); return false; @@ -97,8 +102,8 @@ static bool common_speculative_are_compatible( : n_vocab_dft - n_vocab_tgt; if (vocab_diff > SPEC_VOCAB_MAX_SIZE_DIFFERENCE) { - LOG_DBG("%s: draft model vocab must closely match target model to use speculation but ", __func__); - LOG_DBG("target vocab size %d does not match draft vocab size %d - difference %d, max allowed %d\n", + SPC_DBG("draft model vocab must closely match target model to use speculation but " + "target vocab size %d does not match draft vocab size %d - difference %d, max allowed %d\n", n_vocab_tgt, llama_vocab_n_tokens(vocab_dft), vocab_diff, SPEC_VOCAB_MAX_SIZE_DIFFERENCE); return false; } @@ -108,8 +113,8 @@ static bool common_speculative_are_compatible( const char * token_text_dft = llama_vocab_get_text(vocab_dft, i); if (std::strcmp(token_text_tgt, token_text_dft) != 0) { - LOG_DBG("%s: draft model vocab must match target model to use speculation but ", __func__); - LOG_DBG("token %d content differs - target '%s', draft '%s'\n", i, + SPC_DBG("draft model vocab must match target model to use speculation but " + "token %d content differs - target '%s', draft '%s'\n", i, common_token_to_piece(vocab_tgt, i).c_str(), common_token_to_piece(vocab_dft, i).c_str()); return false; @@ -186,9 +191,9 @@ struct common_speculative_impl_draft_simple : public common_speculative_impl { auto * ctx_dft = this->params.ctx_dft; auto * ctx_tgt = this->params.ctx_tgt; - LOG_INF("%s: adding speculative implementation 'draft-simple'\n", __func__); - LOG_INF("%s: - n_max=%d, n_min=%d, p_min=%f\n", __func__, this->params.n_max, this->params.n_min, this->params.p_min); - LOG_INF("%s: - gpu_layers=%d, cache_k=%s, cache_v=%s, ctx_tgt=%s, ctx_dft=%s, devices=[%s]\n", __func__, + SPC_TRC("%s", "adding speculative implementation 'draft-simple'\n"); + SPC_TRC("- n_max=%d, n_min=%d, p_min=%f\n", this->params.n_max, this->params.n_min, this->params.p_min); + SPC_TRC("- gpu_layers=%d, cache_k=%s, cache_v=%s, ctx_tgt=%s, ctx_dft=%s, devices=[%s]\n", this->params.n_gpu_layers, ggml_type_name(this->params.cache_type_k), ggml_type_name(this->params.cache_type_v), @@ -228,16 +233,16 @@ struct common_speculative_impl_draft_simple : public common_speculative_impl { } const bool vocab_cmpt = common_speculative_are_compatible(llama_get_model(ctx_tgt), llama_get_model(ctx_dft)); - LOG_DBG("%s: vocab_cmpt = %d\n", __func__, vocab_cmpt); + SPC_DBG("vocab_cmpt = %d\n", vocab_cmpt); if (!vocab_cmpt) { - LOG_ERR("%s: the target and draft vocabs are not compatible\n", __func__); + SPC_ERR("%s", "the target and draft vocabs are not compatible\n"); throw std::runtime_error("draft model vocab type must match target model to use speculation"); } if (n_seq != llama_n_seq_max(ctx_dft)) { - LOG_ERR("%s: n_seq mismatch: %d != %d\n", __func__, n_seq, llama_n_seq_max(ctx_dft)); + SPC_ERR("n_seq mismatch: %d != %d\n", n_seq, llama_n_seq_max(ctx_dft)); throw std::runtime_error("the draft model number of sequences is incompatible with the speculative n_seq"); } @@ -257,7 +262,7 @@ struct common_speculative_impl_draft_simple : public common_speculative_impl { const int ret = llama_decode(ctx_dft, batch); if (ret != 0) { - LOG_ERR("%s: failed to decode draft batch, ret = %d\n", __func__, ret); + SPC_ERR("failed to decode draft batch, ret = %d\n", ret); return false; } @@ -290,7 +295,7 @@ struct common_speculative_impl_draft_simple : public common_speculative_impl { int ret = llama_decode(ctx_dft, batch); if (ret != 0) { - LOG_WRN("%s: llama_decode returned %d\n", __func__, ret); + SPC_ERR("llama_decode returned %d\n", ret); return; } @@ -314,7 +319,7 @@ struct common_speculative_impl_draft_simple : public common_speculative_impl { const auto * cur_p = common_sampler_get_candidates(smpl, true); for (int k = 0; k < std::min(3, (int) cur_p->size); ++k) { - LOG_DBG(" - seq_id %d, draft candidate %3d, pos %3d: %6d (%8.3f) '%s'\n", + SPC_DBG(" - seq_id %d, draft candidate %3d, pos %3d: %6d (%8.3f) '%s'\n", seq_id, k, i, cur_p->data[k].id, cur_p->data[k].p, common_token_to_piece(ctx_dft, cur_p->data[k].id).c_str()); } @@ -354,7 +359,7 @@ struct common_speculative_impl_draft_simple : public common_speculative_impl { // evaluate the drafted tokens on the draft model ret = llama_decode(ctx_dft, batch); if (ret != 0) { - LOG_WRN("%s: llama_decode[%d] returned %d\n", __func__, i, ret); + SPC_ERR("llama_decode[%d] returned %d\n", i, ret); break; } @@ -449,8 +454,8 @@ struct common_speculative_impl_draft_eagle3 : public common_speculative_impl { : common_speculative_impl(COMMON_SPECULATIVE_TYPE_DRAFT_EAGLE3, n_seq) , params(params.draft) { - LOG_INF("%s: adding speculative implementation 'draft-eagle3'\n", __func__); - LOG_INF("%s: - n_max=%d, n_min=%d, p_min=%f, backend_sampling=%d\n", __func__, params.draft.n_max, params.draft.n_min, params.draft.p_min, (int) params.draft.backend_sampling); + SPC_TRC("%s", "adding speculative implementation 'draft-eagle3'\n"); + SPC_TRC("- n_max=%d, n_min=%d, p_min=%f, backend_sampling=%d\n", params.draft.n_max, params.draft.n_min, params.draft.p_min, (int) params.draft.backend_sampling); auto * ctx_tgt = this->params.ctx_tgt; auto * ctx_dft = this->params.ctx_dft; @@ -493,7 +498,7 @@ struct common_speculative_impl_draft_eagle3 : public common_speculative_impl { llama_sampler_chain_add(chain, llama_sampler_init_top_k(10)); if (!llama_set_sampler(ctx_dft, seq_id, chain)) { - LOG_WRN("%s: backend offload failed for seq_id=%d; using CPU sampler\n", __func__, (int) seq_id); + SPC_WRN("backend offload failed for seq_id=%d; using CPU sampler\n", (int) seq_id); llama_sampler_free(chain); chain = nullptr; } @@ -548,9 +553,9 @@ struct common_speculative_impl_draft_eagle3 : public common_speculative_impl { auto * ctx_dft = this->params.ctx_dft; const llama_pos pos_max = llama_memory_seq_pos_max(llama_get_memory(ctx_dft), seq_id); if (pos_max < N - 2) { - LOG_WRN("%s: ctx_dft pos_max=%d < N-2=%d — process() did not run on every prefill ubatch. " + SPC_WRN("ctx_dft pos_max=%d < N-2=%d — process() did not run on every prefill ubatch. " "Drafts may degrade.\n", - __func__, (int) pos_max, N - 2); + (int) pos_max, N - 2); } } @@ -621,8 +626,8 @@ struct common_speculative_impl_draft_eagle3 : public common_speculative_impl { }; const int32_t rc = llama_encode(ctx_dft, enc_batch); if (rc != 0) { - LOG_ERR("%s: llama_encode(ctx_dft) failed rc=%d (n_tokens=%d, offset=%d)\n", - __func__, rc, (int) n_chunk, (int) i); + SPC_ERR("llama_encode(ctx_dft) failed rc=%d (n_tokens=%d, offset=%d)\n", + rc, (int) n_chunk, (int) i); return false; } @@ -692,8 +697,8 @@ struct common_speculative_impl_draft_eagle3 : public common_speculative_impl { if (batch.n_tokens > 0) { const int32_t rc = llama_decode(ctx_dft, batch); if (rc != 0) { - LOG_ERR("%s: llama_decode(ctx_dft) failed rc=%d (n_tokens=%d, ubatch_pos[0]=%d)\n", - __func__, rc, (int) batch.n_tokens, (int) batch_in.pos[0]); + SPC_ERR("llama_decode(ctx_dft) failed rc=%d (n_tokens=%d, ubatch_pos[0]=%d)\n", + rc, (int) batch.n_tokens, (int) batch_in.pos[0]); return false; } } @@ -744,7 +749,7 @@ struct common_speculative_impl_draft_eagle3 : public common_speculative_impl { int ret = llama_decode(ctx_dft, batch); if (ret != 0) { - LOG_WRN("%s: llama_decode returned %d\n", __func__, ret); + SPC_ERR("llama_decode returned %d\n", ret); return; } @@ -770,7 +775,7 @@ struct common_speculative_impl_draft_eagle3 : public common_speculative_impl { const auto * cur_p = common_sampler_get_candidates(smpl, true); for (int k = 0; k < std::min(3, (int) cur_p->size); ++k) { - LOG_DBG(" - seq_id %d, draft candidate %3d, pos %3d: %6d (%8.3f) '%s'\n", + SPC_DBG(" - seq_id %d, draft candidate %3d, pos %3d: %6d (%8.3f) '%s'\n", seq_id, k, i, cur_p->data[k].id, cur_p->data[k].p, common_token_to_piece(ctx_dft, cur_p->data[k].id).c_str()); } @@ -809,7 +814,7 @@ struct common_speculative_impl_draft_eagle3 : public common_speculative_impl { ret = llama_decode(ctx_dft, batch); if (ret != 0) { - LOG_WRN("%s: llama_decode[%d] returned %d\n", __func__, i, ret); + SPC_ERR("llama_decode[%d] returned %d\n", i, ret); break; } @@ -942,9 +947,9 @@ struct common_speculative_impl_draft_mtp : public common_speculative_impl { "MTP input row width must match the target h_nextn width"); n_mtp_layers = std::max(1, (int) llama_model_n_layer_nextn(llama_get_model(ctx_dft))); - LOG_INF("%s: adding speculative implementation 'draft-mtp'\n", __func__); - LOG_INF("%s: - n_max=%d, n_min=%d, p_min=%.2f, n_embd=%d, backend_sampling=%d\n", __func__, this->params.n_max, this->params.n_min, this->params.p_min, n_embd, (int) this->params.backend_sampling); - LOG_INF("%s: - gpu_layers=%d, cache_k=%s, cache_v=%s, ctx_tgt=%s, ctx_dft=%s, devices=[%s]\n", __func__, + SPC_TRC("%s", "adding speculative implementation 'draft-mtp'\n"); + SPC_TRC("- n_max=%d, n_min=%d, p_min=%.2f, n_embd=%d, backend_sampling=%d\n", this->params.n_max, this->params.n_min, this->params.p_min, n_embd, (int) this->params.backend_sampling); + SPC_TRC("- gpu_layers=%d, cache_k=%s, cache_v=%s, ctx_tgt=%s, ctx_dft=%s, devices=[%s]\n", this->params.n_gpu_layers, ggml_type_name(this->params.cache_type_k), ggml_type_name(this->params.cache_type_v), @@ -975,7 +980,7 @@ struct common_speculative_impl_draft_mtp : public common_speculative_impl { llama_sampler_chain_add(chain, llama_sampler_init_top_k(10)); if (!llama_set_sampler(ctx_dft, seq_id, chain)) { - LOG_WRN("%s: backend offload failed for seq_id=%d; using CPU sampler\n", __func__, (int) seq_id); + SPC_WRN("backend offload failed for seq_id=%d; using CPU sampler\n", (int) seq_id); llama_sampler_free(chain); chain = nullptr; } @@ -1038,11 +1043,11 @@ struct common_speculative_impl_draft_mtp : public common_speculative_impl { const llama_pos pos_max = llama_memory_seq_pos_max(llama_get_memory(ctx_dft), seq_id); if (pos_max < N - 1 && !is_mem_shared) { - LOG_WRN("%s: ctx_dft pos_max=%d < N-1=%d - " + SPC_WRN("ctx_dft pos_max=%d < N-1=%d - " "process() hook may not have run on every prefill ubatch " "(need_embd / logits=1 on every prompt position?). " "Drafts may degrade.\n", - __func__, (int) pos_max, N - 1); + (int) pos_max, N - 1); } } @@ -1128,8 +1133,8 @@ struct common_speculative_impl_draft_mtp : public common_speculative_impl { const int32_t rc = llama_decode(ctx_dft, batch); if (rc != 0) { - LOG_ERR("%s: llama_decode(ctx_dft) head=%d failed rc=%d (pos=%d)\n", - __func__, head, (int) rc, (int) batch_in.pos[0]); + SPC_ERR("llama_decode(ctx_dft) head=%d failed rc=%d (pos=%d)\n", + head, (int) rc, (int) batch_in.pos[0]); ok = false; break; } @@ -1217,7 +1222,7 @@ struct common_speculative_impl_draft_mtp : public common_speculative_impl { int ret = llama_decode(ctx_dft, batch); if (ret != 0) { - LOG_WRN("%s: llama_decode[%d] returned %d\n", __func__, i, ret); + SPC_ERR("llama_decode[%d] returned %d\n", i, ret); break; } @@ -1239,7 +1244,7 @@ struct common_speculative_impl_draft_mtp : public common_speculative_impl { const auto * cur_p = common_sampler_get_candidates(smpl, true); for (int k = 0; k < std::min(3, (int) cur_p->size); ++k) { - LOG_DBG(" - seq_id %d, draft candidate %3d, pos %3d: %6d (%8.3f) '%s'\n", + SPC_DBG(" - seq_id %d, draft candidate %3d, pos %3d: %6d (%8.3f) '%s'\n", seq_id, k, i, cur_p->data[k].id, cur_p->data[k].p, common_token_to_piece(ctx_dft, cur_p->data[k].id).c_str()); } @@ -1353,8 +1358,8 @@ struct common_speculative_impl_ngram_simple : public common_speculative_impl { , params(params.ngram_simple) , config(config) { - LOG_INF("%s: adding speculative implementation 'ngram-simple'\n", __func__); - LOG_INF("%s: - size_n=%d, size_m=%d, min_hits=%d\n", __func__, + SPC_TRC("%s", "adding speculative implementation 'ngram-simple'\n"); + SPC_TRC("- size_n=%d, size_m=%d, min_hits=%d\n", this->params.size_n, this->params.size_m, this->params.min_hits); } @@ -1403,8 +1408,8 @@ struct common_speculative_impl_ngram_map_k : public common_speculative_impl { this->config.push_back(config); } - LOG_INF("%s: adding speculative implementation '%s'\n", __func__, common_speculative_type_to_str(this->type).c_str()); - LOG_INF("%s: - size_key=%d, size_value=%d, key_only=%d, min_hits=%d\n", __func__, + SPC_TRC("adding speculative implementation '%s'\n", common_speculative_type_to_str(this->type).c_str()); + SPC_TRC("- size_key=%d, size_value=%d, key_only=%d, min_hits=%d\n", config.size_key, config.size_value, config.key_only, config.min_hits); } @@ -1478,15 +1483,15 @@ struct common_speculative_impl_ngram_mod : public common_speculative_impl { , verbose(std::getenv("LLAMA_TRACE") != nullptr) { static_assert(sizeof(llama_token) == sizeof(common_ngram_mod::entry_t)); - LOG_INF("%s: adding speculative implementation 'ngram-mod'\n", __func__); - LOG_INF("%s: - n_match=%d, n_max=%d, n_min=%d\n", __func__, + SPC_TRC("%s", "adding speculative implementation 'ngram-mod'\n"); + SPC_TRC("- n_match=%d, n_max=%d, n_min=%d\n", this->params.n_match, this->params.n_max, this->params.n_min); - LOG_INF("%s: - mod size=%zu (%.3f MB)\n", __func__, + SPC_TRC("- mod size=%zu (%.3f MB)\n", mod.size(), (float)(mod.size_bytes())/1024/1024); if (this->params.n_match < 16) { - LOG_WRN("%s: ngram_mod n_match=%d is too small - poor quality is possible, " - "see: https://github.com/ggml-org/llama.cpp/pull/19164\n", __func__, this->params.n_match); + SPC_WRN("ngram_mod n_match=%d is too small - poor quality is possible, " + "see: https://github.com/ggml-org/llama.cpp/pull/19164\n", this->params.n_match); } sinfos.resize(n_seq); @@ -1510,11 +1515,11 @@ struct common_speculative_impl_ngram_mod : public common_speculative_impl { sinfo.i_last = prompt.size() - n; const double f = (double)mod.get_used() / (double)mod.size(); - LOG_INF("%s: ngram_mod occupancy = %zu/%zu (%.2f)\n", __func__, mod.get_used(), mod.size(), f); + SPC_TRC("ngram_mod occupancy = %zu/%zu (%.2f)\n", mod.get_used(), mod.size(), f); constexpr double f_thold = 0.25; if (f > f_thold) { - LOG_WRN("%s: ngram_mod occupancy %.2f exceeds threshold (%.2f) - resetting\n", __func__, f, f_thold); + SPC_WRN("ngram_mod occupancy %.2f exceeds threshold (%.2f) - resetting\n", f, f_thold); mod.reset(); } @@ -1608,7 +1613,7 @@ struct common_speculative_impl_ngram_mod : public common_speculative_impl { sinfo.n_low++; if (sinfo.n_low >= 5) { if (verbose) { - LOG_WRN("%s: low acceptance streak (%d) - resetting ngram_mod\n", __func__, sinfo.n_low); + SPC_TRC("low acceptance streak (%d) - resetting ngram_mod\n", sinfo.n_low); } mod.reset(); @@ -1658,8 +1663,8 @@ struct common_speculative_impl_ngram_cache : public common_speculative_impl { , save_dynamic(save_dynamic) , save_static(save_static) { - LOG_INF("%s: adding speculative implementation 'ngram-cache'\n", __func__); - LOG_INF("%s: - n_draft=%d, cache_static=%s, cache_dynamic=%s\n", __func__, + SPC_TRC("%s", "adding speculative implementation 'ngram-cache'\n"); + SPC_TRC("- n_draft=%d, cache_static=%s, cache_dynamic=%s\n", n_draft, path_static.empty() ? "none" : path_static.c_str(), path_dynamic.empty() ? "none" : path_dynamic.c_str()); @@ -1674,7 +1679,7 @@ struct common_speculative_impl_ngram_cache : public common_speculative_impl { sinfo.ngram_cache_static = ngram_cache_static; } } catch (...) { - LOG_ERR("failed to open static lookup cache: %s", path_static.c_str()); + SPC_ERR("failed to open static lookup cache: %s", path_static.c_str()); GGML_ABORT("Couldn't read static lookup cache"); } } @@ -1687,7 +1692,7 @@ struct common_speculative_impl_ngram_cache : public common_speculative_impl { sinfo.ngram_cache_dynamic = ngram_cache_dynamic; } } catch (...) { - LOG_ERR("failed to open dynamic lookup cache: %s", path_dynamic.c_str()); + SPC_ERR("failed to open dynamic lookup cache: %s", path_dynamic.c_str()); GGML_ABORT("Couldn't read dynamic lookup cache"); } } @@ -2034,7 +2039,7 @@ common_speculative * common_speculative_init(common_params_speculative & params, } if (impls.empty()) { - LOG_WRN("%s: no implementations specified for speculative decoding\n", __func__); + SPC_TRC("%s", "no implementations specified for speculative decoding\n"); return nullptr; } @@ -2161,13 +2166,13 @@ void common_speculative_draft(common_speculative * spec) { if (dp.n_max > 0) { if (!result.empty() && (int) result.size() > dp.n_max) { - LOG_DBG("%s: truncating draft to %d tokens\n", __func__, dp.n_max); + SPC_DBG("truncating draft to %d tokens\n", dp.n_max); result.resize(dp.n_max); } } if (!result.empty()) { - LOG_DBG("%s: called impl %s, hist size = %zu, call_count = %zu, gen = %zu\n", __func__, + SPC_DBG("called impl %s, hist size = %zu, call_count = %zu, gen = %zu\n", common_speculative_type_to_str(impl.get()->type).c_str(), dp.prompt->size(), impl.get()->n_call_draft, result.size()); @@ -2291,7 +2296,7 @@ void common_speculative_print_stats(const common_speculative * spec) { str_stats = ", #mean acc len = " + oss.str() + ", #acc rate/pos = (" + tmp.str() + ")"; } - LOG_INF("statistics %16s: #calls(b,g,a) = %4zu %6zu %6zu, #gen drafts = %6zu, #acc drafts = %5zu, #gen tokens = %6zu, #acc tokens = %5zu%s%s\n", + SPC_TRC("statistics %16s: #calls(b,g,a) = %4zu %6zu %6zu, #gen drafts = %6zu, #acc drafts = %5zu, #gen tokens = %6zu, #acc tokens = %5zu%s%s\n", common_speculative_type_to_str(impl->type).c_str(), impl->n_call_begin, impl->n_call_draft, impl->n_call_accept, impl->n_gen_drafts, diff --git a/src/llama-context.cpp b/src/llama-context.cpp index 220240ea95..9f8a8fdb86 100644 --- a/src/llama-context.cpp +++ b/src/llama-context.cpp @@ -256,7 +256,7 @@ llama_context::llama_context( LLAMA_LOG_INFO("%s: n_outputs_max = %u\n", __func__, cparams.n_outputs_max); if (cparams.n_ctx_seq < hparams.n_ctx_train) { - LLAMA_LOG_WARN("%s: n_ctx_seq (%u) < n_ctx_train (%u) -- the full capacity of the model will not be utilized\n", + LLAMA_LOG_INFO("%s: n_ctx_seq (%u) < n_ctx_train (%u) -- the full capacity of the model will not be utilized\n", __func__, cparams.n_ctx_seq, hparams.n_ctx_train); } diff --git a/tools/server/server-context.cpp b/tools/server/server-context.cpp index 5c33a418f5..bb1c236cbf 100644 --- a/tools/server/server-context.cpp +++ b/tools/server/server-context.cpp @@ -106,7 +106,6 @@ struct server_batch { if ((int32_t)tokens.size() >= n_tokens_alloc) { return false; } - // LOG_INF("adding token to batch: slot=%d, token=%d, pos=%d, output=%d\n", id_slot, token, pos, output); tokens.push_back({ id_slot, token, pos, output }); return true; } @@ -228,7 +227,7 @@ struct server_slot { const size_t cur_size = cur_size_tgt + cur_size_dft; - SRV_WRN(" - saving prompt with length %d, total state size = %.3f MiB (draft: %.3f MiB)\n", + SRV_TRC(" - saving prompt with length %d, total state size = %.3f MiB (draft: %.3f MiB)\n", (int) prompt.tokens.size(), cur_size / (1024.0 * 1024.0), cur_size_dft / (1024.0 * 1024.0)); auto * cur = prompt_cache.alloc(prompt, cur_size_tgt, cur_size_dft); @@ -258,7 +257,7 @@ struct server_slot { GGML_ASSERT(!is_processing()); } - SLT_INF(*this, "clearing prompt with %zu tokens\n", prompt.tokens.size()); + SLT_TRC(*this, "clearing prompt with %zu tokens\n", prompt.tokens.size()); common_context_seq_rm(ctx_tgt, id, -1, -1); if (ctx_dft) { @@ -627,8 +626,10 @@ struct server_slot { } SLT_INF(*this, - "draft acceptance = %0.5f (%5d accepted / %5d generated), mean acceptance length = %5.2f, acceptance rate per position = (%s)\n", - draft_ratio, n_draft_accepted, n_draft_total, mean_acc_len, acceptance_rates_per_pos.c_str()); + "draft acceptance = %0.5f (%5d accepted / %5d generated), mean len = %5.2f\n", + draft_ratio, n_draft_accepted, n_draft_total, mean_acc_len); + SLT_TRC(*this, + " acc per pos = (%s)\n", acceptance_rates_per_pos.c_str()); } common_speculative_print_stats(spec); @@ -771,7 +772,7 @@ struct server_slot { } // TODO @ngxson : move this log line to debug when it become more stable - SLT_INF(*this, "encoding mtmd batch from idx = %zu, n_chunks = %d\n", idx, n_added); + SLT_TRC(*this, "encoding mtmd batch from idx = %zu, n_chunks = %d\n", idx, n_added); res = mtmd_batch_encode(mbatch.get()); if (res != 0) { @@ -1032,7 +1033,8 @@ private: } - SRV_INF("loading model '%s'\n", params.model.path.c_str()); + SRV_INF("loading model '%s'\n", params.model.get_name().c_str()); + SRV_TRC("local path '%s'\n", params.model.path.c_str()); std::string & mmproj_path = params_base.mmproj.path; mtmd_context_params mparams = mtmd_context_params_default(); @@ -1061,7 +1063,7 @@ private: for (auto & [dev, size] : mmproj_mem) { total += size; } - SRV_INF("[mtmd] estimated worst-case memory usage of mmproj is %.2f MiB (took %.2f ms)\n", total / (1024.0 * 1024.0), t_elapsed / 1000.0); + SRV_TRC("[mtmd] estimated worst-case memory usage of mmproj is %.2f MiB (took %.2f ms)\n", total / (1024.0 * 1024.0), t_elapsed / 1000.0); GGML_ASSERT(!params_base.fit_params_target.empty()); for (auto & [dev, size] : mmproj_mem) { for (size_t i = 0; i < ggml_backend_dev_count(); i++) { @@ -1141,7 +1143,7 @@ private: } } } - SRV_INF("[spec] estimated memory usage of %s is %.2f MiB\n", + SRV_TRC("[spec] estimated memory usage of %s is %.2f MiB\n", has_draft ? "draft model" : "MTP context", total / (1024.0 * 1024.0)); } catch (const std::exception & e) { @@ -1177,7 +1179,7 @@ private: // TODO speculative: move to common/speculative.cpp? const auto & params_spec = params_base.speculative.draft; - SRV_INF("loading draft model '%s'\n", params_spec.mparams.path.c_str()); + SRV_TRC("loading draft model '%s'\n", params_spec.mparams.path.c_str()); auto params_dft = params_base; @@ -1229,7 +1231,7 @@ private: // no new model load, so we simply report 0.0 and 1.0 progress load_progress_callback(0.0f, &load_progress_spec); - SRV_INF("creating MTP draft context against the target model '%s'\n", + SRV_TRC("creating MTP draft context against the target model '%s'\n", params_base.model.path.c_str()); auto cparams_mtp = common_context_params_to_llama(params_base); @@ -1303,9 +1305,6 @@ private: // Necessary similarity of prompt for slot selection slot_prompt_similarity = params_base.slot_prompt_similarity; - // setup slots - SRV_INF("initializing slots, n_slots = %d\n", params_base.n_parallel); - const int n_ctx_train = llama_model_n_ctx_train(model_tgt); int n_ctx_slot = llama_n_ctx_seq(ctx_tgt); @@ -1322,9 +1321,13 @@ private: } if (ctx_tgt_seq_rm_type == COMMON_CONTEXT_SEQ_RM_TYPE_FULL) { - SRV_WRN("%s", "speculative decoding will use checkpoints\n"); + SRV_TRC("%s", "speculative decoding will use checkpoints\n"); } + // setup slots + SRV_INF("initializing, n_slots = %d, n_ctx_slot = %d, kv_unified = '%s'\n", + params_base.n_parallel, n_ctx_slot, params_base.kv_unified ? "true" : "false"); + // initialize slots for (int i = 0; i < params_base.n_parallel; i++) { slots.emplace_back(); @@ -1344,7 +1347,7 @@ private: } if (spec) { - SRV_INF("%s", "speculative decoding context initialized\n"); + SRV_TRC("%s", "speculative decoding context initialized\n"); } else { ctx_dft.reset(); } @@ -1361,7 +1364,7 @@ private: slot.mctx = mctx; slot.prompt.tokens.has_mtmd = mctx != nullptr; - SLT_INF(slot, "new slot, n_ctx = %d\n", slot.n_ctx); + SLT_TRC(slot, "new slot, n_ctx = %d\n", slot.n_ctx); slot.callback_on_release = [this](int id_slot) { queue_tasks.pop_deferred_task(id_slot); @@ -1397,23 +1400,23 @@ private: if (params_base.cache_ram_mib != 0) { if (params_base.cache_ram_mib < 0) { - SRV_INF("prompt cache is enabled, size limit: %s\n", "no limit"); + SRV_TRC("prompt cache is enabled, size limit: %s\n", "no limit"); } else { - SRV_INF("prompt cache is enabled, size limit: %d MiB\n", params_base.cache_ram_mib); + SRV_TRC("prompt cache is enabled, size limit: %d MiB\n", params_base.cache_ram_mib); } - SRV_INF("%s", "use `--cache-ram 0` to disable the prompt cache\n"); + SRV_TRC("%s", "use `--cache-ram 0` to disable the prompt cache\n"); prompt_cache = std::make_unique(params_base.cache_ram_mib, n_ctx); } else { - SRV_INF("%s", "prompt cache is disabled - use `--cache-ram N` to enable it\n"); + SRV_TRC("%s", "prompt cache is disabled - use `--cache-ram N` to enable it\n"); } - SRV_INF("%s", "for more info see https://github.com/ggml-org/llama.cpp/pull/16391\n"); + SRV_TRC("%s", "for more info see https://github.com/ggml-org/llama.cpp/pull/16391\n"); if (params_base.n_ctx_checkpoints > 0) { - SRV_INF("context checkpoints enabled, max = %d, min spacing = %d\n", + SRV_TRC("context checkpoints enabled, max = %d, min spacing = %d\n", params_base.n_ctx_checkpoints, params_base.checkpoint_min_step); } else { - SRV_INF("%s", "context checkpoints disabled\n"); + SRV_TRC("%s", "context checkpoints disabled\n"); } if (!params_base.model_alias.empty()) { @@ -1470,11 +1473,11 @@ private: params_base.cache_idle_slots = false; } else { if (params_base.kv_unified) { - SRV_INF("%s", "idle slots will be saved to prompt cache and cleared upon starting a new task\n"); + SRV_TRC("%s", "idle slots will be saved to prompt cache and cleared upon starting a new task\n"); } else { // without a unified KV cache, clearing a slot frees no reusable room, so we only // publish a RAM-cache copy of idle slots (their KV stays in VRAM) [TAG_IDLE_SLOT_CLEAR] - SRV_INF("%s", "idle slots will be saved to prompt cache upon starting a new task\n"); + SRV_TRC("%s", "idle slots will be saved to prompt cache upon starting a new task\n"); } SRV_DBG("%s", "__TEST_TAG_CACHE_IDLE_SLOTS_ENABLED__\n"); } @@ -1500,7 +1503,7 @@ private: try { chat_templates = common_chat_templates_init(model_tgt, params_base.chat_template); - LOG_INF("%s: chat template, example_format: '%s'\n", __func__, + SRV_TRC("%s: chat template, example_format: '%s'\n", __func__, common_chat_format_example(chat_templates.get(), params_base.use_jinja, params_base.default_template_kwargs).c_str()); } catch (const std::exception & e) { @@ -1515,7 +1518,7 @@ private: // 2. The chat template supports it const bool template_supports_thinking = params_base.use_jinja && common_chat_templates_support_enable_thinking(chat_templates.get()); const bool enable_thinking = params_base.enable_reasoning != 0 && template_supports_thinking; - SRV_INF("%s: chat template, thinking = %d\n", __func__, enable_thinking); + SRV_TRC("%s: chat template, thinking = %d\n", __func__, enable_thinking); // IMPORTANT: chat_params is reused across sleeping / resuming states, // never store llama_context/llama_model pointers in chat_params, @@ -1658,7 +1661,7 @@ private: update_cache = update_cache && task.type == SERVER_TASK_TYPE_COMPLETION; if (update_cache) { - SRV_INF("%s", "updating prompt cache\n"); + SRV_TRC("%s", "updating prompt cache\n"); const int64_t t_start = ggml_time_us(); @@ -1670,7 +1673,7 @@ private: prompt_cache->update(); - SRV_INF("prompt cache update took %.2f ms\n", (ggml_time_us() - t_start) / 1000.0); + SRV_TRC("prompt cache update took %.2f ms\n", (ggml_time_us() - t_start) / 1000.0); } } @@ -2290,7 +2293,7 @@ private: int id_parent = parent_task.id; - SRV_INF("launching slots for parent task id_task = %d with %zu child tasks\n", id_parent, parent_task.child_tasks.size()); + SRV_TRC("launching slots for parent task id_task = %d with %zu child tasks\n", id_parent, parent_task.child_tasks.size()); // to be called in case of failure to release all launched slots auto release_slots = [this, id_parent]() { @@ -2351,7 +2354,7 @@ private: // stash the draft's speculative state with the checkpoint common_speculative_get_state(spec.get(), slot.id, cur.data_spec); - SLT_INF(slot, + SLT_TRC(slot, "created context checkpoint %d of %d (pos_min = %d, pos_max = %d, n_tokens = %" PRId64 ", size = %.3f MiB)\n", (int) slot.prompt.checkpoints.size(), params_base.n_ctx_checkpoints, cur.pos_min, cur.pos_max, cur.n_tokens, (float) cur.size() / 1024 / 1024); @@ -2415,7 +2418,7 @@ private: if (params_base.cache_idle_slots) { for (auto & slot : slots) { if (!slot.is_processing()) { - SLT_INF(slot, "%s", "saving idle slot to prompt cache\n"); + SLT_TRC(slot, "%s", "saving idle slot to prompt cache\n"); if (slot.prompt_save(*prompt_cache)) { SLT_DBG(slot, "%s", "__TEST_TAG_CACHE_IDLE_SLOT__\n"); @@ -2671,7 +2674,7 @@ private: auto new_loras = construct_lora_list(task.set_lora); // logging for (size_t i = 0; i < new_loras.size(); ++i) { - SRV_INF("set lora adapter idx=%zu scale=%f\n", i, new_loras[i].scale); + SRV_TRC("set lora adapter idx=%zu scale=%f\n", i, new_loras[i].scale); } // TODO @ngxson : make lora_adapters a dedicated member of server_context params_base.lora_adapters = new_loras; @@ -2771,7 +2774,7 @@ private: } if (all_idle) { - SRV_INF("%s", "all slots are idle\n"); + SRV_TRC("%s", "all slots are idle\n"); return; // skip further processing } else { @@ -3287,10 +3290,9 @@ private: const auto it = std::find_if( slot.prompt.checkpoints.rbegin(), slot.prompt.checkpoints.rend(), - [&, func_name = __func__](const auto & cur) { + [&](const auto & cur) { // guarantee that a checkpoint will result in at least one token being processed [TAG_PROMPT_LOGITS] - LOG_INF("slot %12.*s: id %2d | task %d | Checking checkpoint with [%d, %d] against %d...\n", 12, - func_name, (slot).id, ((slot).task ? (slot).task->id : -1), cur.pos_min, cur.pos_max, pos_min_thold); + SLT_TRC(slot, "checking checkpoint with [%d, %d] against %d...\n", cur.pos_min, cur.pos_max, pos_min_thold); // workaround for [TAG_CHECKPOINTS_FIX_POS_MIN] if (cur.pos_max > pos_next) { return false; @@ -3310,11 +3312,11 @@ private: pos_next = std::min(pos_next, std::max(it->pos_min + 1, it->pos_max)); n_past = std::min(slot.prompt.tokens.size_up_to_pos(pos_next), (size_t) it->n_tokens); - SLT_WRN(slot, "restored context checkpoint (pos_min = %d, pos_max = %d, n_tokens = %" PRId64 ", n_past = %d, size = %.3f MiB)\n", it->pos_min, it->pos_max, it->n_tokens, n_past, (float) it->size() / 1024 / 1024); + SLT_TRC(slot, "restored context checkpoint (pos_min = %d, pos_max = %d, n_tokens = %" PRId64 ", n_past = %d, size = %.3f MiB)\n", it->pos_min, it->pos_max, it->n_tokens, n_past, (float) it->size() / 1024 / 1024); } if (do_reset) { - SLT_WRN(slot, "forcing full prompt re-processing due to lack of cache data (likely due to SWA or hybrid/recurrent memory, see %s)\n", + SLT_TRC(slot, "forcing full prompt re-processing due to lack of cache data (likely due to SWA or hybrid/recurrent memory, see %s)\n", "https://github.com/ggml-org/llama.cpp/pull/13194#issuecomment-2868343055"); pos_next = 0; n_past = 0; @@ -3327,7 +3329,7 @@ private: for (auto it = slot.prompt.checkpoints.begin(); it != slot.prompt.checkpoints.end();) { const auto & cur = *it; if (cur.pos_max > pos_next) { - SLT_WRN(slot, "erased invalidated context checkpoint (pos_min = %d, pos_max = %d, n_tokens = %" PRId64 ", n_swa = %d, pos_next = %d, size = %.3f MiB)\n", cur.pos_min, cur.pos_max, cur.n_tokens, n_swa, pos_next, (float) cur.size() / 1024 / 1024); + SLT_TRC(slot, "erased invalidated context checkpoint (pos_min = %d, pos_max = %d, n_tokens = %" PRId64 ", n_swa = %d, pos_next = %d, size = %.3f MiB)\n", cur.pos_min, cur.pos_max, cur.n_tokens, n_swa, pos_next, (float) cur.size() / 1024 / 1024); it = slot.prompt.checkpoints.erase(it); } else { ++it; @@ -3674,7 +3676,7 @@ private: // all children slots should already launched by launch_slots_with_parent_task() // copy state to the child slots for (auto & child : children) { - SLT_INF(slot, " - copying state to child %d\n", child->id); + SLT_TRC(slot, " - copying state to child %d\n", child->id); GGML_ASSERT(child->state == SLOT_STATE_WAIT_OTHER); diff --git a/tools/server/server-http.cpp b/tools/server/server-http.cpp index 82f34edac0..21bed64c92 100644 --- a/tools/server/server-http.cpp +++ b/tools/server/server-http.cpp @@ -83,7 +83,7 @@ bool server_http_context::init(const common_params & params) { hostname = params.hostname; if (gcp.enabled) { - SRV_INF("Google Cloud Platform compat: health route = %s, predict route = %s, port = %d\n", gcp.path_health.c_str(), gcp.path_predict.c_str(), gcp.port); + SRV_TRC("Google Cloud Platform compat: health route = %s, predict route = %s, port = %d\n", gcp.path_health.c_str(), gcp.path_predict.c_str(), gcp.port); if (port != gcp.port) { SRV_WRN("Google Cloud Platform compat: overriding server port %d with AIP_HTTP_PORT %d\n", port, gcp.port); @@ -96,13 +96,13 @@ bool server_http_context::init(const common_params & params) { #ifdef CPPHTTPLIB_OPENSSL_SUPPORT if (!params.ssl_file_key.empty() && !params.ssl_file_cert.empty()) { - SRV_INF("running with SSL: key = %s, cert = %s\n", params.ssl_file_key.c_str(), params.ssl_file_cert.c_str()); + SRV_TRC("running with SSL: key = %s, cert = %s\n", params.ssl_file_key.c_str(), params.ssl_file_cert.c_str()); srv = std::make_unique( params.ssl_file_cert.c_str(), params.ssl_file_key.c_str() ); is_ssl = true; } else { - SRV_INF("%s", "running without SSL\n"); + SRV_TRC("%s", "running without SSL\n"); srv = std::make_unique(); } #else @@ -165,9 +165,9 @@ bool server_http_context::init(const common_params & params) { if (params.api_keys.size() == 1) { const auto key = params.api_keys[0]; const std::string substr = key.substr(std::max(static_cast(key.length() - 4), 0)); - SRV_INF("api_keys: ****%s\n", substr.c_str()); + SRV_TRC("api_keys: ****%s\n", substr.c_str()); } else if (params.api_keys.size() > 1) { - SRV_INF("api_keys: %zu keys loaded\n", params.api_keys.size()); + SRV_TRC("api_keys: %zu keys loaded\n", params.api_keys.size()); } // @@ -293,7 +293,7 @@ bool server_http_context::init(const common_params & params) { // +4 threads for monitoring, health and some threads reserved for MCP and other tasks in the future n_threads_http = std::max(params.n_parallel + 4, static_cast(std::thread::hardware_concurrency() - 1)); } - SRV_INF("using %d threads for HTTP server\n", n_threads_http); + SRV_TRC("using %d threads for HTTP server\n", n_threads_http); srv->new_task_queue = [n_threads_http] { // spawn n_threads_http fixed thread (always alive), while allow up to 1024 max possible additional threads // when n_threads_http is used, server will create new "dynamic" threads that will be destroyed after processing each request @@ -412,13 +412,13 @@ bool server_http_context::start() { auto is_sock = false; if (string_ends_with(std::string(hostname), ".sock")) { is_sock = true; - SRV_INF("%s", "setting address family to AF_UNIX\n"); + SRV_TRC("%s", "setting address family to AF_UNIX\n"); srv->set_address_family(AF_UNIX); // bind_to_port requires a second arg, any value other than 0 should // simply get ignored was_bound = srv->bind_to_port(hostname, 8080); } else { - SRV_INF("%s", "binding port with default address family\n"); + SRV_TRC("%s", "binding port with default address family\n"); // bind HTTP listen port if (port == 0) { const auto bound_port = srv->bind_to_any_port(hostname); diff --git a/tools/server/server-schema.cpp b/tools/server/server-schema.cpp index ed4bda2412..07a842bd6a 100644 --- a/tools/server/server-schema.cpp +++ b/tools/server/server-schema.cpp @@ -287,7 +287,7 @@ std::vector> make_llama_cmpl_schema(const common_params & ->set_desc("Chat format used internally by the server") ->set_handler([&](field_eval_context & ctx, const json & data) { ctx.params.chat_parser_params.format = static_cast(data.at("chat_format").get()); - SRV_INF("Chat format: %s\n", common_chat_format_name(ctx.params.chat_parser_params.format)); + SRV_TRC("chat format: %s\n", common_chat_format_name(ctx.params.chat_parser_params.format)); })); add((new field_str("reasoning_format")) diff --git a/tools/server/server-stream.cpp b/tools/server/server-stream.cpp index 757c36ad25..785c28b3a5 100644 --- a/tools/server/server-stream.cpp +++ b/tools/server/server-stream.cpp @@ -339,11 +339,11 @@ void stream_pipe_producer::close() { // httplib bails its content provider the moment is_peer_alive() goes false, so pump the rest // of the generation into the ring buffer here. a DELETE flips is_cancelled and cuts it short if (done_ || session_->is_cancelled()) { - SRV_INF("stream_pipe close: skip drain (done=%d cancelled=%d) conv=%s\n", + SRV_TRC("stream_pipe close: skip drain (done=%d cancelled=%d) conv=%s\n", done_ ? 1 : 0, session_->is_cancelled() ? 1 : 0, session_->conversation_id.c_str()); return; } - SRV_INF("stream_pipe close: draining conv=%s\n", session_->conversation_id.c_str()); + SRV_TRC("stream_pipe close: draining conv=%s\n", session_->conversation_id.c_str()); size_t drained = 0; std::string chunk; while (true) { @@ -357,7 +357,7 @@ void stream_pipe_producer::close() { break; } } - SRV_INF("stream_pipe close: drain ended conv=%s bytes=%zu\n", session_->conversation_id.c_str(), drained); + SRV_TRC("stream_pipe close: drain ended conv=%s bytes=%zu\n", session_->conversation_id.c_str(), drained); } std::shared_ptr stream_pipe_producer::create(stream_session_ptr session, @@ -520,7 +520,7 @@ server_http_context::handler_t make_stream_delete_handler() { if (conv_id.empty()) { return make_error_response(400, "Missing conversation id in path", ERROR_TYPE_INVALID_REQUEST); } - SRV_INF("DELETE /v1/stream/%s -> evict_and_cancel\n", conv_id.c_str()); + SRV_TRC("DELETE /v1/stream/%s -> evict_and_cancel\n", conv_id.c_str()); g_stream_sessions.evict_and_cancel(conv_id); auto res = std::make_unique(); res->status = 204; @@ -550,8 +550,7 @@ std::string stream_conv_id_from_headers(const std::map void stream_session_attach_pipe(server_http_res & res, const std::map & headers) { std::string conversation_id = stream_conv_id_from_headers(headers); - SRV_INF("stream_session_attach_pipe: conv_id=%s (empty=%d)\n", - conversation_id.c_str(), conversation_id.empty() ? 1 : 0); + SRV_TRC("conv_id=%s (empty=%d)\n", conversation_id.c_str(), conversation_id.empty() ? 1 : 0); if (conversation_id.empty()) { return; } diff --git a/tools/server/server-task.cpp b/tools/server/server-task.cpp index a9ebac013f..775f50bafb 100644 --- a/tools/server/server-task.cpp +++ b/tools/server/server-task.cpp @@ -1626,7 +1626,7 @@ server_prompt * server_prompt_cache::alloc(const server_prompt & prompt, size_t const int cur_lcp_len = it->tokens.get_common_prefix(prompt.tokens); if (cur_lcp_len == (int) prompt.tokens.size()) { - SRV_INF("%s", " - prompt is already in the cache, skipping\n"); + SRV_TRC("%s", " - prompt is already in the cache, skipping\n"); return nullptr; } } @@ -1636,7 +1636,7 @@ server_prompt * server_prompt_cache::alloc(const server_prompt & prompt, size_t const int len = it->tokens.get_common_prefix(prompt.tokens); if (len == (int) it->tokens.size()) { - SRV_WRN(" - removing obsolete cached prompt with length %d\n", len); + SRV_TRC(" - removing obsolete cached prompt with length %d\n", len); it = states.erase(it); } else { @@ -1681,7 +1681,7 @@ bool server_prompt_cache::load(server_prompt & prompt, const server_tokens & tok float f_keep_best = prompt.tokens.size() > 0 ? float(lcp_best) / prompt.tokens.size() : -1.0f; // empty slot: any cache entry wins float sim_best = float(lcp_best) / tokens_new.size(); - SRV_INF(" - looking for better prompt, base f_keep = %.3f, sim = %.3f\n", f_keep_best, sim_best); + SRV_TRC(" - looking for better prompt, base f_keep = %.3f, sim = %.3f\n", f_keep_best, sim_best); auto it_best = states.end(); @@ -1706,7 +1706,7 @@ bool server_prompt_cache::load(server_prompt & prompt, const server_tokens & tok } if (it_best != states.end()) { - SRV_INF(" - found better prompt with f_keep = %.3f, sim = %.3f\n", f_keep_best, sim_best); + SRV_TRC(" - found better prompt with f_keep = %.3f, sim = %.3f\n", f_keep_best, sim_best); { auto & data = it_best->data.main; @@ -1783,11 +1783,11 @@ void server_prompt_cache::update() { } } - SRV_INF(" - cache state: %zu prompts, %.3f MiB (limits: %.3f MiB, %zu tokens, %zu est)\n", + SRV_TRC(" - cache state: %zu prompts, %.3f MiB (limits: %.3f MiB, %zu tokens, %zu est)\n", states.size(), size() / (1024.0 * 1024.0), limit_size / (1024.0 * 1024.0), limit_tokens, limit_tokens_cur); for (const auto & state : states) { - SRV_INF(" - prompt %p: %7d tokens, checkpoints: %2zu, %9.3f MiB\n", + SRV_TRC(" - prompt %p: %7d tokens, checkpoints: %2zu, %9.3f MiB\n", (const void *)&state, state.n_tokens(), state.checkpoints.size(), state.size() / (1024.0 * 1024.0)); } } diff --git a/tools/server/server.cpp b/tools/server/server.cpp index 1bbc99d890..eafef86bac 100644 --- a/tools/server/server.cpp +++ b/tools/server/server.cpp @@ -124,7 +124,7 @@ int llama_server(int argc, char ** argv) { } if (params.n_parallel < 0) { - SRV_INF("%s", "n_parallel is set to auto, using n_parallel = 4 and kv_unified = true\n"); + SRV_TRC("%s", "n_parallel is set to auto, using n_parallel = 4 and kv_unified = true\n"); params.n_parallel = 4; params.kv_unified = true; @@ -338,7 +338,7 @@ int llama_server(int argc, char ** argv) { std::function clean_up; if (is_router_server) { - SRV_INF("%s", "starting router server, no model will be loaded in this process\n"); + SRV_INF("%s", "starting server in router mode. models will be automatically loaded on-demand\n"); clean_up = [&models_routes]() { SRV_INF("%s: cleaning up before exit...\n", __func__); @@ -391,9 +391,6 @@ int llama_server(int argc, char ** argv) { }); } - // load the model - SRV_INF("%s", "loading model\n"); - if (!ctx_server.load_model(params)) { clean_up(); if (ctx_http.thread.joinable()) { @@ -429,8 +426,9 @@ int llama_server(int argc, char ** argv) { SetConsoleCtrlHandler(reinterpret_cast(console_ctrl_handler), true); #endif + SRV_INF("listening on %s\n", ctx_http.listening_address.c_str()); + if (is_router_server) { - SRV_INF("router server is listening on %s\n", ctx_http.listening_address.c_str()); SRV_WRN("%s", "NOTE: router mode is experimental\n"); SRV_WRN("%s", " it is not recommended to use this mode in untrusted environments\n"); @@ -446,8 +444,6 @@ int llama_server(int argc, char ** argv) { // when the HTTP server stops, clean up and exit clean_up(); } else { - SRV_INF("server is listening on %s\n", ctx_http.listening_address.c_str()); - // optionally, notify router server that this instance is ready std::thread monitor_thread; if (child.is_child()) {